'Duplicate entry' when Alfresco is started by script

[flob]

Hi all,

I'm running Alfresco 3.4d CE on SLES11SP2 64bit with bundled Tomcat and remote MySQL database. Everything works great, but I'm facing a startup problem when Alfresco is started via custom shell script.
The situation:
At night a Tivoli backup script shuts down Alfresco, performs the backup of alf_data and finally starts Alfresco again.

alfresco-up.sh

export LANG=POSIX
export LC_CTYPE=de_DE.UTF-8
export HOST=rrzvm037
export TERM=linux
export SHELL=/bin/bash
export HOSTTYPE=x86_64
export PATH=/sbin:/usr/sbin:/usr/local/sbin:/root/bin:/usr/local/bin:/usr/bin:/bin:/usr/bin/X11:/usr/X11R6/bin:/usr/games:/usr/lib/mit/bin:/usr/lib/mit/sbin
export HOME=/root
export OSTYPE=linux
export USER=root
export JAVA_HOME=/opt/alfresco-3.4.d/java
export JAVA_BINDIR=/opt/alfresco-3.4.d/java/bin
export JAVA_ROOT=/opt/alfresco-3.4.d/java
export JRE_HOME=/opt/alfresco-3.4.d/java/jre

echo "Starting Alfresco after a backup"
. /opt/alfresco-3.4.d/scripts/setenv.sh
. /opt/alfresco-3.4.d/alfresco.sh start
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Alfresco starts in a kind of zombie mode. The log says:

02:19:09,634 INFO  [org.alfresco.service.descriptor.DescriptorService] Alfresco started (Community): Current version 3.4.0 (d 3370) schema 4113 - Originally installed version 3.4.0 (d 3370) schema 4113
02:19:09,643 INFO  [org.alfresco.repo.management.subsystems.ChildApplicationContextFactory] Starting 'Replication' subsystem, ID: [Replication, default]
02:19:09,653 INFO  [org.alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
02:19:09,654 INFO  [org.alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
02:19:09,654 INFO  [org.alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
02:19:09,654 INFO  [org.alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/module/org.alfresco.module.vti/context/vti.properties]
02:19:09,666 INFO  [org.alfresco.repo.management.subsystems.ChildApplicationContextFactory] Startup of 'Replication' subsystem, ID: [Replication, default] complete
02:19:27,881 INFO  [org.alfresco.module.vti.VtiServer] Vti server started successfully on port: 7070
02:19:32,192 ERROR [org.springframework.web.context.ContextLoader] Context initialization failed
org.alfresco.service.cmr.repository.DuplicateChildNodeNameException: Duplicate child name not allowed: Internal Target
   at org.alfresco.repo.domain.node.AbstractNodeDAOImpl$3.execute(AbstractNodeDAOImpl.java:2260)
   at org.alfresco.repo.domain.node.AbstractNodeDAOImpl$3.execute(AbstractNodeDAOImpl.java:2246)
   at org.alfresco.ibatis.RetryingCallbackHelper.doWithRetry(RetryingCallbackHelper.java:101)
   at org.alfresco.repo.domain.node.AbstractNodeDAOImpl.newChildAssocImpl(AbstractNodeDAOImpl.java:2268)
   at org.alfresco.repo.domain.node.AbstractNodeDAOImpl.newNode(AbstractNodeDAOImpl.java:884)
   at org.alfresco.repo.node.db.DbNodeServiceImpl.createNode(DbNodeServiceImpl.java:308)
   at sun.reflect.GeneratedMethodAccessor329.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:597)
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
   at org.alfresco.repo.tenant.MultiTNodeServiceInterceptor.invoke(MultiTNodeServiceInterceptor.java:104)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
   at $Proxy7.createNode(Unknown Source)
   at sun.reflect.GeneratedMethodAccessor329.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:597)
   at org.alfresco.repo.service.StoreRedirectorProxyFactory$RedirectorInvocationHandler.invoke(StoreRedirectorProxyFactory.java:215)
   at $Proxy8.createNode(Unknown Source)
   at org.alfresco.repo.node.MLPropertyInterceptor.invoke(MLPropertyInterceptor.java:276)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:183)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:183)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
   at $Proxy7.createNode(Unknown Source)
   at sun.reflect.GeneratedMethodAccessor329.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:597)
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
   at net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:80)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:80)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:44)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.alfresco.repo.audit.AuditMethodInterceptor.proceed(AuditMethodInterceptor.java:160)
   at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:137)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:44)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.alfresco.repo.audit.AuditMethodInterceptor.proceedWithAudit(AuditMethodInterceptor.java:217)
   at org.alfresco.repo.audit.AuditMethodInterceptor.proceed(AuditMethodInterceptor.java:184)
   at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:137)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
   at $Proxy7.createNode(Unknown Source)
   at org.alfresco.repo.transfer.TransferServiceImpl2.createTransferTarget(TransferServiceImpl2.java:248)
   at org.alfresco.repo.transfer.TransferServiceImpl2.createAndSaveTransferTarget(TransferServiceImpl2.java:202)
   at org.alfresco.module.org_alfresco_module_wcmquickstart.publish.PublishBootstrap$Lifecycle$1.doWork(PublishBootstrap.java:89)
   at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:508)
   at org.alfresco.module.org_alfresco_module_wcmquickstart.publish.PublishBootstrap$Lifecycle.onBootstrap(PublishBootstrap.java:73)
   at org.springframework.extensions.surf.util.AbstractLifecycleBean.onApplicationEvent(AbstractLifecycleBean.java:56)
   at org.alfresco.module.org_alfresco_module_wcmquickstart.publish.PublishBootstrap.onApplicationEvent(PublishBootstrap.java:62)
   at org.alfresco.module.org_alfresco_module_wcmquickstart.publish.PublishBootstrap.onApplicationEvent(PublishBootstrap.java:35)
   at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:97)
   at org.alfresco.repo.management.SafeApplicationEventMulticaster.multicastEvent(SafeApplicationEventMulticaster.java:78)
   at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:294)
   at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:858)
   at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:419)
   at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:261)
   at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:192)
   at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:47)
   at org.alfresco.web.app.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:63)
   at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3972)
   at org.apache.catalina.core.StandardContext.start(StandardContext.java:4467)
   at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791)
   at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)
   at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:546)
   at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:637)
   at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:563)
   at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498)
   at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)
   at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321)
   at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
   at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)
   at org.apache.catalina.core.StandardHost.start(StandardHost.java:785)
   at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)
   at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443)
   at org.apache.catalina.core.StandardService.start(StandardService.java:519)
   at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)
   at org.apache.catalina.startup.Catalina.start(Catalina.java:581)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:597)
   at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
   at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)
Caused by: org.springframework.dao.DuplicateKeyException: SqlMapClient operation; SQL [];   
— The error occurred in alfresco/ibatis/#resource.dialect#/node-insert-SqlMap.xml.  
— The error occurred while applying a parameter map.  
— Check the alfresco.node.insert_ChildAssoc-InlineParameterMap.  
— Check the statement (update failed).  
— Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '479-33-4081700585-internal target' for key 2; nested exception is com.ibatis.common.jdbc.exception.NestedSQLException:   
— The error occurred in alfresco/ibatis/#resource.dialect#/node-insert-SqlMap.xml.  
— The error occurred while applying a parameter map.  
— Check the alfresco.node.insert_ChildAssoc-InlineParameterMap.  
— Check the statement (update failed).  
— Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '479-33-4081700585-internal target' for key 2
   at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:241)
   at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
   at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:203)
   at org.springframework.orm.ibatis.SqlMapClientTemplate.insert(SqlMapClientTemplate.java:364)
   at org.alfresco.repo.domain.node.ibatis.NodeDAOImpl.insertChildAssoc(NodeDAOImpl.java:723)
   at org.alfresco.repo.domain.node.AbstractNodeDAOImpl$3.execute(AbstractNodeDAOImpl.java:2252)
   … 96 more
Caused by: com.ibatis.common.jdbc.exception.NestedSQLException:   
— The error occurred in alfresco/ibatis/#resource.dialect#/node-insert-SqlMap.xml.  
— The error occurred while applying a parameter map.  
— Check the alfresco.node.insert_ChildAssoc-InlineParameterMap.  
— Check the statement (update failed).  
— Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '479-33-4081700585-internal target' for key 2
   at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeUpdate(MappedStatement.java:107)
   at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.insert(SqlMapExecutorDelegate.java:393)
   at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.insert(SqlMapSessionImpl.java:82)
   at org.springframework.orm.ibatis.SqlMapClientTemplate$8.doInSqlMapClient(SqlMapClientTemplate.java:366)
   at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:200)
   … 99 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '479-33-4081700585-internal target' for key 2
   at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
   at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
   at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
   at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
   at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
   at com.mysql.jdbc.Util.getInstance(Util.java:384)
   at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1041)
   at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3566)
   at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3498)
   at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
   at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
   at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
   at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
   at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1364)
   at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
   at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:169)
   at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeUpdate(SqlExecutor.java:100)
   at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.sqlExecuteUpdate(MappedStatement.java:216)
   at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeUpdate(MappedStatement.java:94)
   … 103 more

‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I have to login to the server and issue the startup command
/etc/init.d/alfresco start
which works flawlessly and brings up the server as expected.

Both, the post-backup script alfresco-up.sh as well as the manual start /etc/init.d/alfresco start, are performed under the same user account.

So the question is, and this amazes me, why would Alfresco being troubled with mysql errors

com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '479-33-4081700585-internal target' for key 2

Caused by: com.ibatis.common.jdbc.exception.NestedSQLException:  
— The error occurred in alfresco/ibatis/#resource.dialect#/node-insert-SqlMap.xml.
— The error occurred while applying a parameter map.
— Check the alfresco.node.insert_ChildAssoc-InlineParameterMap.
— Check the statement (update failed).

depending on start up command issued automatically versus manually?

Is there a variable missing in alfresco-up.sh? I would have guessed they're all set in setenv.sh?

Has anyone ever experienced a similar problem? Any help is highly appreciated.

Best regards,


FloB

[jpotts]

In your alfresco-global.properties, are you specifying an absolute path for your data directory (dir.root) or a relative path?

Jeff

[flob]

Hi Jeff,

in alfresco-global.properties the data directory is defined as an absolute path.

dir.root=/data/alf_data‍