[jboss-user] [IronJacamar] - JCA Spec violation using resource-adapter in JBoss 7?

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799730#799730

--------------------------------------------------------------
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
      i*n: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
            [...]
            i*n:xaResourceWrapper2.start(xid5,2097152) threw* #8 @1361560703786..1361560703871 [TMJOIN]
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799730#799730]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799747#799747

--------------------------------------------------------------
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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799747#799747]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799899#799899

--------------------------------------------------------------
Retest your scenario with a nightly snapshot
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799899#799899]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799934#799934

--------------------------------------------------------------
If I download the latest snapshop
https://hudson.jboss.org/hudson/view/JBoss%20AS/job/JBoss-AS-7.0.x/ 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 https://community.jboss.org/thread/196508
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799934#799934]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799935#799935

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

Reply to this message by going to Community
[https://community.jboss.org/message/799935#799935]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799957#799957

--------------------------------------------------------------
Also include TRACE log for org.jboss.jca
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799957#799957]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799961#799961

--------------------------------------------------------------
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 http://docs.jboss.org/ironjacamar/userguide/1.1/en-US/html/tools.html#tools_rarinfo
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799961#799961]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/799975#799975

--------------------------------------------------------------
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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/799975#799975]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800115#800115

--------------------------------------------------------------
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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800115#800115]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800132#800132

--------------------------------------------------------------
I used these instructions to enable logging when I ran the test yesterday:
https://community.jboss.org/docs/DOC-16648 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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800132#800132]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800150#800150

--------------------------------------------------------------
Attached is the MDB source which contains the activation-spec properties
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800150#800150]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800151#800151

--------------------------------------------------------------
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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800151#800151]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800169#800169

--------------------------------------------------------------
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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800169#800169]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jeff Steidl]

Jeff Steidl [https://community.jboss.org/people/jsteidl] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800173#800173

--------------------------------------------------------------
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.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800173#800173]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Tom Jenkinson]

Tom Jenkinson [https://community.jboss.org/people/tomjenkinson] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800298#800298

--------------------------------------------------------------
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
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800298#800298]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jsteidl]

jsteidl [https://community.jboss.org/people/jsteidl] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800406#800406

--------------------------------------------------------------
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: '***@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
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800406#800406]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jsteidl]

jsteidl [https://community.jboss.org/people/jsteidl] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800408#800408

--------------------------------------------------------------

Post by Tom Jenkinson
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).

Note that the comments like "[TMNOFLAGS]" and "[TMJOIN]" were added by hand to the log summary you were looking at, whereas the log summary in post #11 is "raw" and contains no such hand-edits.

In the log summary (tempm.txt) from post #11, the TMJOIN operations are still there (2097152 is TMJOIN) -- the first one is:

in:xaResourceWrapper2.start(xid3,2097152) #6 @1362075193148..1362075193161
   out:XAResource.start(xid3,2097152) #6 @1362075193152..1362075193157
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800408#800408]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/800860#800860

--------------------------------------------------------------
for the JBoss folks - is there anything more I can do with regards to adding logging/tracing that can help with understanding this issue?   (I would need specific instructions on what to enable or what configuration to change).    

Is there any question regarding the resource-adapter implementation we are developing that jsteidl could answer?
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/800860#800860]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/801966#801966

--------------------------------------------------------------
Could you add TRACE logging for com.arjuna and org.jboss.as.ejb3 too ?
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/801966#801966]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802214#802214

--------------------------------------------------------------
new log (logs_0312.zip) attached along with the standalone.xml, logging.properties, the stdout/err from the JBoss server and the MDB's source file which has the @annotated  activation config

This will be a different MDB than before, same basic function, just simplified so I can work outside our test framework.
1) RA deployed and configured in JBoss (as before)
2) RA-backed MDB deployed to JBoss.  MDB is XA enabled, it receives a message then sends an outbound response (Container Managed Txn).
3) A WebLogic client enqueues 3 messages to the inbound queue (this is done on the WebLogic side, no RA or JBoss).
4) MDB should consume the 3 messages and send a response message for each but fails.

You can jump to the failure in the server.log by searcing it for "ERROR".
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802214#802214]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802393#802393

--------------------------------------------------------------
I'm not seeing the TRACE from com.arjuna

Identified one issue (AS7-6725), so thanks for that one :)
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802393#802393]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802395#802395

--------------------------------------------------------------
If you are seeing the problem by just sending one message then just include that log - sending more messages only clutters it
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802395#802395]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802397#802397

--------------------------------------------------------------
If possible include the following Byteman script in your run:

RULE Transaction.enlist
INTERFACE javax.transaction.Transaction
METHOD enlistResource
IF TRUE
DO traceStack("--------------------------->BM-Transaction.enlistResource: " + $1,100);
ENDRULE

RULE Transaction.delist
INTERFACE javax.transaction.Transaction
METHOD delistResource
IF TRUE
DO traceStack("--------------------------->BM-Transaction.delistResource: " + $1 + ", flag: " + $2,100);
ENDRULE


Thanks.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802397#802397]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802469#802469

--------------------------------------------------------------
New log file attached.  

This has com.arjuna logging set to TRACE.
This has the Byteman script you provided in a previous post and I see the "BM" messages in the log
This does not have our RA tracing enabled (which might make it easier for you to read).

I simplified the test case to sending 2 messages.   The first will work but the second fails as it tries to reuse the outbound connection once again (the transaction didn't delist the first time). 
I also simplified the MDB in that it no longer tries to redeliver messages.   Before it was using a default where it makes 5 attempts to deliver the same message to the MDB (a config parameter that protects against poison messages).   This time it will try to deliver it once then discard it if that delivery fails   This should help unclutter the logs a bit more.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802469#802469]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802771#802771

--------------------------------------------------------------
We have done some updates, so can rerun using the latest AS7 snapshot - and use the ij-core-impl from here: https://repository.jboss.org/nexus/content/repositories/snapshots/org/jboss/ironjacamar/ironjacamar-core-impl/1.0.16-SNAPSHOT/ https://repository.jboss.org/nexus/content/repositories/snapshots/org/jboss/ironjacamar/ironjacamar-core-impl/1.0.16-SNAPSHOT/ - just override the 1.0.15 version.

Thanks.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802771#802771]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802783#802783

--------------------------------------------------------------
Sharing my steps, let me know if I need to do something differently:

I'm already using the last successful nightly AS8 (build version 1498) from https://ci.jboss.org/jenkins/job/JBoss-AS-7.x-latest/ https://ci.jboss.org/jenkins/job/JBoss-AS-7.x-latest/  so I didn't change.

I go to jboss-as-8.0.0.Alpha1-SNAPSHOT/modules/system/layers/base/org/jboss/ironjacamar/impl/main
and move ironjacamar-core-impl-1.0.15.Final.jar* to a temp directory.

I copy in the new version,  ironjacamar-core-impl-1.0.16-20130314.184732-1.jar
and I update module.xml to replace the reference of  +ironjacamar-core-impl-1.0.15.Final.jar+ to +ironjacamar-core-impl-1.0.16-20130314.184732-1.jar+

Attached is the server.log from my test run.   This run did have the previous byteman script enabled.   Searching the log for ERROR, I still see the " Attempt to start a transaction while in an active (global or local) transaction" issue but I also see a new error message that precedes it,

+13:00:56,127 ERROR [org.jboss.msc.service] (MSC service thread 1-4) MSC000002: Invocation of listener "org.jboss.as.connector.util.RaServicesFactory$***@3745dc3b" failed: java.lang.IllegalStateException: JBAS014666: Duplicate resource resource-adapters+
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802783#802783]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802789#802789

--------------------------------------------------------------
(follow up from my previous message, #25 in this topic)

Tried a couple of more runs and do not see the +Duplicate resource resource-adapters+ error.   Just the "Attempt to start a transaction..." as before.    New server.logs attached, one with and one without our RA trace enabled.+
+
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802789#802789]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Tom Jenkinson]

Tom Jenkinson [https://community.jboss.org/people/tomjenkinson] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/803241#803241

--------------------------------------------------------------
I am not seeing delistResource happen
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/803241#803241]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/803321#803321

--------------------------------------------------------------
Please, do another run with the attached jar
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/803321#803321]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/803348#803348

--------------------------------------------------------------
Using the ironjacamar-core-impl.jar provided in messge #28.   I no longer see the issue ("Attempt to start a transaction while in an active (global or local) transaction").    Looking at the log I don't see an ERROR message and the MDB is processing inbound/outbound messages as required by the test case.

Attached is the log from my run with the byteman debugging code active, you will see the byteman "--------------------------->BM-Transaction.delistResource"... messages in this run that we didn't see before.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/803348#803348]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/803585#803585

--------------------------------------------------------------
Thanks for taking the time to test this patch, and providing us with your logs.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/803585#803585]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jleinawe]

jleinawe [https://community.jboss.org/people/jleinawe] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/804402#804402

--------------------------------------------------------------
Hi Jesper,

Some questions/observations:
1. Do you know when the patch you provided, https://community.jboss.org/servlet/JiveServlet/download/2098-221780-803321-80503/ironjacamar-core-impl.jar ironjacamar-core-impl.jar, will be available in the nightly snapshots?  

2. We haven't tested a lot with JBoss releases prior to 7.1.1 but may in the near future (say JBoss 5).   Do you know if this issue exists in prior releases and if so, are patches such has this backported?

3. In one of our test runs, we saw a NPE in the JBoss code when shutting down the JBoss server.   See attached server.log and search for "NullPointerException"

4. An observation from one of our developers from looking at our RA tracing.    It appears JBoss is still violating the JCA spec by not immediately delisting in response to ConnectionEventListener.connectionClosed.  (It's deferring it until just before the commit.).

For #4, our RA is compatable with JBoss so this isn't an open issue for us.  Just sharing since some day in the future more validation checks may be added or some other vendor's RA might run into this.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/804402#804402]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[Jesper Pedersen]

Jesper Pedersen [https://community.jboss.org/people/jesper.pedersen] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/804591#804591

--------------------------------------------------------------
1) JBJCA-1009 will be in IronJacamar 1.1.0.Beta5 which is scheduled for inclusion in AS8

2) Patches are available as part of your subscription. Latest EAP is available here http://www.jboss.org/jbossas/downloads http://www.jboss.org/jbossas/downloads

3) I have notified the EJB3 lead about this

4) delistResource will happen dependning on transaction usage, further testing will be done as part of JBJCA-1009

HTH
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/804591#804591]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jaikiran pai]

jaikiran pai [https://community.jboss.org/people/jaikiran] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/804610#804610

--------------------------------------------------------------

Post by jleinawe
3. In one of our test runs, we saw a NPE in the JBoss code when shutting down the JBoss server.   See attached server.log and search for "NullPointerException"

That's a bug. Can you please file a JIRA for this under the EJB component? I can do it myself but since you are the one who found this out, you might want to have it opened in your name.
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/804610#804610]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]

[jsteidl]

jsteidl [https://community.jboss.org/people/jsteidl] created the discussion

"Re: JCA Spec violation using resource-adapter in JBoss 7?"

To view the discussion, visit: https://community.jboss.org/message/802339#802339

--------------------------------------------------------------
Attached are the log summary (tempm.txt) and intermediate file (tempm.int) derived from the full logs included with post #18.

[Due to the test changes described by jleinawe, the attached log summary is a bit different than the one described in post #12.  It is now "xaResourceWrapper1" rather than "xaResourceWrapper2" that is being repeatedly 'XAResource.start'ed and never 'XAResource.end'ed.  And the first xid where the transaction is committed without first ending the association is "xid1".]
--------------------------------------------------------------

Reply to this message by going to Community
[https://community.jboss.org/message/802339#802339]

Start a new discussion in IronJacamar at Community
[https://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2098]