[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
Len DiMaggio (JIRA)
jira-events at lists.jboss.org
Wed Sep 19 15:49:10 EDT 2007
[ 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 at 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 at 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 at 264d107e
2007-09-19 15:05:27,370 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction at 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 at 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 at 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 at 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 at 586f14d6
2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction at 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 at 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 at 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 at 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 at 264d107e
2007-09-19 15:05:27,370 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction at 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 at 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 at 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 at 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 at 586f14d6
2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction at 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 at 64c11af5
------------------------------------------------------------------------------
> ESB server (default) hang on startup - at "schema export complete" - intermittent problem - seeing about 8 times out of 10 today - on multiple systems
> ------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: JBESB-1063
> URL: http://jira.jboss.com/jira/browse/JBESB-1063
> Project: JBoss ESB
> Issue Type: Bug
> Security Level: Public(Everyone can see)
> Affects Versions: 4.2.1 IR1
> Environment: [root at atlantis trunk]# uname -a
> Linux atlantis.boston.redhat.com 2.6.18-8.el5xen #1 SMP Fri Jan 26 14:42:21 EST 2007 i686 i686 i386 GNU/Linux
> (RHEL5)
> [root at atlantis trunk]# java -version
> java version "1.5.0_12"
> Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_12-b04)
> Java HotSpot(TM) Client VM (build 1.5.0_12-b04, mixed mode)
> svn update
> Updated to revision 15241.
> Reporter: Len DiMaggio
> Assigned To: Mark Little
> Fix For: 4.2.1 IR1
>
> Attachments: server.log.fragment, server.log.gz, stdout.txt
>
>
> 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 at 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 at 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 at 264d107e
> 2007-09-19 15:05:27,370 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction at 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 at 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 at 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 at 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 at 586f14d6
> 2007-09-19 15:05:27,372 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JDBCTransaction at 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 at 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
More information about the esb-issues
mailing list