glassfish
  1. glassfish
  2. GLASSFISH-19872

GlassFish does not correctly delist connections which are closed when CDI TransactionScope ends

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 4.0_b80_EE7MS6
    • Fix Version/s: 4.0_b85
    • Component/s: jms
    • Labels:
      None

      Description

      I think I have found a bug in the enlistment/delistment of connections which are created using the new JMSContext injection CDI extension.

      Here's a quick summary:
      1. This concerns the case when an injected JMSContext has transaction scope.
      2. Run a simple CMT business method that uses an injected JMSContext
      3. When the business method completes the transaction is committed and the connection closed. The XAResource is committed and its connection returned to the pool, but something goes wrong with its delistment from the TM.
      4. We then wait for idle-timeout-in-seconds seconds to pass
      5. Then call the business method again. When the transaction is started the TM thinks the XAresource used in the previous call is still enlisted, and so calls start(). However since its connection has been (quite correctly) destroyed by the pool manager, this fails with an exception.

      Here is the session bean:

      @TransactionManagement(TransactionManagementType.CONTAINER) 
      @Stateless
      public class CMBean1 {
      
          @Inject
          @JMSConnectionFactory("jms/ConnectionFactory")
          JMSContext context;
      
          @Resource(mappedName="jms/MY_QUEUE")
          Queue queue;
      
          @TransactionAttribute(TransactionAttributeType.REQUIRED)
          public void method5() {
      	System.out.println("CMBean1.method5() entry");
      	JMSProducer producer = context.createProducer();
      	System.out.println("Sending message [Message 1]");
              producer.send(queue,"Message 1");
      
            	System.out.println("CMBean1.method5() exit");
          }
      }
      

      To reproduce this, deploy the above bean and call its business method. I reproduced this using glassfish-4.0-b80-03_13_2013. I also turned on the following logging:

      com.sun.messaging.jms.ra.DirectXAResource.level=FINE
      javax.jms.Connection.mqjmsra.level=FINE
      

      The first time it is called it appears to work fine. Here's an edited extract from the server log for that operation. We'll refer to this in a moment.

      INFO:   CMBean1.method5() entry
      FINE:   MQJMSRA_DXA1101: DirectXAResource (1635975195) Start   (GlobalTransactionID=[B@3f6f1925, BranchQualifier=[B@16dbecac) 
              (Flags: TMNOFLAGS ), connectionId=5976344228131155712
      FINE:   MQJMSRA_DC1101: connectionId=5976344228131155712:createSession():isTransacted=false:acknowledgeMode=1
      INFO:   Sending message [Message 1]
      INFO:   CMBean1.method5() exit
      FINE:   MQJMSRA_DXA1101: DirectXAResource (1635975195) End     (GlobalTransactionID=[B@3f6f1925, BranchQualifier=[B@16dbecac) 
              (Flags: TMNOFLAGS TMSUCCESS ), connectionId=5976344228131155712
      FINE:   MQJMSRA_DXA1101: DirectXAResource (1635975195) Commit  (GlobalTransactionID=[B@3f6f1925, BranchQualifier=[B@16dbecac)  
              (onePhase=true), connectionId=5976344228131155712
      FINE:   MQJMSRA_DC1101: connectionId=5976344228131155712:close():
      INFO:   Running caseJ 1 completed
      

      Now we wait until the connections in the pool reach their idle-timeout-in-seconds. To make this easy to reproduce I had previously set the idle-timeout-in-seconds to 2 seconds.

      Now we call the bean's business method again. This throws an exception. The (first) exception logged in the server log, together with nearby logging, is:

      INFO:   Running caseJ 2
      FINE:   MQJMSRA_DXA1101: DirectXAResource (1635975195) Start   
      (GlobalTransactionID=[B@65982356, BranchQualifier=[B@67381735) (Flags: TMNOFLAGS ), connectionId=5976344228131155712
      SEVERE:   startTransaction (XA) on JMSService:jmsdirect failed for connectionId:5976344228131155712
      due to Unknown JMSService server error ERROR: com.sun.messaging.jmq.jmsservice.JMSServiceException:
      startTransaction: connection ID not found: 5976344228131155712
      WARNING:   JTS5041: The resource manager is doing work outside a global transaction
      javax.transaction.xa.XAException
      	at com.sun.messaging.jms.ra.DirectXAResource.sendStartToBroker(DirectXAResource.java:836)
      	at com.sun.messaging.jms.ra.DirectXAResource.start(DirectXAResource.java:792)
      	at com.sun.jts.jta.TransactionState.startAssociation(TransactionState.java:341)
      	at com.sun.jts.jta.TransactionImpl.enlistResource(TransactionImpl.java:212)
      	at com.sun.enterprise.transaction.JavaEETransactionImpl.enlistResource(JavaEETransactionImpl.java:660)
      	at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistXAResource(JavaEETransactionManagerSimplified.java:1277)
      	at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistResource(JavaEETransactionManagerSimplified.java:368)
      	at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistComponentResources(JavaEETransactionManagerSimplified.java:1299)
      	at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistComponentResources(JavaEETransactionManagerSimplified.java:487)
      	at com.sun.ejb.containers.EJBContainerTransactionManager.startNewTx(EJBContainerTransactionManager.java:312)
      	at com.sun.ejb.containers.EJBContainerTransactionManager.preInvokeTx(EJBContainerTransactionManager.java:248)
      	at com.sun.ejb.containers.BaseContainer.preInvokeTx(BaseContainer.java:4451)
      	at com.sun.ejb.containers.BaseContainer.preInvoke(BaseContainer.java:1939)
      	at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:210)
      	at com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
      	at com.sun.proxy.$Proxy314.method5(Unknown Source)
      	at beans.__EJB31_Generated__CMBean1__Intf____Bean__.method5(Unknown Source)
      	at servlets.NewServlet.caseBug(NewServlet.java:121)
      	at servlets.NewServlet.processRequest(NewServlet.java:52)
      	at servlets.NewServlet.doGet(NewServlet.java:82)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
      	at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
      	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:318)
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
      	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
      	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
      	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:176)
      	at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:357)
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:260)
      	at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:188)
      	at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:191)
      	at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:168)
      	at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:189)
      	at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
      	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
      	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
      	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
      	at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
      	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
      	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
      	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
      	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:564)
      	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:544)
      	at java.lang.Thread.run(Thread.java:722)
      Caused by: com.sun.messaging.jmq.jmsservice.JMSServiceException: startTransaction: connection ID not found: 5976344228131155712
      	at com.sun.messaging.jmq.jmsserver.service.imq.IMQDirectService.checkConnectionId(IMQDirectService.java:2521)
      	at com.sun.messaging.jmq.jmsserver.service.imq.IMQDirectService.startTransaction(IMQDirectService.java:1535)
      	at com.sun.messaging.jms.ra.DirectXAResource.sendStartToBroker(DirectXAResource.java:811)
      	... 47 more
      

      It is obvious that something has gone wrong with the enlistment/delistment of resources since this that trace shows that the container is calling XAResource.start when the transaction is being started by the container. At this point no bean code has been executed and there should be no resources enlisted (registered) with the transaction manager.

      However the logging shows that when the second transaction is being started, the transaction manager is calling XAResource.start on the same XAResource that was used in the previous transaction, even though the previous transaction has been committed and the connection has been closed (from the perspective of the application).

      Look for where DirectXAResource (1635975195) is logged. The big number {[(1635975195)}} is a hashcode used to identify the XAResource instance.

      More detailed analysis

      Further investigation confirms that when the first transaction was committed by the container, after XAResource.end and XAResource.commit were called, the injected JMSContext scope ends and JMSContext.close is called. This calls Connection.close(), as shown in the above log. Using the debugger I have confirmed that the Connection has broadcast the required javax.resource.spi.ConnectionEvent.CONNECTION_CLOSED event which the container's ConnectionEventListener has received and uses to delist the resource. (Of course calling Connection.close() doesn't physically connection, it simply returns it to the pool).

      Then, when idle-timeout-in-seconds is reached, the connection is physically closed by the container by calling the destroy method on the ManagedConnection.

      Next, we call the bean's business method a second time. The CMT transaction is started by the container, which causes the TM to call start on all enlisted resources. At this point there shouldn't be any resources to enlist. However the TM somehow still has a reference to the XAResource that was used in the previous transaction and calls start. Since the underlying connection has been closed, this throws an exception. The error that is thrown is

      SEVERE:   startTransaction (XA) on JMSService:jmsdirect failed for connectionId:5976344228131155712 
      due to Unknown JMSService server error ERROR: com.sun.messaging.jmq.jmsservice.JMSServiceException: 
      startTransaction: connection ID not found: 5976344228131155712
      

      which means that start is called even though the connection is closed.

      Steps to reproduce
      I have created a NetBeans project which allows this bug to be demonstrated easily. It can be downloaded from http://java.net/projects/jms-spec/downloads/download/GlassFishIssue2.zip . Simply unzip this file, open it in NetBeans and deploy and run it. Wait for the browser to open, click on the link, and wait for the error. Then look at the server log.

      If you don't to use NetBeans, the key files are:

      • src\java\beans\CMBean1.java - the session bean
      • src\java\servlets
        NewServlet
        - a simple servlet which calls the bean once, waits 3 seconds, and calls it again
      • setup\glassfish-resources.xml - defines the connection factory resource required by the application and sets its idle-timeout-in-seconds to 2.

        Activity

        Hide
        Tom Mueller added a comment -

        Approved for 4.0

        Show
        Tom Mueller added a comment - Approved for 4.0
        Hide
        David Zhao added a comment -

        Committed __PM workaround by revision 61190.

        Show
        David Zhao added a comment - Committed __PM workaround by revision 61190.
        Hide
        michael.y.chen added a comment -

        Is this fixed with revision 61190?

        Show
        michael.y.chen added a comment - Is this fixed with revision 61190?
        Hide
        marina vatkina added a comment -

        Partially.

        Show
        marina vatkina added a comment - Partially.
        Hide
        marina vatkina added a comment -

        Enable workaround to use __pm resource upon request: either via "-Dorg.glassfish.jms.skip-resource-registration-in-transaction=true" or choosing an __pm resource for the JMSContext.

        See rev 61418 of trunk/main/appserver/jms/gf-jms-injection/src/main/java/org/glassfish/jms/injection/InjectableJMSContext.java

        Show
        marina vatkina added a comment - Enable workaround to use __pm resource upon request: either via "-Dorg.glassfish.jms.skip-resource-registration-in-transaction=true" or choosing an __pm resource for the JMSContext. See rev 61418 of trunk/main/appserver/jms/gf-jms-injection/src/main/java/org/glassfish/jms/injection/InjectableJMSContext.java

          People

          • Assignee:
            David Zhao
            Reporter:
            Nigel Deakin
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: