12:59 p.m.
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401384 ]
Andrew Dinn commented on JBTM-338:
----------------------------------
The periodic recovery thread is stopped from TransactionManagerService.destroyService()
which logs an info message,
"Stopping recovery manager". This message does not appear in the server log
which makes me question whether
the error is in the AS shutdown. If destroyService() gets called then I cannot see how the
recovery manager thread can
fail to stop. (I did identify a race condition in stopping the socket listener worker
thread but that's not the one that is
repeatedly printing recovery messages).
n.b. TransactionManagerService does not implement the stopService() method. Is the AS
sending this message
but failing to invoke destroyService()?
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
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