[JBoss JIRA] Created: (JBESB-1063) ESB server (default) hang on startup - at "schema export complete"
2:29 p.m.
ESB server (default) hang on startup - at "schema export complete"
------------------------------------------------------------------
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@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@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
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
2:49 p.m.
New subject: [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
------------------------------------------------------------------------------
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@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@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@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
4:16 a.m.
New subject: [JBoss JIRA] Commented: (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=comments#action_12377760 ]
Kevin Conner commented on JBESB-1063:
-------------------------------------
Len, this does not appear to be a hang, why do you suspect it is?
According to the logs you have sent (console and server.log) the instance started
successfully.
(from server.log)
2007-09-19 15:14:20,668 INFO [org.jboss.system.server.Server] JBoss (MX MicroKernel)
[4.2.1.GA (build: SVNTag=JBoss_4_2_1_GA date=200707131605)] Started in 36s:333ms
2007-09-19 15:14:25,727 INFO [org.hibernate.tool.hbm2ddl.SchemaExport] schema export
complete
(from stdout.txt)
15:07:27,740 INFO [Server] JBoss (MX MicroKernel) [4.2.1.GA (build: SVNTag=JBoss_4_2_1_GA
date=200707131605)] Started in 35s:213ms
15:07:30,995 INFO [SchemaExport] schema export complete
The schema export is a background task that completes after the server has started. The
jbpm debugs are part of the normal operation of jbpm.
Removing jbpm.esb is not a workaround, the best course of action is to disable the debug
category for hibernate and jbpm.
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@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@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@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
9:11 a.m.
New subject: [JBoss JIRA] Closed: (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 closed JBESB-1063.
-------------------------------
Resolution: Rejected
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@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@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@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
6773
days inactive
6774
days old
3 comments
2 participants
participants (2)
-
Kevin Conner (JIRA) -
Len DiMaggio (JIRA)