[jbossts-issues] [JBoss JIRA] Commented: (JBTM-818) Order in which JBoss nodes are restarted affects the outcome of XA transactions recovery

[Jonathan Halliday (JIRA)]

    [ https://jira.jboss.org/browse/JBTM-818?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12567392#comment-12567392 ] 

Jonathan Halliday commented on JBTM-818:
----------------------------------------

in node B, XARecoveryModule.xaRecovery(XAResource xares)
 previousFailure returns value!=null so call record.recover
 XAResourceRecord.recover -> RC.replay_completion (jacorb _RecoveryCoordinatorStub code), returns CosTransactions::StatusRolledBack - incorrect: parent tx is merely uncontactable which != rolledback.


 11:35:08,181 DEBUG [logger] XAResourceRecord.recover
11:35:23,682 DEBUG [logger] RootOA::objectIsReady (Servant)
11:37:29,763 DEBUG [logger] InterpositionClientRequestInterceptorImpl::send_request ( replay_completion )
11:37:29,767 DEBUG [logger] InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( replay_completion )
11:37:29,767 DEBUG [logger] InterpositionServerRequestInterceptorImpl.receive_request ( replay_completion )
11:37:29,768 DEBUG [logger] JacOrbDefaultServant::replay_completion)
11:37:29,769 DEBUG [logger] RecoveryCoordinatorId(7f000001:9b7f:4cf8d3f9:f2*7f000001:9b7f:4cf8d3f9:ed*7f000001:9b7f:4cf8d3f9:0*true)
11:37:29,770 DEBUG [loggerI18N] Can't find resource for bundle java.util.PropertyResourceBundle, key com.arjuna.ats.internal.jts.orbspecific.jacorb.recoverycoordinators.JacOrbRCDefaultServant_1: [key='com.arjuna.ats.internal.jts.orbspecific.jacorb.recoverycoordinators.JacOrbRCDefaultServant_1'](7f000001:9b7f:4cf8d3f9:f2, 7f000001:9b7f:4cf8d3f9:ed, 7f000001:9b7f:4cf8d3f9:0, interposed-tx), 
11:37:29,770 DEBUG [loggerI18N] Can't find resource for bundle java.util.PropertyResourceBundle, key com.arjuna.ats.internal.jts.orbspecific.jacorb.recoverycoordinators.JacOrbRCDefaultServant_2: [key='com.arjuna.ats.internal.jts.orbspecific.jacorb.recoverycoordinators.JacOrbRCDefaultServant_2']7f000001:9b7f:4cf8d3f9:f2*7f000001:9b7f:4cf8d3f9:ed*7f000001:9b7f:4cf8d3f9:0*true, 
11:37:29,770 DEBUG [logger] GenericRecoveryCoordinator(7f000001:9b7f:4cf8d3f9:f2).replay_completion(resource supplied)
11:37:29,770 DEBUG [logger] StatusChecker.get_current_status(7f000001:9b7f:4cf8d3f9:ed, 7f000001:9b7f:4cf8d3f9:0)
11:37:29,770 DEBUG [logger] StatusChecker.checkOriginalStatus(7f000001:9b7f:4cf8d3f9:ed, 7f000001:9b7f:4cf8d3f9:0, false)
11:37:29,770 DEBUG [logger] StatusChecker.getStatus(7f000001:9b7f:4cf8d3f9:ed, com.arjuna.ats.internal.jts.recovery.contact.FactoryContactItem at 609bac9d, false)
11:37:29,770 DEBUG [loggerI18N] [com.arjuna.ats.internal.jts.recovery.contact.StatusChecker_13] [com.arjuna.ats.internal.jts.recovery.contact.StatusChecker_13] - StatusChecker.getStatus(7f000001:9b7f:4cf8d3f9:ed) -  no factory, process previously dead
11:37:29,774 DEBUG [loggerI18N] [com.arjuna.ats.internal.jts.recovery.transactions.CachedRecoveredTransaction_1] [com.arjuna.ats.internal.jts.recovery.transactions.CachedRecoveredTransaction_1] - CachedRecoveredTransaction created [7f000001:9b7f:4cf8d3f9:ed, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction]
11:37:29,774 DEBUG [logger] CachedRecoveredTransaction.get_status [7f000001:9b7f:4cf8d3f9:ed, /StateManager/BasicAction/TwoPhaseCoordinator/ArjunaTransactionImple/ServerTransaction] = CosTransactions::StatusRolledBack
11:37:29,775 DEBUG [logger] InterpositionServerRequestInterceptorImpl::send_reply ( replay_completion )
11:37:29,775 DEBUG [logger] InterpositionServerRequestInterceptorImpl.suspendContext ( replay_completion )
11:37:29,776 DEBUG [logger] ResourceCompletor.rollback()
11:37:29,776 DEBUG [logger] InterpositionClientRequestInterceptorImpl::receive_reply ( replay_completion )
11:37:29,777 DEBUG [logger] InterpositionClientRequestInterceptorImpl::send_request ( rollback )
11:37:29,778 DEBUG [logger] InterpositionServerRequestInterceptorImpl::receive_request_service_contexts ( rollback )
11:37:29,778 DEBUG [logger] InterpositionServerRequestInterceptorImpl.receive_request ( rollback )
11:37:29,778 DEBUG [logger] XAResourceRecord.rollback for < 131072, 27, 25, 504555102484848484849585755565158529910256100525148581025255102484848484849585798551025852991025610051102575810248 >


> Order in which JBoss nodes are  restarted affects the outcome of XA transactions recovery
> -----------------------------------------------------------------------------------------
>
>                 Key: JBTM-818
>                 URL: https://jira.jboss.org/browse/JBTM-818
>             Project: JBoss Transaction Manager
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: JTS
>    Affects Versions: 4.6.1.CP07
>         Environment: JBoss 5.1 EAP Postgres 8.4
>            Reporter: Tom Ross
>         Attachments: testCase.zip
>
>
> The test case consisting of a servlet and two stateless session beans. 
> The servlet and SLSB A are deployed on node A  and SLSB B is deployed on node B.
> The servlet calls SLSB A on node A. The bean then retrieves XA data source from JNDI, creates JDBC connection and inserts a row into a table in the database (Postgres). 
> Next it retrieves JmsXa connection factory from JNDI, creates connection and sends a message to a queue.
> After that it calls SLSB B on node B that retrieves XA data source from JNDI, creates JDBC connection and inserts a row into a table in the database.
> At the end it should produce two rows in the database table and a message on the queue.
> Node A has a simple byteman rule that kills node A JVM at the end of BasicAction.prepare() method. After JVM on node A dies, the JVM on node B gets  "kill -9".
> The above test case produces two different results that depend on the order in which JBoss nodes are restarted.
> If node is restarted A first followed by node B the outcome is consistent result i.e. two rows can be seen in the database.
> If the node B is restarted first followed by node A the outcome is inconsistent i.e. only one row in the table; row inserted by SLSB A on node A.
> Both beans use the default attributes for transaction support and both nodes have been configured to use JTS transactions.
> During recovery node B reports the following error:
> 2010-11-22 10:25:37,916 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-22) PeriodicRecovery: background thread backing off
> 2010-11-22 10:25:37,922 WARN  [com.arjuna.ats.jta.logging.loggerI18N] (RequestProcessor-2) [com.arjuna.ats.internal.jta.resources.jts.orbspecific.xaerror] [com.arjuna.ats.internal.jta.resources.jts.orbspecific.xaerror] XAResourceRecord.rollback caused an XA error: XAException.XAER_RMERR
> 2010-11-22 10:25:37,922 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (RequestProcessor-2) OutputObjectState::OutputObjectState()
> Where as node A reports 
> 2010-11-22 10:28:15,174 WARN  [com.arjuna.ats.jts.logging.loggerI18N] (Thread-22) [com.arjuna.ats.internal.jts.resources.rrcaught] ResourceRecord commit - caught exception: org.omg.CORBA.OBJECT_NOT_EXIST: Server-side Exception: unknown oid  vmcid: 0x0  minor code: 0  completed: No
> Postgres log contains the following error:
> 2010-11-22 10:25:37 GMTERROR:  prepared transaction with identifier "131072_Mi0tM2Y1N2ZlOWM6YzQ5ZTo0Y2VhNDM4MDpmYQ==_LTNmNTdmZTkyOjRhZDY6NGNlYTQzOGQ6ZmQ=" does not exist
> 2010-11-22 10:25:37 GMTSTATEMENT:  ROLLBACK PREPARED '131072_Mi0tM2Y1N2ZlOWM6YzQ5ZTo0Y2VhNDM4MDpmYQ==_LTNmNTdmZTkyOjRhZDY6NGNlYTQzOGQ6ZmQ='

-- 
This message is automatically generated by JIRA.
-
For more information on JIRA, see: http://www.atlassian.com/software/jira