[jboss-jira] [JBoss JIRA] Updated: (JBMESSAGING-1403) Recovery doesn't hapen when JBoss Transactions Recovery Manager is configured

[ https://jira.jboss.org/jira/browse/JBMESSAGING-1403?page=com.atlassian.ji... ] Jeff Mesnil updated JBMESSAGING-1403: ------------------------------------- Attachment: server-200808131311.txt.zip I was finally able to reproduce the issue. I used a modified version of JBM 1.4.0 SP3 CP02 with a sleep of a few seconds before the commit phase of the 2PC protocol (in MessagingXAResource.commit()). When I crash the server (by killing -9 it), I have: - 5 in-flight transactions in JBM_TX table - 100 messages in JBM_MSG table - no messages have been consumed mysql> select * from JBM_TX; +---------+-------------------+----------------------------+-----------+------------------------------+ | NODE_ID | TRANSACTION_ID | BRANCH_QUAL | FORMAT_ID | GLOBAL_TXID | +---------+-------------------+----------------------------+-----------+------------------------------+ | 0 | 19966055755464704 | -3f57fff6:d9b0:48a2d5e1:c9 | 131075 | 1--3f57fff6:d9b0:48a2d5e1:c8 | | 0 | 19966055755464705 | -3f57fff6:d9b0:48a2d5e1:ba | 131075 | 1--3f57fff6:d9b0:48a2d5e1:b9 | | 0 | 19966055755563010 | -3f57fff6:d9b0:48a2d5e1:c5 | 131075 | 1--3f57fff6:d9b0:48a2d5e1:c4 | | 0 | 19966055755726851 | -3f57fff6:d9b0:48a2d5e1:bd | 131075 | 1--3f57fff6:d9b0:48a2d5e1:bc | | 0 | 19966055755808772 | -3f57fff6:d9b0:48a2d5e1:bb | 131075 | 1--3f57fff6:d9b0:48a2d5e1:b8 | +---------+-------------------+----------------------------+-----------+------------------------------+ 5 rows in set (0.00 sec) When I restart the server: - 95 messages are delivered - the 5 in-flight tx are removed from the DB table but the corresponding messages are not delivered In the log, we see that the recovery occurs: 2008-08-13 14:44:59,948 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.loading] Local XARecoveryModule loading org.jboss.jms.server.recovery.MessagingXAResourceRecoveryjava:/DefaultJMSProvider 2008-08-13 14:44:59,953 TRACE [org.jboss.jms.server.recovery.MessagingXAResourceRecovery] Constructing BridgeXAResourceRecovery 2008-08-13 14:44:59,954 TRACE [org.jboss.jms.server.recovery.MessagingXAResourceRecovery] Constructing BridgeXAResourceRecovery 2008-08-13 14:44:59,954 TRACE [org.jboss.jms.server.recovery.MessagingXAResourceRecovery] org.jboss.jms.server.recovery.MessagingXAResourceRecovery@6bb14e intialise: java:/DefaultJMSProvider 2008-08-13 14:44:59,960 TRACE [org.jboss.jms.server.recovery.MessagingXAResourceRecovery] org.jboss.jms.server.recovery.MessagingXAResourceRecovery@6bb14e initialised E.g for one of the in-flight tx (19966055755464704), we got logs that it is committed: 2008-08-13 14:47:59,372 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint] ConnectionEndpoint[pb-iadrxtjf-1-lcbqxtjf-jns01e-a0o4c5] received TWO_PHASE_COMMIT commit request 2008-08-13 14:47:59,372 TRACE [org.jboss.jms.server.endpoint.ServerConnectionEndpoint] Committing TX(19966055755464704):PREPARED 2008-08-13 14:47:59,372 TRACE [org.jboss.messaging.core.impl.tx.Transaction] TX(19966055755464704):PREPARED executing before commit hooks 2008-08-13 14:47:59,372 TRACE [org.jboss.messaging.core.impl.JDBCPersistenceManager] org.jboss.messaging.core.impl.JDBCPersistenceManager$1HandleBeforeCommit2PCRunner@bd2c77 commitPreparedTransaction, tx= TX(19966055755464704):PREPARED 2008-08-13 14:47:59,373 TRACE [org.jboss.messaging.core.impl.JDBCPersistenceManager] UPDATE JBM_MSG_REF SET STATE='C', TRANSACTION_ID = NULL WHERE TRANSACTION_ID=19966055755464704 AND STATE='+' removed 0 row(s) 2008-08-13 14:47:59,373 TRACE [org.jboss.messaging.core.impl.JDBCPersistenceManager] DELETE FROM JBM_MSG_REF WHERE TRANSACTION_ID=19966055755464704 AND STATE='-' updated 1 row(s) 2008-08-13 14:47:59,374 TRACE [org.jboss.messaging.core.impl.JDBCPersistenceManager] DELETE FROM JBM_TX WHERE NODE_ID = 0 AND TRANSACTION_ID = 19966055755464704 removed 1 row(s) 2008-08-13 14:47:59,376 TRACE [org.jboss.messaging.core.impl.JDBCPersistenceManager] Deleted 1 messages 2008-08-13 14:47:59,377 TRACE [org.jboss.messaging.core.impl.tx.Transaction] TX(19966055755464704):COMMITTED committed 2008-08-13 14:47:59,377 TRACE [org.jboss.messaging.core.impl.tx.Transaction] TX(19966055755464704):COMMITTED executing after commit hooks 2008-08-13 14:47:59,377 TRACE [org.jboss.messaging.core.impl.ChannelSupport] Queue[12778896/0/3-A].InMemoryCallback[459854] removing Delivery[Reference[19966055742357508]:RELIABLE] after commit 2008-08-13 14:47:59,377 TRACE [org.jboss.messaging.core.impl.tx.Transaction] TX(19966055755464704):COMMITTED commit process complete but the corresponding message is never delivered. About the WARN and ERROR messages: 14:47:59,329 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,329 WARN [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 28, 26, 1--3f57fff6:d9b0:48a2d5e1:bc-3f57fff6:d9b0:48a2d5e1:f6 > 14:47:59,339 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,339 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,340 WARN [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 28, 26, 1--3f57fff6:d9b0:48a2d5e1:b8-3f57fff6:d9b0:48a2d5e1:f1 > 14:47:59,349 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,349 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,349 WARN [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 28, 26, 1--3f57fff6:d9b0:48a2d5e1:b9-3f57fff6:d9b0:48a2d5e1:df > 14:47:59,361 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,361 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,362 WARN [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 28, 26, 1--3f57fff6:d9b0:48a2d5e1:c4-3f57fff6:d9b0:48a2d5e1:e8 > 14:47:59,371 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,371 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule@761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule@405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule@342608] 14:47:59,371 WARN [loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] [com.arjuna.ats.internal.jta.resources.arjunacore.norecoveryxa] Could not find new XAResource to use for recovering non-serializable XAResource < 131075, 28, 26, 1--3f57fff6:d9b0:48a2d5e1:c8-3f57fff6:d9b0:48a2d5e1:d6 > they do *not* correspond to the in-flight transactions, their branch qualifiers is different -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: https://jira.jboss.org/jira/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira