'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=POSIXexport LC_CTYPE=de_DE.UTF-8export HOST=rrzvm037export TERM=linuxexport SHELL=/bin/bashexport HOSTTYPE=x86_64export 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/sbinexport HOME=/rootexport OSTYPE=linuxexport USER=rootexport JAVA_HOME=/opt/alfresco-3.4.d/javaexport JAVA_BINDIR=/opt/alfresco-3.4.d/java/binexport JAVA_ROOT=/opt/alfresco-3.4.d/javaexport JRE_HOME=/opt/alfresco-3.4.d/java/jreecho "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 411302: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] complete02:19:27,881 INFO  [org.alfresco.module.vti.VtiServer] Vti server started successfully on port: 707002:19:32,192 ERROR [org.springframework.web.context.ContextLoader] Context initialization failedorg.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 moreCaused 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 moreCaused 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‍