[esb-issues] [JBoss JIRA] Updated: (JBESB-1063) ESB server (default) hang on startup - at "schema export complete" - intermittent problem - seeing about 8 times out of 10 today - on multiple systems

[ http://jira.jboss.com/jira/browse/JBESB-1063?page=all ] Len DiMaggio updated JBESB-1063: -------------------------------- Summary: ESB server (default) hang on startup - at "schema export complete" - intermittent problem - seeing about 8 times out of 10 today - on multiple systems (was: ESB server (default) hang on startup - at "schema export complete") Description: ESB server (default) hang on startup - at "schema export complete" - intermittent problem - seeing about 8 times out of 10 today - on multiple systems I've attached the server.log file. The messages displayed on stdout (I used run.sh to start the server) are hung on: ------------------------------------------------------------------------------ 15:07:29,249 INFO [STDOUT] Hibernate: call identity() 15:07:30,844 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 15:07:30,915 INFO [SchemaExport] Running hbm2ddl schema export 15:07:30,919 INFO [SchemaExport] exporting generated schema to database 15:07:30,995 INFO [SchemaExport] schema export complete ------------------------------------------------------------------------------ In the server log - look for the pattern listed here - it is repeated in an infinite loop until the server is stopped. Removing the hypersonic dir does not solve this problem. ------------------------------------------------------------------------------ 2007-09-19 15:05:27,369 DEBUG [org.jbpm.job.executor.JobExecutorThread] acquiring jobs for execution... 2007-09-19 15:05:27,369 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2007-09-19 15:05:27,369 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@6fadc122 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-09-19 15:05:27,369 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4875176867303424 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction 2007-09-19 15:05:27,369 DEBUG [org.hibernate.transaction.JDBCTransaction] begin 2007-09-19 15:05:27,369 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2007-09-19 15:05:27,369 DEBUG [org.hibernate.transaction.JDBCTransaction] current autocommit status: true 2007-09-19 15:05:27,369 DEBUG [org.hibernate.transaction.JDBCTransaction] disabling autocommit 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JDBCTransaction@21712712 2007-09-19 15:05:27,370 DEBUG [org.jbpm.job.executor.JobExecutorThread] querying for acquirable job... 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_30_, job0_.VERSION_ as VERSION3_30_, job0_.DUEDATE_ as DUEDATE4_30_, job0_.PROCESSINSTANCE_ as PROCESSI5_30_, job0_.TOKEN_ as TOKEN6_30_, job0_.TASKINSTANCE_ as TASKINST7_30_, job0_.ISSUSPENDED_ as ISSUSPEN8_30_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_30_, job0_.LOCKOWNER_ as LOCKOWNER10_30_, job0_.LOCKTIME_ as LOCKTIME11_30_, job0_.EXCEPTION_ as EXCEPTION12_30_, job0_.RETRIES_ as RETRIES13_30_, job0_.NAME_ as NAME14_30_, job0_.REPEAT_ as REPEAT15_30_, job0_.TRANSITIONNAME_ as TRANSIT16_30_, job0_.ACTION_ as ACTION17_30_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_30_, job0_.GRAPHELEMENT_ as GRAPHEL19_30_, job0_.NODE_ as NODE20_30_, job0_.CLASS_ as CLASS2_30_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.DUEDATE_<=? and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2007-09-19 15:05:27,370 DEBUG [org.jbpm.job.executor.JobExecutorThread] no acquirable jobs in job table 2007-09-19 15:05:27,370 DEBUG [org.jbpm.JbpmContext] closing JbpmContext 2007-09-19 15:05:27,370 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@264d107e 2007-09-19 15:05:27,370 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction@21712712 2007-09-19 15:05:27,370 DEBUG [org.hibernate.transaction.JDBCTransaction] commit 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] re-enabling autocommit 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] committed JDBC Connection 2007-09-19 15:05:27,371 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2007-09-19 15:05:27,371 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-09-19 15:05:27,371 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@d75d3d7 2007-09-19 15:05:27,371 DEBUG [org.jbpm.job.executor.JobExecutorThread] obtained locks on following jobs: [] 2007-09-19 15:05:27,371 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2007-09-19 15:05:27,371 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@32a6cf28 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-09-19 15:05:27,371 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4875176867311616 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] begin 2007-09-19 15:05:27,371 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] current autocommit status: true 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] disabling autocommit 2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JDBCTransaction@2c11b4c2 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_30_, job0_.VERSION_ as VERSION3_30_, job0_.DUEDATE_ as DUEDATE4_30_, job0_.PROCESSINSTANCE_ as PROCESSI5_30_, job0_.TOKEN_ as TOKEN6_30_, job0_.TASKINSTANCE_ as TASKINST7_30_, job0_.ISSUSPENDED_ as ISSUSPEN8_30_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_30_, job0_.LOCKOWNER_ as LOCKOWNER10_30_, job0_.LOCKTIME_ as LOCKTIME11_30_, job0_.EXCEPTION_ as EXCEPTION12_30_, job0_.RETRIES_ as RETRIES13_30_, job0_.NAME_ as NAME14_30_, job0_.REPEAT_ as REPEAT15_30_, job0_.TRANSITIONNAME_ as TRANSIT16_30_, job0_.ACTION_ as ACTION17_30_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_30_, job0_.GRAPHELEMENT_ as GRAPHEL19_30_, job0_.NODE_ as NODE20_30_, job0_.CLASS_ as CLASS2_30_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2007-09-19 15:05:27,372 DEBUG [org.jbpm.JbpmContext] closing JbpmContext 2007-09-19 15:05:27,372 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@586f14d6 2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction@2c11b4c2 2007-09-19 15:05:27,372 DEBUG [org.hibernate.transaction.JDBCTransaction] commit 2007-09-19 15:05:27,372 DEBUG [org.hibernate.transaction.JDBCTransaction] re-enabling autocommit 2007-09-19 15:05:27,372 DEBUG [org.hibernate.transaction.JDBCTransaction] committed JDBC Connection 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2007-09-19 15:05:27,373 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-09-19 15:05:27,373 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@64c11af5 ------------------------------------------------------------------------------ was: I'm seeing the ESB server (default) hang on startup - at schema export complete I've attached the server.log file. The messages displayed on stdout (I used run.sh to start the server) are hung on: ------------------------------------------------------------------------------ 15:07:29,249 INFO [STDOUT] Hibernate: call identity() 15:07:30,844 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 15:07:30,915 INFO [SchemaExport] Running hbm2ddl schema export 15:07:30,919 INFO [SchemaExport] exporting generated schema to database 15:07:30,995 INFO [SchemaExport] schema export complete ------------------------------------------------------------------------------ In the server log - look for the pattern listed here - it is repeated in an infinite loop until the server is stopped. Removing the hypersonic dir does not solve this problem. ------------------------------------------------------------------------------ 2007-09-19 15:05:27,369 DEBUG [org.jbpm.job.executor.JobExecutorThread] acquiring jobs for execution... 2007-09-19 15:05:27,369 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2007-09-19 15:05:27,369 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@6fadc122 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-09-19 15:05:27,369 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4875176867303424 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction 2007-09-19 15:05:27,369 DEBUG [org.hibernate.transaction.JDBCTransaction] begin 2007-09-19 15:05:27,369 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2007-09-19 15:05:27,369 DEBUG [org.hibernate.transaction.JDBCTransaction] current autocommit status: true 2007-09-19 15:05:27,369 DEBUG [org.hibernate.transaction.JDBCTransaction] disabling autocommit 2007-09-19 15:05:27,369 DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JDBCTransaction@21712712 2007-09-19 15:05:27,370 DEBUG [org.jbpm.job.executor.JobExecutorThread] querying for acquirable job... 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_30_, job0_.VERSION_ as VERSION3_30_, job0_.DUEDATE_ as DUEDATE4_30_, job0_.PROCESSINSTANCE_ as PROCESSI5_30_, job0_.TOKEN_ as TOKEN6_30_, job0_.TASKINSTANCE_ as TASKINST7_30_, job0_.ISSUSPENDED_ as ISSUSPEN8_30_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_30_, job0_.LOCKOWNER_ as LOCKOWNER10_30_, job0_.LOCKTIME_ as LOCKTIME11_30_, job0_.EXCEPTION_ as EXCEPTION12_30_, job0_.RETRIES_ as RETRIES13_30_, job0_.NAME_ as NAME14_30_, job0_.REPEAT_ as REPEAT15_30_, job0_.TRANSITIONNAME_ as TRANSIT16_30_, job0_.ACTION_ as ACTION17_30_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_30_, job0_.GRAPHELEMENT_ as GRAPHEL19_30_, job0_.NODE_ as NODE20_30_, job0_.CLASS_ as CLASS2_30_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.DUEDATE_<=? and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2007-09-19 15:05:27,370 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2007-09-19 15:05:27,370 DEBUG [org.jbpm.job.executor.JobExecutorThread] no acquirable jobs in job table 2007-09-19 15:05:27,370 DEBUG [org.jbpm.JbpmContext] closing JbpmContext 2007-09-19 15:05:27,370 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@264d107e 2007-09-19 15:05:27,370 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction@21712712 2007-09-19 15:05:27,370 DEBUG [org.hibernate.transaction.JDBCTransaction] commit 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] re-enabling autocommit 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] committed JDBC Connection 2007-09-19 15:05:27,371 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2007-09-19 15:05:27,371 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-09-19 15:05:27,371 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@d75d3d7 2007-09-19 15:05:27,371 DEBUG [org.jbpm.job.executor.JobExecutorThread] obtained locks on following jobs: [] 2007-09-19 15:05:27,371 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2007-09-19 15:05:27,371 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@32a6cf28 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-09-19 15:05:27,371 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4875176867311616 2007-09-19 15:05:27,371 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] begin 2007-09-19 15:05:27,371 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] current autocommit status: true 2007-09-19 15:05:27,371 DEBUG [org.hibernate.transaction.JDBCTransaction] disabling autocommit 2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JDBCTransaction@2c11b4c2 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_30_, job0_.VERSION_ as VERSION3_30_, job0_.DUEDATE_ as DUEDATE4_30_, job0_.PROCESSINSTANCE_ as PROCESSI5_30_, job0_.TOKEN_ as TOKEN6_30_, job0_.TASKINSTANCE_ as TASKINST7_30_, job0_.ISSUSPENDED_ as ISSUSPEN8_30_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_30_, job0_.LOCKOWNER_ as LOCKOWNER10_30_, job0_.LOCKTIME_ as LOCKTIME11_30_, job0_.EXCEPTION_ as EXCEPTION12_30_, job0_.RETRIES_ as RETRIES13_30_, job0_.NAME_ as NAME14_30_, job0_.REPEAT_ as REPEAT15_30_, job0_.TRANSITIONNAME_ as TRANSIT16_30_, job0_.ACTION_ as ACTION17_30_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_30_, job0_.GRAPHELEMENT_ as GRAPHEL19_30_, job0_.NODE_ as NODE20_30_, job0_.CLASS_ as CLASS2_30_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2007-09-19 15:05:27,372 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2007-09-19 15:05:27,372 DEBUG [org.jbpm.JbpmContext] closing JbpmContext 2007-09-19 15:05:27,372 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@586f14d6 2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction@2c11b4c2 2007-09-19 15:05:27,372 DEBUG [org.hibernate.transaction.JDBCTransaction] commit 2007-09-19 15:05:27,372 DEBUG [org.hibernate.transaction.JDBCTransaction] re-enabling autocommit 2007-09-19 15:05:27,372 DEBUG [org.hibernate.transaction.JDBCTransaction] committed JDBC Connection 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2007-09-19 15:05:27,372 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2007-09-19 15:05:27,373 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-09-19 15:05:27,373 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@64c11af5 ------------------------------------------------------------------------------ -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira