AnsweredAssumed Answered

'Duplicate entry' when Alfresco is started by script

Question asked by flob on Apr 25, 2012
Latest reply on Apr 25, 2012 by 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

Outcomes