[jboss-jira] [JBoss JIRA] Updated: (JBMESSAGING-1403) Recovery doesn't hapen when JBoss Transactions Recovery Manager is configured
Jeff Mesnil (JIRA)
jira-events at lists.jboss.org
Wed Aug 13 09:40:42 EDT 2008
[ https://jira.jboss.org/jira/browse/JBMESSAGING-1403?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
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 at 6bb14e intialise: java:/DefaultJMSProvider
2008-08-13 14:44:59,960 TRACE [org.jboss.jms.server.recovery.MessagingXAResourceRecovery] org.jboss.jms.server.recovery.MessagingXAResourceRecovery at 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 at 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 at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 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 at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 342608]
14:47:59,339 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 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 at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 342608]
14:47:59,349 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 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 at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 342608]
14:47:59,361 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 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 at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 342608]
14:47:59,371 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule at 761c5d, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 405b74, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 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
> Recovery doesn't hapen when JBoss Transactions Recovery Manager is configured
> -----------------------------------------------------------------------------
>
> Key: JBMESSAGING-1403
> URL: https://jira.jboss.org/jira/browse/JBMESSAGING-1403
> Project: JBoss Messaging
> Issue Type: Bug
> Components: Messaging Core
> Affects Versions: 1.4.0.SP3.CP02
> Environment: JBoss-EAP-4.3_CP1 , JDK 1.5.0_15-b04 , Fedora 8, MySQL 5.0.45 , Enabled JBoss Transactions Recovery Manager to recover JBoss Messaging resources as per the "JBoss Messaging XA Recovery Configuration"
> Reporter: Tyronne Wickramarathne
> Assignee: Tim Fox
> Fix For: 1.4.0.SP3.CP04
>
> Attachments: MessagingXAResourceRecovery#getXAResource().txt, server-200808131311.txt.zip, server.log, Tests.zip
>
>
> How to reproduce:
> ------------------------
> -Configure jbossjta-properties.xml is configured with the following property:
> <property name="com.arjuna.ats.jta.recovery.XAResourceRecovery.JBMESSAGING1"
> value="org.jboss.jms.server.recovery.MessagingXAResourceRecovery;java:/DefaultJMSProvider"/>
> -Deploy the attached mdbtest.war , mymdbs.jar at JBoss-EAP.
> -Run the qsender.jsp : http://<your_host>:<port>/mdbtest/qsender.jsp
> -Kill the JBoss-EAP when all the messages are sent to the destination
> -Reboot the server, you'd see the messages are getting delivered, but the ERROR+WARN messages are getting logged
> The Tests.zip folder contains both (mdbtest.war , mymdbs.jar) libraries, configured to send 100000 messages while setting the latency in consuming messages to 500ms. You can use these libraries to reproduce this issue, quite rapidly.
> Findings after debugging JBM:
> -----------------------------------------
> When you reproduce this as per the given instructions, it gives you two different behaviours.
> 1. You don't get any records left at JBM_MSG, JBM_MSG_REF or JBM_TX tables, once the server is killed.
> When you restart the server, you can find the following :
> 2008-07-18 11:57:44,070 ERROR [STDERR] **recoveryModules [com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule at 81db25, com.arjuna.ats.internal.txoj.recovery.TORecoveryModule at 15a740a, com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule at 1787395]
> 2008-07-18 11:57:44,070 WARN [com.arjuna.ats.jta.logging.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-7f000001:a493:487ef922:4f67f000001:a493:487ef922:4fc########################################################################## >
> MessagingXAResourceRecovery#getXAResource() returns the following :
> "res"= MessagingXAResourceWrapper (id=399)
> connection= null
> delegate= null
> password= null
> providerName= "java:/DefaultJMSProvider"
> count= 24
> hash= 0
> offset= 58
> value= char[82] (id=412)
> username= null
> 2. You'd find one or more records left with at JBM_MSG, JBM_MSG_REF or JBM_TX tables, when the server is killed.
> At this stage, when you restart the server, you won't encounter any transaction errors from JBossTM component. Also, you can notice MessagingXAResourceRecovery#getXAResource() returns a valid XA resource.
> Please refer the attach document to see the content of : MessagingXAResourceRecovery#getXAResource().txt
> But, the message(s) remains in the database table and it doesn't get delivered to the destination or shown in the corresponding destination when you observe via JMX-Console. Also, I have attached the server.log for this scenario at TRACE level.
--
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
More information about the jboss-jira
mailing list