1 2 3 Previous Next 38 Replies Latest reply on Sep 25, 2014 12:13 PM by Scott Marlow

    JCA Spec violation using resource-adapter in JBoss 7?

    jleinawe Newbie

      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]

        • 1. Re: JCA Spec violation using resource-adapter in JBoss 7?
          jleinawe Newbie

          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.

          • 2. Re: JCA Spec violation using resource-adapter in JBoss 7?
            Jesper Pedersen Master

            Retest your scenario with a nightly snapshot

            • 3. Re: JCA Spec violation using resource-adapter in JBoss 7?
              jleinawe Newbie

              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

              • 5. Re: JCA Spec violation using resource-adapter in JBoss 7?
                Jesper Pedersen Master

                Also include TRACE log for org.jboss.jca

                • 6. Re: JCA Spec violation using resource-adapter in JBoss 7?
                  Jesper Pedersen Master

                  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

                  • 7. Re: JCA Spec violation using resource-adapter in JBoss 7?
                    jleinawe Newbie

                    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.

                    • 8. Re: JCA Spec violation using resource-adapter in JBoss 7?
                      Jesper Pedersen Master

                      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.

                      • 9. Re: JCA Spec violation using resource-adapter in JBoss 7?
                        jleinawe Newbie

                        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.

                        • 10. Re: JCA Spec violation using resource-adapter in JBoss 7?
                          jleinawe Newbie

                          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.

                          • 11. Re: JCA Spec violation using resource-adapter in JBoss 7?
                            jleinawe Newbie

                            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.

                            • 12. Re: JCA Spec violation using resource-adapter in JBoss 7?
                              jsteidl Newbie

                              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.

                              • 13. Re: JCA Spec violation using resource-adapter in JBoss 7?
                                Tom Jenkinson Master

                                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

                                • 14. Re: JCA Spec violation using resource-adapter in JBoss 7?
                                  jsteidl Newbie

                                  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

                                  1 2 3 Previous Next