[Building Sakai] Sakai 10.1 fails to start after two times when auto.ddl=true

Mark Triggs mark at dishevelled.net
Mon Sep 1 23:47:34 PDT 2014 

Hi all,

Payten Giles and I have been taking 10.1 out for a spin, but have
noticed an interesting problem when starting up.

Running against an empty MySQL database with "auto.ddl=true", everything
is fine the first two times the system is started, but on the third
time, the startup bombs out with the following error (apologies for the
line lengths):

  2014-09-02 16:26:00,431  INFO localhost-startStop-1 org.sakaiproject.metaobj.shared.mgt.impl.StructuredArtifactDefinitionManagerImpl - init()
  2014-09-02 16:26:00,433  INFO localhost-startStop-1 org.sakaiproject.metaobj.shared.mgt.impl.StructuredArtifactDefinitionManagerImpl - Updating base Metaobj XSLT files (auto.ddl is on).
  2014-09-02 16:26:00,447  WARN localhost-startStop-1 org.sakaiproject.db.impl.BasicSqlService - Sql.dbWrite(): recordAlreadyExists: true, failQuiet: false, : error code: 1062, sql: insert into CONTENT_COLLECTION (COLLECTION_ID,IN_COLLECTION,BINARY_ENTITY, XML) values ( ?,  ?, ? , NULL ), binds:  /group/PortfolioAdmin/ /group/ [B at 77cdbf51, error: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '/group/PortfolioAdmin/' for key 'CONTENT_COLLECTION_INDEX'
  2014-09-02 16:26:00,448  WARN localhost-startStop-1 org.sakaiproject.db.impl.BasicSqlService - Sql.dbWrite(): recordAlreadyExists: true, failQuiet: false, : error code: 1062, sql: insert into CONTENT_COLLECTION (COLLECTION_ID,IN_COLLECTION,BINARY_ENTITY, XML) values ( ?,  ?, ? , NULL ), binds:  /group/PortfolioAdmin/system/ /group/PortfolioAdmin/ [B at 4b9de054, error: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '/group/PortfolioAdmin/system/' for key 'CONTENT_COLLECTION_INDEX'
  2014-09-02 16:26:00,468  WARN localhost-startStop-1 org.sakaiproject.db.impl.BasicSqlService - Sql.dbWrite(): recordAlreadyExists: true, failQuiet: false, : error code: 1062, sql: insert into CONTENT_RESOURCE_DELETE (RESOURCE_ID,IN_COLLECTION,CONTEXT,FILE_SIZE,RESOURCE_TYPE_ID,RESOURCE_UUID,DELETE_DATE,DELETE_USERID,BINARY_ENTITY, XML) values ( ?,  ?, ?, ?, ?, ? ,? ,? ,?, NULL), binds:  /group/PortfolioAdmin/system/formCreate.xslt /group/PortfolioAdmin/system/ PortfolioAdmin 12573 org.sakaiproject.content.types.fileUpload 58a034d2-8fcd-4fbb-a42e-cafd4478431e 20140902062600467 admin [B at 625de173, error: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '58a034d2-8fcd-4fbb-a42e-cafd4478431e' for key 'CONTENT_RESOURCE_UUID_DELETE_I'
  2014-09-02 16:26:00,473 ERROR localhost-startStop-1 org.springframework.web.context.ContextLoader - Context initialization failed
  org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'presentationItemCustomEditor' defined in ServletContext resource [/WEB-INF/presentation-web-config.xml]: Cannot resolve reference to bean 'presentationManager' while setting bean property 'presentationManager'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'presentationManager' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/osp-presentation-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'presentationManagerTarget' while setting bean property 'target'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'presentationManagerTarget' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/osp-presentation-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'homeFactory' while setting bean property 'homeFactory'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'homeFactory' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/sakai-metaobj-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'mapHomeFactory' while setting bean property 'homeFactories' with key [1]; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'mapHomeFactory' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/sakai-metaobj-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'org.sakaiproject.metaobj.shared.mgt.ReadableObjectHome.contentResource' while setting bean property 'homes' with key [TypedStringValue: value [fileArtifact], target type [null]]; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.sakaiproject.metaobj.shared.mgt.ReadableObjectHome.contentResource' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/sakai-metaobj-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'dbXmlHomeFactory' while setting bean property 'homeFactory'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dbXmlHomeFactory' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/sakai-metaobj-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'structuredArtifactDefinitionManager' while setting bean property 'structuredArtifactDefinitionManager'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'structuredArtifactDefinitionManager' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/sakai-metaobj-component/WEB-INF/components.xml]: Cannot resolve reference to bean 'structuredArtifactDefinitionManagerTarget' while setting bean property 'target'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'structuredArtifactDefinitionManagerTarget' defined in file [/mnt/ssd/cle/nobackup/apache-tomcat-7.0.54/components/sakai-metaobj-component/WEB-INF/components.xml]: Invocation of init method failed; nested exception is java.lang.NullPointerException: putDeleteResource returned a null value, this is unrecoverable
          at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:329)
          at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:107)
          at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1387)
          at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1128)
          at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
          at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
          at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:295)
          at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
          at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:292)
          at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
          at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:626)
          at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:932)
          at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
          at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:389)
          at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:294)
          at org.sakaiproject.component.impl.ContextLoader.initWebApplicationContext(ContextLoader.java:64)
          at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
          at org.sakaiproject.util.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:56)
          at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4973)
          at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5467)
          at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
          at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
          at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
          at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:632)
          at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1083)
          at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1880)
          at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
          at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
          at java.util.concurrent.FutureTask.run(FutureTask.java:138)
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
          at java.lang.Thread.run(Thread.java:662)


We tried reproducing the issue with Sakai 10.0 and saw no problems, so
it seems to be a regression in 10.1.  After a fair amount of
divide-and-conquering we tracked the issue down to this patch against
kernel:

  https://gist.github.com/marktriggs/53f589d1eaf7b0a18254

which I think relates to this issue:

  https://jira.sakaiproject.org/browse/KNL-1286

We've verified that applying this patch to a vanilla 10.0 source and
rebuilding kernel produces the same error.

The root cause of the issue seems to be
StructuredArtifactDefinitionManagerImpl.init() (from metaobj) trying to
delete and recreate its .xslt files.  On the first startup it creates a
new resource with no problems.  On the second startup it deletes that
first resource and creates a new one.  On the third (and subsequent)
startup, it tries to delete the existing resource but conflicts with the
previously deleted copy, and the call to dbWrite() fails and returns
null.  The issue was alluded to here as well:
https://jira.sakaiproject.org/browse/SAK-25782.

Turning off auto.ddl gets us past the error, but I thought I'd better
report it.  Happy to do some more testing if there's anything I can do
to help.

Thanks,

Mark

-- 
Mark Triggs
<mark at dishevelled.net>

More information about the sakai-dev mailing list