-
1. Re: XA_RBROLLBACK on XAResource.end
jhalliday Aug 15, 2007 5:37 AM (in response to traffic)Hmm, interesting corner case. Which resource manager are you using? I don't recall ever coming across one that returns XA_RBROLLBACK on XAResource.end, although clearly it is allowed. In what circumstances is it doing so?
-
2. Re: XA_RBROLLBACK on XAResource.end
marklittle Aug 15, 2007 10:08 AM (in response to traffic)"traffic" wrote:
Conducting some testing I noticed that when a XAResource throws a XAException with errorCode set to XA_RBROLLBACK on XAResource.end, the JBoss transaction manager (TM) assumes that the resource manager has rolled back the transaction and never calls XAResource.rollback.
That's not the case: if any participant causes the transaction to have to roll back during commit, then we'll call roll back on that participant as well. If you're not seeing that happen then there's definitely something wrong. What makes you think that rollback has not been called?
I think the error message you're seeing could do with rephrasing though. What has happened here is that you've tried to commit a transaction and it hasn't, so it's been aborted. That's prefectly valid. But the text doesn't really convey that. -
3. Re: XA_RBROLLBACK on XAResource.end
traffic Aug 15, 2007 7:07 PM (in response to traffic)
Hmm, interesting corner case. Which resource manager are you using? I don't recall ever coming across one that returns XA_RBROLLBACK on XAResource.end, although clearly it is allowed. In what circumstances is it doing so?
We?re using our own XAResource ? it?s used in our resource adapter implementation.
Here?s what leads to the XA_RBROLLBACK on XAResource.end
This test involves a SLSB, a single resource manager, and CMT.
While in transaction state, the caller suffers an exception accessing a program in an EIS environment, which causes our resource adapter to flag the transaction as rollback-only. When XAResource.end is eventually called by the transaction manager, we throw a XAException with errorCode set to XA_RBROLLBACK, which is done to simply notify the TM to not bother with going through the 2pc phase (if multiple resource managers were involved), but to immediately roll back the transaction. (We could simply wait for the Prepare -if multiple resource managers were involved - or the XAResource.commit and then send the XA_RBROLLBACK).
Thanks for your help. -
4. Re: XA_RBROLLBACK on XAResource.end
traffic Aug 15, 2007 8:04 PM (in response to traffic)
That's not the case: if any participant causes the transaction to have to roll back during commit, then we'll call roll back on that participant as well. If you're not seeing that happen then there's definitely something wrong. What makes you think that rollback has not been called?
Here's what we are seeing:
While in transaction state the caller executes the following:
1)Caller (a SLSB) gets a connection
2)Creates an interaction (javax.resource.cci.Connection.createInteraction)
3)The Interaction fails with an exception
4)Resource adapter flags the transaction as rollback-only due to the Interaction exception
5)TM calls XAResource.end
6)XAResource throws XAException with errorCode set to XA_RBROLLBACK
Other than my logs showing that XAResource.rollback was never called and an outstanding transaction in the EIS environment, I would have to say the transaction was not rolled back. But again, I could be missing something?
The test was conducted using JBoss 4.2.0 and JBoss 4.0.3.
The test passed when I tried using the old standard JBoss transaction manager on JBoss 4.0.2.
I think the error message you're seeing could do with rephrasing though. What has happened here is that you've tried to commit a transaction and it hasn't, so it's been aborted. That's prefectly valid. But the text doesn't really convey that.
We aren't doing anything to the transaction. We're simply waiting for the TM.
Here are parts of two server logs from 4.0.3 (4.2.0 is similar). I can forward the logs to you if you like. The log differ in that one lists TransactionImple.rollback and the other lists TransactionImple.commit. In the TransactionImple.commit case, the application was redeploy. Im not sure if that means anything at all.2007-08-15 13:50:53,503 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0503][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] --->TIPXAResource.start 2007-08-15 13:50:53,503 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0503][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] xid = 01000200031e196a7261632d2d33666334303739313a3633393a34366333363666363a36302d33666334303739313a3633393a34366333363666363a3633 2007-08-15 13:50:53,503 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0503][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] flags = 0 2007-08-15 13:50:53,503 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0503][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] COMSManagedConnection uid = 7f509a7a:1146b4a33a3:07fb3 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] --->COMSManagedConnection.transactionStarted 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] transactionType = 0 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] transactionIdentifier = 01000200031e196a7261632d2d33666334303739313a3633393a34366333363666363a36302d33666334303739313a3633393a34366333363666363a3633 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] xaFlags = 0 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Current transaction state: TX_NONE_STATE (0) 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] <---COMSManagedConnection.transactionStarted 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] new transactionState = TX_ACTIVE_STATE (1) 2007-08-15 13:50:53,847 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0847][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] <---TIPXAResource.start 2007-08-15 13:50:53,847 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 1 ) 2007-08-15 13:50:53,847 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (-3fc40791:639:46c366f6:64, 1) 2007-08-15 13:50:53,862 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 30, 25, jrac--3fc40791:639:46c366f6:60-3fc40791:639:46c366f6:63 > ) 2007-08-15 13:50:53,862 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:639:46c366f6:64 2007-08-15 13:50:53,862 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0862][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Entering getConnection 2007-08-15 13:50:53,862 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0862][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Created COMSConnection with uid 7f509a7a:1146b4a33a3:07fac 2007-08-15 13:50:53,862 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0862][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Exiting getConnection 2007-08-15 13:50:53,862 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0862][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fdc][CON ] Exiting getConnection 2007-08-15 13:50:53,862 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0862][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Entering createInteraction 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Created COMSInteraction with uid 7f509a7a:1146b4a33a3:07fab 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Added COMSInteraction [7f509a7a:1146b4a33a3:07fab], connection has 1 active interaction(s) 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Exiting createInteraction 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] --->COMSInteraction.execute(InteractionSpec, Record, Record) 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] Interaction Verb = SYNC_SEND_RECEIVE 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] In Record Name = InputRecord 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] Out Record Name = OutputRecord 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] Starting Java -> MCP data conversion from record InputRecord 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fbb][INT ] --->InputRecord.toByteArray 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fbb][INT ] encoding = com.unisys.coms.connector.COMSAseriesEbcdic 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fbc][INT ] --->COMSMappedRecord.toByteArray 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fbc][INT ] Converting 1 item(s) in record 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fba][INT ] --->COMSEbcdic.toByteArray 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fba][INT ] encoding = com.unisys.coms.connector.COMSAseriesEbcdic 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fba][INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] >>>>>>>>>>>>>>>>>> Starting Stack Trace <<<<<<<<<<<<<<<<<< 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] [INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null, error code: ERROR-INT-011 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] 2007-08-15 13:50:53,878 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0878][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fab][INT ] javax.resource.ResourceException: [INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null, error code: ERROR-INT-011 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Entering close 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Closing 1 active Interaction(s) 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Closing Interaction 7f509a7a:1146b4a33a3:07fab 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Closed Interaction 7f509a7a:1146b4a33a3:07fab 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Closed 1 Interaction(s) 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Connection is no longer active 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Entering fireConnectionClosedEvent 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Firing Connection closed event; 1 listener(s) are registered 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Exiting fireConnectionClosedEvent 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fac][CON ] Exiting close 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.setRollbackOnly 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.equals 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.rollback 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Abort() for action-id -3fc40791:639:46c366f6:60 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doAbort (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@fe2509) 2007-08-15 13:50:53,894 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelAbort for < 131075, 30, 25, jrac--3fc40791:639:46c366f6:60-3fc40791:639:46c366f6:63 > 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] --->TIPXAResource.end 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] xid = 01000200031e196a7261632d2d33666334303739313a3633393a34366333363666363a36302d33666334303739313a3633393a34366333363666363a3633 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] flags = 4000000 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] local = false 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb1][TX ] COMSManagedConnection uid = 7f509a7a:1146b4a33a3:07fb3 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] --->COMSManagedConnection.transactionCompleted 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] xaFlags = 4000000 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Current transaction state: TX_ACTIVE_STATE (1) 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Transaction failed: id = 01000200031e196a7261632d2d33666334303739313a3633393a34366333363666363a36302d33666334303739313a3633393a34366333363666363a3633 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] <---COMSManagedConnection.transactionCompleted - return value = false 2007-08-15 13:50:53,894 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0894][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] new transactionState = TX_NONE_STATE (0) 2007-08-15 13:50:53,909 WARN [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.rollbackxaerror] [com.arjuna.ats.internal.jta.resources.arjunacore.rollbackxaerror] XAResourceRecord.rollback - xa error XAException.XA_RBROLLBACK 2007-08-15 13:50:53,909 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Entering cleanup 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Clean Up Request: 0 connection(s) active 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] ManagedConnection cleanup successful 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] --->COMSManagedConnection.setMCState 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] current state = READY [2] 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] new state = READY [2] 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] <---COMSManagedConnection.setMCState 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] new MC State = READY [2] 2007-08-15 13:50:53,909 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 13:50:53.0909][ http-0.0.0.0-8080-1][7f509a7a:1146b4a33a3:07fb3][MC ] Exiting cleanup 2007-08-15 13:50:53,909 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2007-08-15 13:50:53,909 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend 2007-08-15 13:50:53,909 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3fc40791:639:46c366f6:60 removing 1721a26 2007-08-15 13:50:53,909 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action -3fc40791:639:46c366f6:60 removing 1721a26 result = true
2007-08-15 14:46:42,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:42.0845][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] --->TIPXAResource.start 2007-08-15 14:46:42,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:42.0845][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6131623a34366333373363303a36322d33666334303739313a6131623a34366333373363303a3635 2007-08-15 14:46:42,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:42.0845][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] flags = 0 2007-08-15 14:46:42,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:42.0845][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] COMSManagedConnection uid = 66a4a638:1146b7c2a97:07f7b 2007-08-15 14:46:42,939 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:42.0939][ JCA PoolFiller][66a4a638:1146b7c2a97:07f78][MC ] >>>>>>>>>>>>>>>>>> Dumping contents of byte array outbound framing header <<<<<<<<<<<<<<<<<< 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] --->COMSManagedConnection.transactionStarted 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] transactionType = 0 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] transactionIdentifier = 01000200031e196a7261632d2d33666334303739313a6131623a34366333373363303a36322d33666334303739313a6131623a34366333373363303a3635 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] xaFlags = 0 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Current transaction state: TX_NONE_STATE (0) 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] <---COMSManagedConnection.transactionStarted 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] new transactionState = TX_ACTIVE_STATE (1) 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] <---TIPXAResource.start 2007-08-15 14:46:43,204 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 1 ) 2007-08-15 14:46:43,204 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (-3fc40791:a1b:46c373c0:66, 1) 2007-08-15 14:46:43,204 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 30, 25, jrac--3fc40791:a1b:46c373c0:62-3fc40791:a1b:46c373c0:65 2007-08-15 14:46:43,204 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:a1b:46c373c0:66 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Entering getConnection 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Created COMSConnection with uid 66a4a638:1146b7c2a97:07f74 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Exiting getConnection 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f8c][CON ] Exiting getConnection 2007-08-15 14:46:43,204 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0204][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Entering createInteraction 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Created COMSInteraction with uid 66a4a638:1146b7c2a97:07f73 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Added COMSInteraction [66a4a638:1146b7c2a97:07f73], connection has 1 active interaction(s) 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Exiting createInteraction 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] --->COMSInteraction.execute(InteractionSpec, Record, Record) 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] Interaction Verb = SYNC_SEND_RECEIVE 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] In Record Name = InputRecord 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] Out Record Name = OutputRecord 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] Starting Java -> MCP data conversion from record InputRecord 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f83][INT ] --->InputRecord.toByteArray 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f83][INT ] encoding = com.unisys.coms.connector.COMSAseriesEbcdic 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f84][INT ] --->COMSMappedRecord.toByteArray 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f84][INT ] Converting 1 item(s) in record 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f82][INT ] --->COMSEbcdic.toByteArray 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f82][INT ] encoding = com.unisys.coms.connector.COMSAseriesEbcdic 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f82][INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] >>>>>>>>>>>>>>>>>> Starting Stack Trace <<<<<<<<<<<<<<<<<< 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] [INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null, error code: ERROR-INT-011 2007-08-15 14:46:43,220 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] 2007-08-15 14:46:43,235 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0220][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f73][INT ] javax.resource.ResourceException: [INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null, error code: ERROR-INT-011 2007-08-15 14:46:43,235 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0235][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Entering close 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Closing 1 active Interaction(s) 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Closing Interaction 66a4a638:1146b7c2a97:07f73 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Closed Interaction 66a4a638:1146b7c2a97:07f73 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Closed 1 Interaction(s) 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Connection is no longer active 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Entering fireConnectionClosedEvent 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Firing Connection closed event; 1 listener(s) are registered 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Exiting fireConnectionClosedEvent 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f74][CON ] Exiting close 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.equals 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.commit 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id -3fc40791:a1b:46c373c0:62 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::onePhaseCommit() for action-id -3fc40791:a1b:46c373c0:62 2007-08-15 14:46:43,251 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelOnePhaseCommit for < 131075, 30, 25, jrac--3fc40791:a1b:46c373c0:62-3fc40791:a1b:46c373c0:65 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] --->TIPXAResource.end 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6131623a34366333373363303a36322d33666334303739313a6131623a34366333373363303a3635 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] flags = 4000000 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] local = false 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f79][TX ] COMSManagedConnection uid = 66a4a638:1146b7c2a97:07f7b 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] --->COMSManagedConnection.transactionCompleted 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] xaFlags = 4000000 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Current transaction state: TX_ACTIVE_STATE (1) 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Transaction failed: id = 01000200031e196a7261632d2d33666334303739313a6131623a34366333373363303a36322d33666334303739313a6131623a34366333373363303a3635 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] <---COMSManagedConnection.transactionCompleted - return value = false 2007-08-15 14:46:43,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0251][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] new transactionState = TX_NONE_STATE (0) 2007-08-15 14:46:43,251 INFO [STDOUT] javax.transaction.xa.XAException 2007-08-15 14:46:43,251 INFO [STDOUT] at com.unisys.tip.TIPXAResource.end(TIPXAResource.java:403) 2007-08-15 14:46:43,251 INFO [STDOUT] at com.unisys.tip.TIPXAResource.end(TIPXAResource.java:417) 2007-08-15 14:46:43,251 INFO [STDOUT] at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:601) 2007-08-15 14:46:43,251 INFO [STDOUT] at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2620) 2007-08-15 14:46:43,251 INFO [STDOUT] at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1780) 2007-08-15 14:46:43,251 INFO [STDOUT] at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:87) 2007-08-15 14:46:43,251 INFO [STDOUT] at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:208) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.plugins.TxInterceptorCMT.endTransaction(TxInterceptorCMT.java:486) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:346) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.ejb.Container.invoke(Container.java:873) 2007-08-15 14:46:43,251 INFO [STDOUT] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2007-08-15 14:46:43,251 INFO [STDOUT] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 2007-08-15 14:46:43,251 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 2007-08-15 14:46:43,251 INFO [STDOUT] at java.lang.reflect.Method.invoke(Method.java:585) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.mx.server.Invocation.invoke(Invocation.java:72) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:155) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:104) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:179) 2007-08-15 14:46:43,251 INFO [STDOUT] at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:165) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:55) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:97) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:86) 2007-08-15 14:46:43,267 INFO [STDOUT] at $Proxy65.method(Unknown Source) 2007-08-15 14:46:43,267 INFO [STDOUT] at methodBean.submit(methodBean.java:84) 2007-08-15 14:46:43,267 INFO [STDOUT] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2007-08-15 14:46:43,267 INFO [STDOUT] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 2007-08-15 14:46:43,267 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 2007-08-15 14:46:43,267 INFO [STDOUT] at java.lang.reflect.Method.invoke(Method.java:585) 2007-08-15 14:46:43,267 INFO [STDOUT] at com.sun.faces.el.MethodBindingImpl.invoke(MethodBindingImpl.java:126) 2007-08-15 14:46:43,267 INFO [STDOUT] at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:72) 2007-08-15 14:46:43,267 INFO [STDOUT] at javax.faces.component.UICommand.broadcast(UICommand.java:312) 2007-08-15 14:46:43,267 INFO [STDOUT] at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:267) 2007-08-15 14:46:43,267 INFO [STDOUT] at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:381) 2007-08-15 14:46:43,267 INFO [STDOUT] at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:75) 2007-08-15 14:46:43,267 INFO [STDOUT] at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:248) 2007-08-15 14:46:43,267 INFO [STDOUT] at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:90) 2007-08-15 14:46:43,267 INFO [STDOUT] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:193) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527) 2007-08-15 14:46:43,267 INFO [STDOUT] at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112) 2007-08-15 14:46:43,267 INFO [STDOUT] at java.lang.Thread.run(Thread.java:595) 2007-08-15 14:46:43,267 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Entering cleanup 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Clean Up Request: 0 connection(s) active 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] ManagedConnection cleanup successful 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] --->COMSManagedConnection.setMCState 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] current state = READY [2] 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] new state = READY [2] 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] <---COMSManagedConnection.setMCState 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] new MC State = READY [2] 2007-08-15 14:46:43,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 15, 2007 14:46:43.0267][ http-0.0.0.0-8080-3][66a4a638:1146b7c2a97:07f7b][MC ] Exiting cleanup 2007-08-15 14:46:43,267 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2007-08-15 14:46:43,267 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend 2007-08-15 14:46:43,267 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3fc40791:a1b:46c373c0:62 removing 1d1964d 2007-08-15 14:46:43,267 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action -3fc40791:a1b:46c373c0:62 removing 1d1964d result = true
Maybe there's someting I'm overlooking. Anyways, thanks for your help. -
5. Re: XA_RBROLLBACK on XAResource.end
marklittle Aug 16, 2007 7:10 AM (in response to traffic)Hold on ... you've only got one resource in your transaction?
-
6. Re: XA_RBROLLBACK on XAResource.end
jhalliday Aug 16, 2007 8:14 AM (in response to traffic)OK, that's an error in our code. I've queued it up for fixing the in the next version. Thanks for bringing this to our attention.
http://jira.jboss.com/jira/browse/JBTM-278 -
7. Re: XA_RBROLLBACK on XAResource.end
marklittle Aug 16, 2007 8:48 AM (in response to traffic)For now, turn off one-phase commit optimization.
-
8. Re: XA_RBROLLBACK on XAResource.end
traffic Aug 16, 2007 11:41 PM (in response to traffic)
Hold on ... you've only got one resource in your transaction?
The test didn't work with 2 resource managers, but for a different reason. It seems that the TM is trying to roll back the transaction after receiving the XA_RBROLLBACK on XAResourece.end; however, in the process the TM calls XAResource.end on the same RM that threw the XAException/XA_RBROLLBACK on a previous call to XAResource.end, which causes that RM to throw a XAException with errorCode set to XAER_PROTO. The XAER_PROTO is returned since the first call to XAResource.end dissociated the RM from the transaction (the XAException/XA_RBROLLBACK was thrown to inform the TM that the transaction has been marked rollback-only and is no longer associated with the RM).
I guess this goes back to my original post: Does throwing XAException with errorCode set to XA_RBROLLBACK on XAResource.end mean that the transaction has been marked rollback-only and the RM is no longer associated with the transaction or does it simply mean that an exception has happened and the TM should call XAResource.end again at some point? I believe the former.
I was able to get the transaction (using 2 RMs) to successfully roll back using JBoss 4.0.2 and the old JBoss transaction manager.
Anyhow, here's what we?re seeing:
While in transaction state the caller executes the following:
1) Caller (a SLSB) gets a connection ? connection is associated with RM-1 (XAResource)
2) Creates an interaction (javax.resource.cci.Connection.createInteraction)
3) Successfully executes the interaction (javax.resource.cci.Interaction.execute)
4) Caller get a second connection - c2 ? connection is associated with RM-2
5) Creates an interaction on connection c2
6) The Interaction associated with c2 fails with an exception
7) Resource adapter flags the transaction as rollback-only for connection c2 due to the Interaction exception
8) TM calls XAResource.end for RM-1, which returns successfully
9) TM calls XAResource.prepare for RM-1, which returns successfully
10) TM calls XAResource.end for RM-2, which throws an XAException with errorCode set to XA_RBROLLBACK
11) TM calls XAResource.rollback for RM-1, which returns successfully
12) TM calls XAResource.end for RM-2, which throws a XAException with errorCode set XAER_PROTO because the RM has previously been disassociated from the transaction at step 10.
I was wondering if there's a setting to have XAResource.end called first for all RMs involved in the transaction followed by the transaction completion phase(s)?
Here's part of the server log from the test...2007-08-16 18:55:25,063 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0063][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] --->TIPXAResource.start 2007-08-16 18:55:25,063 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0063][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3633 2007-08-16 18:55:25,063 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0063][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] flags = 0 2007-08-16 18:55:25,063 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0063][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07faf 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] --->COMSManagedConnection.transactionStarted 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] transactionType = 0 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] transactionIdentifier = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3633 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] xaFlags = 0 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Current transaction state: TX_NONE_STATE (0) 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] <---COMSManagedConnection.transactionStarted 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] new transactionState = TX_ACTIVE_STATE (1) 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] <---TIPXAResource.start 2007-08-16 18:55:25,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 1 ) 2007-08-16 18:55:25,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (-3fc40791:f5e:46c4ffd7:64, 1) 2007-08-16 18:55:25,157 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 30, 25, jrac--3fc40791:f5e:46c4ffd7:60-3fc40791:f5e:46c4ffd7:63 2007-08-16 18:55:25,157 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:f5e:46c4ffd7:64 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Entering getConnection 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Created COMSConnection with uid 3b477e4f:1147187618d:07fa8 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Exiting getConnection 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fdc][CON ] Exiting getConnection 2007-08-16 18:55:25,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Entering createInteraction 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Created COMSInteraction with uid 3b477e4f:1147187618d:07fa7 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Added COMSInteraction [3b477e4f:1147187618d:07fa7], connection has 1 active interaction(s) 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Exiting createInteraction 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] --->COMSInteraction.execute(InteractionSpec, Record, Record) 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] Interaction Verb = SYNC_SEND_RECEIVE 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] In Record Name = InputRecord 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] Out Record Name = OutputRecord 2007-08-16 18:55:25,173 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0173][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] Starting Java -> MCP data conversion from record InputRecord 2007-08-16 18:55:25,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0845][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] Starting MCP -> Java data conversion, inserting 20 bytes into record OutputRecord 2007-08-16 18:55:25,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0845][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] MCP -> Java data conversion complete 2007-08-16 18:55:25,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:25.0845][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa7][INT ] <---COMSInteraction.execute(InteractionSpec, Record, Record) - return value = true 2007-08-16 18:55:25,845 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:25.0845][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fd9][CON ] Entering getConnection 2007-08-16 18:55:25,845 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:25,845 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:25,845 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.getStatus 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( com.unisys.tip.TIPXAResource@1feae0f ) 2007-08-16 18:55:26,142 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,142 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] --->TIPXAResource.isSameRM 2007-08-16 18:55:26,142 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] xares = uid = 3b477e4f:1147187618d:07fa3 2007-08-16 18:55:26,142 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07faf 2007-08-16 18:55:26,142 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] <---TIPXAResource.isSameRM - return value = false 2007-08-16 18:55:26,142 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] --->TIPXAResource.setTransactionTimeout 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] seconds = 300 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0142][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07fa5 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] XAResource transaction timeout set to 300 second(s) 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] <---TIPXAResource.setTransactionTimeout - return value = true 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] --->TIPXAResource.start 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] flags = 0 2007-08-16 18:55:26,157 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0157][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07fa5 2007-08-16 18:55:26,235 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0235][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] --->COMSManagedConnection.transactionStarted 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0235][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] transactionType = 0 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0235][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] transactionIdentifier = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0235][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] xaFlags = 0 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Current transaction state: TX_NONE_STATE (0) 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] <---COMSManagedConnection.transactionStarted 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] new transactionState = TX_ACTIVE_STATE (1) 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] <---TIPXAResource.start 2007-08-16 18:55:26,251 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StateManager::StateManager( 1 ) 2007-08-16 18:55:26,251 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (-3fc40791:f5e:46c4ffd7:67, 1) 2007-08-16 18:55:26,251 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 30, 25, jrac--3fc40791:f5e:46c4ffd7:60-3fc40791:f5e:46c4ffd7:66 2007-08-16 18:55:26,251 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3fc40791:f5e:46c4ffd7:64) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:f5e:46c4ffd7:67 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Entering getConnection 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Created COMSConnection with uid 3b477e4f:1147187618d:07f9f 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Exiting getConnection 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fd9][CON ] Exiting getConnection 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Entering createInteraction 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Created COMSInteraction with uid 3b477e4f:1147187618d:07f9e 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Added COMSInteraction [3b477e4f:1147187618d:07f9e], connection has 1 active interaction(s) 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Exiting createInteraction 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] --->COMSInteraction.execute(InteractionSpec, Record, Record) 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] Interaction Verb = SYNC_SEND_RECEIVE 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] In Record Name = InputRecord2 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] Out Record Name = OutputRecord2 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] Starting Java -> MCP data conversion from record InputRecord2 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9c][INT ] --->InputRecord2.toByteArray 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9c][INT ] encoding = com.unisys.coms.connector.COMSAseriesEbcdic 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9d][INT ] --->COMSMappedRecord.toByteArray 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9d][INT ] Converting 1 item(s) in record 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9b][INT ] --->COMSEbcdic.toByteArray 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9b][INT ] encoding = com.unisys.coms.connector.COMSAseriesEbcdic 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9b][INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] >>>>>>>>>>>>>>>>>> Starting Stack Trace <<<<<<<<<<<<<<<<<< 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] [INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null, error code: ERROR-INT-011 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] 2007-08-16 18:55:26,251 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0251][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9e][INT ] javax.resource.ResourceException: [INT ] Null Data Value:[COMSEbcdic.toByteArray] - object to be sent to a COMS program is null, error code: ERROR-INT-011 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Entering close 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Closing 1 active Interaction(s) 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Closing Interaction 3b477e4f:1147187618d:07fa7 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Closed Interaction 3b477e4f:1147187618d:07fa7 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Closed 1 Interaction(s) 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Connection is no longer active 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Entering fireConnectionClosedEvent 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Firing Connection closed event; 1 listener(s) are registered 2007-08-16 18:55:26,267 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,267 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Exiting fireConnectionClosedEvent 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa8][CON ] Exiting close 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Entering close 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Closing 1 active Interaction(s) 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Closing Interaction 3b477e4f:1147187618d:07f9e 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Closed Interaction 3b477e4f:1147187618d:07f9e 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Closed 1 Interaction(s) 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Connection is no longer active 2007-08-16 18:55:26,267 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0267][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Entering fireConnectionClosedEvent 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Firing Connection closed event; 1 listener(s) are registered 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Exiting fireConnectionClosedEvent 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07f9f][CON ] Exiting close 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.equals 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.commit 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.beforeCompletion 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id -3fc40791:f5e:46c4ffd7:60 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::prepare () for action-id -3fc40791:f5e:46c4ffd7:60 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.ShadowingStore( 14 ) 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowNoFileLockStore.ShadowNoFileLockStore( 14 ) 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedStore( 14 ) 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedActionStore() 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.setupStore() 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(PutObjectStoreDirHere\HashedActionStore\defaultStore\) 2007-08-16 18:55:26,282 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelPrepare for < 131075, 30, 25, jrac--3fc40791:f5e:46c4ffd7:60-3fc40791:f5e:46c4ffd7:63 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] --->TIPXAResource.end 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3633 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] flags = 4000000 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] local = false 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07faf 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] --->COMSManagedConnection.transactionCompleted 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] xaFlags = 4000000 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Current transaction state: TX_ACTIVE_STATE (1) 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Transaction completed: id = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3633 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] <---COMSManagedConnection.transactionCompleted - return value = true 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] new transactionState = TX_NONE_STATE (0) 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] <---TIPXAResource.end 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] --->TIPXAResource.prepare 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3633 2007-08-16 18:55:26,282 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0282][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07faf 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] <---TIPXAResource.prepare - return value = 0 2007-08-16 18:55:26,501 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:f5e:46c4ffd7:64 2007-08-16 18:55:26,501 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelPrepare for < 131075, 30, 25, jrac--3fc40791:f5e:46c4ffd7:60-3fc40791:f5e:46c4ffd7:66 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] --->TIPXAResource.end 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] flags = 4000000 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] local = false 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07fa5 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] --->COMSManagedConnection.transactionCompleted 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] xaFlags = 4000000 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Current transaction state: TX_ACTIVE_STATE (1) 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Transaction failed: id = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] <---COMSManagedConnection.transactionCompleted - return value = false 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] new transactionState = TX_NONE_STATE (0) 2007-08-16 18:55:26,501 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3fc40791:f5e:46c4ffd7:67 2007-08-16 18:55:26,501 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id -3fc40791:f5e:46c4ffd7:60 failed. 2007-08-16 18:55:26,501 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting 2007-08-16 18:55:26,501 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::phase2Abort() for action-id -3fc40791:f5e:46c4ffd7:60 2007-08-16 18:55:26,501 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doAbort (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@d79c75) 2007-08-16 18:55:26,501 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelAbort for < 131075, 30, 25, jrac--3fc40791:f5e:46c4ffd7:60-3fc40791:f5e:46c4ffd7:63 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] --->TIPXAResource.rollback 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3633 2007-08-16 18:55:26,501 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0501][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07faf 2007-08-16 18:55:26,751 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0751][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fac][TX ] <---TIPXAResource.rollback 2007-08-16 18:55:26,751 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doAbort (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@1013985) 2007-08-16 18:55:26,751 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelAbort for < 131075, 30, 25, jrac--3fc40791:f5e:46c4ffd7:60-3fc40791:f5e:46c4ffd7:66 2007-08-16 18:55:26,751 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0751][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] --->TIPXAResource.end 2007-08-16 18:55:26,751 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0751][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] xid = 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0751][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] flags = 4000000 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0751][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] local = false 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0751][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] COMSManagedConnection uid = 3b477e4f:1147187618d:07fa5 2007-08-16 18:55:26,767 INFO [STDOUT] [Aug 16, 2007 18:55:26.0767][TX ] In end, no transaction started on XAResource, xid passed: 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] >>>>>>>>>>>>>>>>>> Starting Stack Trace <<<<<<<<<<<<<<<<<< 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] In end, no transaction started on XAResource, xid passed: 01000200031e196a7261632d2d33666334303739313a6635653a34366334666664373a36302d33666334303739313a6635653a34366334666664373a3636 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] javax.transaction.xa.XAException 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.unisys.tip.TIPXAResource.displayXAException(TIPXAResource.java:1096) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.unisys.tip.TIPXAResource.end(TIPXAResource.java:312) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.unisys.tip.TIPXAResource.end(TIPXAResource.java:417) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:353) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3219) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3197) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:2212) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1810) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:87) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:208) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.plugins.TxInterceptorCMT.endTransaction(TxInterceptorCMT.java:486) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:346) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.ejb.Container.invoke(Container.java:873) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at java.lang.reflect.Method.invoke(Method.java:585) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.mx.server.Invocation.invoke(Invocation.java:72) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:155) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:104) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:179) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:165) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:55) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:97) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:86) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at $Proxy57.method(Unknown Source) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at methodBean.submit(methodBean.java:84) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at java.lang.reflect.Method.invoke(Method.java:585) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.sun.faces.el.MethodBindingImpl.invoke(MethodBindingImpl.java:126) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:72) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at javax.faces.component.UICommand.broadcast(UICommand.java:312) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:267) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:381) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:75) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:248) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:90) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:193) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] at java.lang.Thread.run(Thread.java:595) 2007-08-16 18:55:26,767 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0767][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa3][TX ] >>>>>>>>>>>>>>>>>> Stack Trace Complete <<<<<<<<<<<<<<<<<< 2007-08-16 18:55:26,782 WARN [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.resources.arjunacore.rollbackxaerror] [com.arjuna.ats.internal.jta.resources.arjunacore.rollbackxaerror] XAResourceRecord.rollback - xa error XAException.XAER_PROTO 2007-08-16 18:55:26,782 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_54] - Top-level abort of action -3fc40791:f5e:46c4ffd7:60 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD> 2007-08-16 18:55:26,782 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id -3fc40791:f5e:46c4ffd7:60 2007-08-16 18:55:26,782 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Entering cleanup 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Clean Up Request: 0 connection(s) active 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] ManagedConnection cleanup successful 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] --->COMSManagedConnection.setMCState 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] current state = READY [2] 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] new state = READY [2] 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] <---COMSManagedConnection.setMCState 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] new MC State = READY [2] 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07faf][MC ] Exiting cleanup 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Entering cleanup 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Clean Up Request: 0 connection(s) active 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] ManagedConnection cleanup successful 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] --->COMSManagedConnection.setMCState 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] current state = READY [2] 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] new state = READY [2] 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] <---COMSManagedConnection.setMCState 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] new MC State = READY [2] 2007-08-16 18:55:26,782 INFO [com.unisys.coms.connector.COMSManagedConnectionFactory.jrac/basic2] [Aug 16, 2007 18:55:26.0782][ http-0.0.0.0-8080-1][3b477e4f:1147187618d:07fa5][MC ] Exiting cleanup 2007-08-16 18:55:26,782 DEBUG [com.arjuna.ats.jta.logging.logger] SynchronizationImple.afterCompletion 2007-08-16 18:55:26,782 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend 2007-08-16 18:55:26,782 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3fc40791:f5e:46c4ffd7:60 removing 176b9ea 2007-08-16 18:55:26,782 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action -3fc40791:f5e:46c4ffd7:60 removing 176b9ea result = true 2007-08-16 18:55:26,782 ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackException in method: public abstract p1.p2.p3.OutputRecord p1.p2.p3.testBasic.method(p1.p2.p3.InputRecord) throws java.rmi.RemoteException, causedBy: javax.transaction.RollbackException at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commit(TransactionImple.java:223) at org.jboss.ejb.plugins.TxInterceptorCMT.endTransaction(TxInterceptorCMT.java:486) at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:346) at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166) at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153) at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192) at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122) at org.jboss.ejb.SessionContainer.internalInvoke(SessionContai
-
9. Re: XA_RBROLLBACK on XAResource.end
marklittle Aug 17, 2007 4:49 AM (in response to traffic)Check out the issue Jonathan raised.
-
10. Re: XA_RBROLLBACK on XAResource.end
jhalliday Aug 17, 2007 8:51 AM (in response to traffic)> Does throwing XAException with errorCode set to XA_RBROLLBACK on XAResource.end mean that the transaction has been marked rollback-only and the RM is no longer associated with the transaction or does it simply mean that an exception has happened and the TM should call XAResource.end again at some point? I believe the former.
I agree end should be called exactly once, as should rollback if end throws an exception. Indeed we do have code in place to make the abort (rollback) skip calling end again if it was called during prepare and threw an exception. Unfortunately it's broken, which is why you are seeing the above behavior.