JCA Spec violation using resource-adapter in JBoss 7?

[jleinawe]

JBoss AS 7.1.1.Final-SNAPSHOT

JBoss IronJacamar 1.0.8.Final

Testing a JMS resource-adapter deployed to JBoss which will use WebLogic as the JMS provider.  In a transacted MDB test, this error appears in the JBoss log (which is attached) when the MDB tries to send and outbound reply message

11:18:24,023 ERROR [stderr] (default-short-running-threads-threads - 1) javax.transaction.xa.XAException: J2EE GJRA-01501: cause = Attempt to start a transaction while in an active (global or local) transaction.; action = Complete current transaction before starting another

By analysis our RA's own tracing, this looks like a JCA spec violation.  xaResourceWrapper2 (the XAResource for managedConnectionImpl0) is being enlisted with xid3.  Then without delisting xaResourceWrapper2, jboss is doing a managedConnectionImpl0.cleanup() call (which is a JCA spec violation).  Then later when it tries to enlist xaResourceWrapper2 with xid5, that fails because xaResourceWrapper2 is still enlisted with xid3.  (That enlistment attempt is not even getting to WebLogic JMS because the RA is detecting the XA protocol violation.)

Excerpts from log:

   out:MessageEndpoint.beforeDelivery(public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)) #4 @1361560688075..1361560688295
      in:xaResourceWrapper0.setTransactionTimeout(300) -> true #4 @1361560688102..1361560688173
         out:XAResource.setTransactionTimeout(300) -> true #4 @1361560688126..1361560688155
      in:xaResourceWrapper0.start(xid3,0) #4 @1361560688191..1361560688277 [TMNOFLAGS]
         out:XAResource.start(xid3,0) #4 @1361560688223..1361560688260     [TMNOFLAGS]
   [...]
   out:MessageListener.onMessage(genericStreamMessage0) #1 @1361560697008..1361560702586
      in:wlxaQueueConnectionFactory0.createConnection() -> wlConnection0 #1 @1361560698037..1361560700740
         out:ConnectionManager.allocateConnection(wlManagedXAQueueConnectionFactory0,connectionRequestInfoImpl0) -> wlConnection0 #1 @1361560698093..1361560700687
            [...]
            in:managedConnectionImpl0.getXAResource() -> xaResourceWrapper2 #1 @1361560699619..1361560699675
            [...]
            in:xaResourceWrapper2.start(xid3,2097152) #6 @1361560700092..1361560700275 [TMJOIN]
               out:XAResource.start(xid3,2097152) #6 @1361560700157..1361560700226     [TMJOIN]
   [...]
   out:MessageEndpoint.afterDelivery() #4 @1361560702595..1361560702930
      in:xaResourceWrapper0.end(xid3,67108864) #4 @1361560702612..1361560702709 [TMSUCCESS]
         out:XAResource.end(xid3,67108864) #5 @1361560702649..1361560702688     [TMSUCCESS]
      in:xaResourceWrapper0.commit(xid3,true) #4 @1361560702729..1361560702851
         out:XAResource.commit(xid3,true) #4 @1361560702766..1361560702830
      in:managedConnectionImpl0.cleanup() #1 @1361560702871..1361560702904 [JCA spec violation]
   out:MessageEndpoint.beforeDelivery(public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)) #6 @1361560702938..1361560703159
      [...]
   out:MessageConsumer.receive(15000) -> TextMessage[ID:<384827.1361560696991.0>, null] #6 @1361560703168..1361560703201
   out:MessageListener.onMessage(genericTextMessage0) #2 @1361560703226..1361560704964
      in:wlxaQueueConnectionFactory0.createConnection() threw #2 @1361560703250..1361560704672
         out:ConnectionManager.allocateConnection(wlManagedXAQueueConnectionFactory0,connectionRequestInfoImpl0) threw #2 @1361560703307..1361560704447
            [...]
            in:xaResourceWrapper2.start(xid5,2097152) threw #8 @1361560703786..1361560703871 [TMJOIN]

[jleinawe]

The relevant bits of the JCA spec are:

   JCA 1.5 spec:

      Figure 6-7 (page 6-43)

      7.6.5 "Scenario: Connection Close and JTA Transactional Cleanup" (page 7-26)

      Figure 7-8 (page 7-28)

   JCA 1.6 spec:

      Figure 6-7 (page 6-41)

      7.6.5 "Scenario: Connection Close and JTA Transactional Cleanup" (page 7-24)

      Figure 7-8 (page 7-26)

A slice of the log summary showing that the the RA is sending connection close notification but jboss is not responding (as required) by delisting the resource:

   [...]
   out:MessageListener.onMessage(genericStreamMessage0) #1 @1361560697008..1361560702586
      in:wlxaQueueConnectionFactory0.createConnection() -> wlConnection0 #1 @1361560698037..1361560700740
          out:ConnectionManager.allocateConnection(wlManagedXAQueueConnectionFactory0,connectionRequestInfoImpl0) -> wlConnection0 #1 @1361560698093..1361560700687
            in:wlManagedXAQueueConnectionFactory0.createManagedConnection(null,connectionRequestInfoImpl0) -> managedConnectionImpl0 #1 @1361560698194..1361560699457
               [...]
            [...]
            in:managedConnectionImpl0.getXAResource() -> xaResourceWrapper2 #1 @1361560699619..1361560699675
            [...]
            in:xaResourceWrapper2.start(xid3,2097152) #6 @1361560700092..1361560700275
               [...]
            [...]
      [...]
      in:wlConnection0.close() #1 @1361560702160..1361560702546
         [...]
         out:ConnectionEventListener.connectionClosed([...]) #1 @1361560702423..1361560702503
   out:MessageEndpoint.afterDelivery() #4 @1361560702595..1361560702930
      [...]
   [...]

I.e., immediately after the "out:ConnectionEventListener.connectionClosed" call (and with an additional level of indent) there should be an "in:xaResourceWrapper2.end" call, but the app-server is not calling XAResource.end as required.

[jesper.pedersen]

Retest your scenario with a nightly snapshot

[jleinawe]

If I download the latest snapshop

https://hudson.jboss.org/hudson/view/JBoss%20AS/job/JBoss-AS-7.0.x/

Will I need to run the patchtool for Ironjacamar (as discussed here):

https://community.jboss.org/thread/196508

[jesper.pedersen]

https://ci.jboss.org/jenkins/job/JBoss-AS-7.x-latest/ and no

[jesper.pedersen]

Also include TRACE log for org.jboss.jca

[jesper.pedersen]

If you can't attach the resource adapter itself - include the resource adapter information report - http://docs.jboss.org/ironjacamar/userguide/1.1/en-US/html/tools.html#tools_rarinfo

[jleinawe]

Attached file named "logs_0227.zip".

This contains a new JBoss server log with org.jboss.jca logging set to TRACE and the output of the rar info tool.

[jesper.pedersen]

There is no TRACE log in that zip.

You need to post your activation configuration too - and filter the log such that it shows the error together with the entire interaction with the connections in question.

[jleinawe]

I used these instructions to enable logging when I ran the test yesterday:

https://community.jboss.org/wiki/JBossAS7Logging

I just attached a new set of logs (logs_0228.zip), this time I added this to logging.properties

logger.org.jboss.jca.level=TRACE

logger.org.jboss.jca.useParentHandlers=true

When I look at the new server.log, I do see TRACE messages for org.jboss.jca*

10:12:09,254 TRACE [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Result of await: true

The logs_0228.zip attachment has my standalone.xml, logger.xml, output from the JBoss server (myjbossserver.out), and server.log.   If I am not setting logging correctly, can you forward instructions - thanks.

[jleinawe]

attached is the MDB source, which contains the @annotations for the activiation-spec properties.

I'll see about getting a filtered log for the connection.

[jleinawe]

Hi Jesper,

Thanks again for your time.   Can you clarify what you mean by "there is no TRACE log".   Is there a distinct log file for this, or is it TRACE messages in the server's log?     If the logs_0228.zip file doesn't contain what is needed, please provide instructions for creating the correct log.

I have tracing information to share from our own RA trace tools.   Attached is a file named "tracem.txt" which is generated from the RA tracing and shows calls made "in" to the RA and when the RA calls anyone "out".

Note that all the problems occur repeatedly and can be found in the first section marked:

   *******************  Inbound  ********************

The smaller section marked:

   ********************  Outbound  ********************

can be ignored as it only contains the startup/config for the RA, the managed connection connection factories, and the endpoints.  (There are no connections created/manipulated in that section.)

The timestamps in the log summary are formatted:

    @<entry-time-millis>..<exit-time-millis>

or in the case of "still running" methods just:

    @<entry-time-millis>

and those times can be used to quickly locate full trace information from the log (at entry time: parameters, at exit-time: exceptions, returned values, at both: call-stack, thread, target object, etc.).  Time stamps are not guaranteed unique so if there may be more than one matching time stamp in the full log, in which case the combination of direction, class, method and invocation-instance can be used.  (It is always unique so long as there is only a single run recorded in the log, which is the case here.)  The general format is:

   [direction]:[class].[method]([params]) [result/status] #[invocation-instance]

Direction is "in" when anyone calls the RA, and "out" when the RA calls anyone.  Some examples:

   out:WorkManager.startWork(endpointThread0) -> 6 #1 @1362075147968..1362075147979

   in:xaResourceWrapper2.start(xid5,2097152) threw #8 @1362075193570..1362075193577

   out:MessageConsumer.receive(15000) still running #22 @1362075225203

(The first returned the value 6.  The second threw an exception.  The third was still running at the time the log file is grabbed.)

Indent is used to show call nesting.  Calls are grouped by thread, and by endpoint for inbound.

For improved readability the log summary uses short names for Xids and many RA objects.  The mapping from the short names used in the log summary to the original/long names uses in the full log is in the section marked:

   ********************  Legends  ********************

Also attached is the "intermediate file" tempm.int.  It contains all "INFO  [STDOUT]" and "INFO  [stdout]" entries from the full log, but with extraneous data added by the app-server stripped out, and with any corruption/intermixing of individual log records (due to the app-server chopping them up into bits and emitting the bits from different threads) undone.  The log summary is created from the contents of this intermediate file, so everything referenced by the log summary can be found in the intermediate file, and the intermediate file is generally easier to read than the full log.

[jsteidl]

To quickly see the problem, search the log summary jleinawe provided (tempm.txt) for "xaResourceWrapper2".  The first three instances are:

in:managedConnectionImpl0.getXAResource() -> xaResourceWrapper2 #1 @1362075193107..1362075193110

[...]

in:xaResourceWrapper2.start(xid3,2097152) #6 @1362075193148..1362075193161

[...]

in:xaResourceWrapper2.start(xid5,2097152) threw #8 @1362075193570..1362075193577

As you can see, the app-server gets this XAResource from the RA, then calls XAResource.start on it multiple times in a row without calling XAResource.end in between (which is why the RA throws an exception the second time xaResourceWrapper2.start is called).  If you keep searching for "xaResourceWrapper2", you'll see several more calls to XAResource.start, but no calls to XAResource.end.

If you then search from the top of the log summary for "xid3", you'll find the following calls made to the RA ("in:" calls):

in:xaResourceWrapper0.start(xid3,0) #4 @1362075179562..1362075179570

[...]

in:xaResourceWrapper2.start(xid3,2097152) #6 @1362075193148..1362075193161

[...]

in:xaResourceWrapper0.end(xid3,67108864) #4 @1362075193388..1362075193396

[...]

in:xaResourceWrapper0.commit(xid3,true) #4 @1362075193397..1362075193438

You can see that while the app-server is ending the association for xaResourceWrapper0 before committing the transaction, it is failing to do so for xaResourceWrapper2.

This line shows that wlConnection0 is the connection handle being used for managedConnectionImpl0:

   in:managedConnectionImpl0.getConnection(null,connectionRequestInfoImpl0) -> wlConnection0 #1 @1362075193164..1362075193199

And if you look at wlConnection0 being closed:

   in:wlConnection0.close() #1 @1362075193351..1362075193382

      out:Connection.stop() #1 @1362075193356..1362075193361

      out:XAResource.end(xid3,67108864) #4 @1362075193364..1362075193368

      out:ConnectionEventListener.connectionClosed(javax.resource.spi.ConnectionEvent[source=OracleJMSConnector.ManagedConnectionImpl.adc2100774.us.oracle.com.-2ebdb17:13d22011ace:-7ffb.20]) #1 @1362075193372..1362075193379

out:MessageEndpoint.afterDelivery() #4 @1362075193386..1362075193444

you'll see that the RA is calling ConnectionEventListener.connectionClosed, but the app-server is failing to delist xaResourceWrapper2 in response (as the JCA spec requires).  [Note that the "out:XAResource.end" call above is for a secondary JMS provider XAResource used internally by the RA, and is not the same as xaResourceWrapper2.]

Since the above lines are grabbed as-is (except for indent) from tempm.txt, you can see those calls in context by searching for them in that file.

[tomjenkinson]

Like the original message says, it looks to me like XAResource::start is being called twice without end being called, the second attempt, we detect that it is a resource JBTM knows about so it uses XAResource.TMJOIN (I can't actually see that message in the later logs).

I can see the stack trace coming from Oracle at this second enlist:

10:13:13,585 WARN  [com.arjuna.ats.jta] (default-threads - 1) ARJUNA016089: TransactionImple.enlistResource - xa_start  - caught: XAException.XAER_PROTO for < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0ae5bb87:5709964c:512f9df9:28, node_name=1, branch_uid=0:ffff0ae5bb87:5709964c:512f9df9:29, subordinatenodename=null, eis_name=unknown eis name >: javax.transaction.xa.XAException: J2EE GJRA-01501: cause = Attempt to start a transaction while in an active (global or local) transaction.; action = Complete current transaction before starting another

    at weblogic.jms.ra.ManagedConnectionImpl.startXA(ManagedConnectionImpl.java:1148)

    at weblogic.jms.ra.XAResourceWrapper.start(XAResourceWrapper.java:391)

    at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.start(XAResourceWrapperImpl.java:191)

    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:715)

IronJacamar is enlisting the second time AbstractConnectionManager::allocateConnection -> reconnectManagedConnection

My question is what triggers the initial enlistment here:

out:MessageEndpoint.beforeDelivery(public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)) #4 @1361560688075..1361560688295
      in:xaResourceWrapper0.setTransactionTimeout(300) -> true #4 @1361560688102..1361560688173
         out:XAResource.setTransactionTimeout(300) -> true #4 @1361560688126..1361560688155
      in:xaResourceWrapper0.start(xid3,0) #4 @1361560688191..1361560688277 [TMNOFLAGS]
         out:XAResource.start(xid3,0) #4 @1361560688223..1361560688260     [TMNOFLAGS]

I can't really find any classes that implement MessageEndpoint so I don't know how to proceed but hopefully that is enough for someone else to go on.

Thanks,

Tom

[jsteidl]

I'm not sure exactly which log you're getting that from (it's from a different run than the last one), and anyways only the latest set of logs includes the intermediate file, so I'll just go with the essentially identical bit from the logs included with post #11:

out:MessageEndpoint.beforeDelivery(public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)) #4 @1362075179551..1362075179571

   in:xaResourceWrapper0.setTransactionTimeout(300) -> true #4 @1362075179554..1362075179560

      out:XAResource.setTransactionTimeout(300) -> true #4 @1362075179556..1362075179559

   in:xaResourceWrapper0.start(xid3,0) #4 @1362075179562..1362075179570

      out:XAResource.start(xid3,0) #4 @1362075179565..1362075179568

(The only difference from the instance you were looking at is the timestamps.)

As described in post #11, you can get a full stack trace for any given call.  In this case you want to know how this is getting called:

   in:xaResourceWrapper0.start(xid3,0) #4 @1362075179562..1362075179570

The easiest way to find that is to search the intermediate file (tempm.int) for the start time (1362075179562) until you locate the entry record for the in:XAResource.start #4 call:

OracleJMSConnector event: enter method

   formal method: javax.transaction.xa.XAResource.start

   call direction: in (OracleJMSConnector is callee)

   call count: 4

   currentThread: Thread[default-threads - 1,5,default-threads]

   currentTimeMillis: 1362075179562

   call stack:

      weblogic.jms.ra.XAResourceWrapper.start(XAResourceWrapper.java:384)

      com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:636)

      com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:397)

      org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.beforeDelivery(MessageEndpointInvocationHandler.java:110)

      sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

      sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

      java.lang.reflect.Method.invoke(Method.java:601)

      org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60)

      org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136)

      org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73)

      $Proxy9.beforeDelivery(Unknown Source)

      weblogic.jms.ra.Provider.beforeDelivery(Provider.java:1460)

      weblogic.jms.ra.EndpointListener.run(EndpointListener.java:315)

      weblogic.jms.ra.EndpointThread.run(EndpointThread.java:143)

      org.jboss.jca.core.workmanager.WorkWrapper.run(WorkWrapper.java:218)

      org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)

      org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:806)

      org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)

      org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:826)

      java.lang.Thread.run(Thread.java:722)

      org.jboss.threads.JBossThread.run(JBossThread.java:122)

   target:

      formal type: javax.transaction.xa.XAResource

      actual type: weblogic.jms.ra.XAResourceWrapper

      classloader.toString: 'ModuleClassLoader for Module "deployment.wl-jms-ra.rar:main" from Service Module Loader'

      interfaces:

         interface: javax.transaction.xa.XAResource

         classloader.toString: 'ModuleClassLoader for Module "javax.transaction.api:main" from local module loader @73d0a8dc (finder: local module finder @7fe3eeb (roots: /scratch/jleinawe/p4/w/src1212_17010b18_x86_64/bea/results/wls/functional/jms/jboss/modules,/scratch/jleinawe/p4/w/src1212_17010b18_x86_64/bea/results/wls/functional/jms/jboss/modules/system/layers/base))'

      identityHashCode: 23175cbf

      toString: 'weblogic.jms.ra.XAResourceWrapper@23175cbf'

   parameter #1:

      formal type: javax.transaction.xa.Xid

      actual type: com.arjuna.ats.jta.xa.XidImple

      classloader.toString: 'ModuleClassLoader for Module "org.jboss.jts:main" from local module loader @73d0a8dc (finder: local module finder @7fe3eeb (roots: /scratch/jleinawe/p4/w/src1212_17010b18_x86_64/bea/results/wls/functional/jms/jboss/modules,/scratch/jleinawe/p4/w/src1212_17010b18_x86_64/bea/results/wls/functional/jms/jboss/modules/system/layers/base))'

      interfaces:

         interface: java.io.Serializable

         classloader is null

         interface: javax.transaction.xa.Xid

         classloader.toString: 'ModuleClassLoader for Module "javax.transaction.api:main" from local module loader @73d0a8dc (finder: local module finder @7fe3eeb (roots: /scratch/jleinawe/p4/w/src1212_17010b18_x86_64/bea/results/wls/functional/jms/jboss/modules,/scratch/jleinawe/p4/w/src1212_17010b18_x86_64/bea/results/wls/functional/jms/jboss/modules/system/layers/base))'

      identityHashCode: 3447fc7

      Xid value:

         formatID: 131077 (0x20005)

             gtid: 00000000000000000000ffff0ae5bb875709964c512f9df90000001d31 (29 bytes)

            bqual: 00000000000000000000ffff0ae5bb875709964c512f9df90000001e0000000000000000 (36 bytes)

      toString: '< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0ae5bb87:5709964c:512f9df9:1d, node_name=1, branch_uid=0:ffff0ae5bb87:5709964c:512f9df9:1e, subordinatenodename=null, eis_name=unknown eis name >'

   parameter #2:

      type: int

      value: 0

   related:

      in:javax.resource.spi.ResourceAdapter.endpointActivation #1

      in:weblogic.jms.ra.api.DestinationSetListener.add #1