Uploaded image for project: 'Spring Web Services'
  1. Spring Web Services
  2. SWS-848

Logging on DEBUG breaks DefaultMessageListenerContainer on WebSphere MQ

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Blocker
    • Resolution: Fixed
    • Affects Version/s: 2.1.3
    • Fix Version/s: 2.2.RC1
    • Component/s: Core
    • Labels:
      None
    • Environment:
      WebSphere 7 FP 27on Red Hat Linux, IBM J9VM - 20121024_126067

      Description

      When I set the logging in the package org.springframework.ws.transport.support (or org.springframework FWIW), I get a strange exception. See below:

      [9/5/13 20:18:30:610 CEST] 00000056 ConnectionEve A   J2CA0056I: The Connection Manager received a fatal connection error from the Resource Adapter for resource [email protected] The exception is: com.ibm.msg.client.jms.DetailedIllegalStateException: JMSCC0032: This message consumer is closed. An application called a method that must not be used after the message consumer is closed. Ensure that the message consumer is not closed before calling the method.
      [9/5/13 20:18:30:640 CEST] 00000051 MCWrapper     E   J2CA0081E: Method cleanup failed while trying to execute method cleanup on ManagedConnection <null> from resource jms/LQG00386. Caught exception: javax.resource.spi.ResourceAdapterInternalException: Failed to stop connection on cleanup
              at com.ibm.ejs.jms.JMSCMUtils.mapToResourceException(JMSCMUtils.java:176)
              at com.ibm.ejs.jms.JMSManagedConnection.cleanup(JMSManagedConnection.java:1122)
              at com.ibm.ejs.j2c.MCWrapper.cleanup(MCWrapper.java:1549)
              at com.ibm.ejs.j2c.FreePool.cleanupAndDestroyMCWrapper(FreePool.java:732)
              at com.ibm.ejs.j2c.FreePool.returnToFreePool(FreePool.java:502)
              at com.ibm.ejs.j2c.PoolManager.release(PoolManager.java:1915)
              at com.ibm.ejs.j2c.MCWrapper.releaseToPoolManager(MCWrapper.java:2404)
              at com.ibm.ejs.j2c.MCWrapper.connectionErrorOccurred(MCWrapper.java:2543)
              at com.ibm.ejs.j2c.ConnectionEventListener.connectionErrorOccurred(ConnectionEventListener.java:511)
              at com.ibm.ejs.jms.JMSManagedConnection.connectionErrorOccurred(JMSManagedConnection.java:1493)
              at com.ibm.ejs.jms.JMSConnectionHandle.markManagedConnectionAsStale(JMSConnectionHandle.java:922)
              at com.ibm.ejs.jms.JMSSessionHandle.markManagedObjectsAsStale(JMSSessionHandle.java:1540)
              at com.ibm.ejs.jms.JMSMessageConsumerHandle.markManagedObjectsAsStale(JMSMessageConsumerHandle.java:915)
              at com.ibm.ejs.jms.JMSMessageConsumerHandle.receive(JMSMessageConsumerHandle.java:570)
              at com.ibm.ejs.jms.JMSMessageConsumerHandle.receive(JMSMessageConsumerHandle.java:500)
              at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:429)
              at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:310)
              at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
              at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
              at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
              at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
              at java.lang.Thread.run(Thread.java:738)
      Caused by: com.ibm.msg.client.jms.DetailedIllegalStateException: JMSCC0008: This connection is closed. An application called a method that must not be used after the connection is closed. Ensure that the connection is not closed before calling the method.
              at sun.reflect.GeneratedConstructorAccessor319.newInstance(Unknown Source)
              at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39)
              at java.lang.reflect.Constructor.newInstance(Constructor.java:527)
              at com.ibm.msg.client.commonservices.j2se.NLSServices.createException(NLSServices.java:411)
              at com.ibm.msg.client.commonservices.nls.NLSServices.createException(NLSServices.java:390)
              at com.ibm.msg.client.jms.internal.JmsErrorUtils.createException(JmsErrorUtils.java:104)
              at com.ibm.msg.client.jms.internal.State.checkNotClosed(State.java:145)
              at com.ibm.msg.client.jms.internal.JmsConnectionImpl.getExceptionListener(JmsConnectionImpl.java:590)
              at com.ibm.mq.jms.MQConnection.getExceptionListener(MQConnection.java:373)
              at com.ibm.ejs.jms.JMSManagedConnection.cleanup(JMSManagedConnection.java:1100)
              ... 20 more
       
      [9/5/13 20:18:30:643 CEST] 00000051 MCWrapper     W   J2CA0088W: The ManagedConnection that is being destroyed from resource No longer available is in an invalid state STATE_INACTIVE. Processing will continue.
      [9/5/13 20:21:31:349 CEST] 00000057 FreePool      E   J2CA0045E: Connection not available while invoking method createOrWaitForConnection for resource [email protected]
      [9/5/13 20:21:36:371 CEST] 00000058 ConnectionEve W   J2CA0206W: A connection error occurred.  To help determine the problem, enable the Diagnose Connection Usage option on the Connection Factory or Data Source. This is the multithreaded access detection option.
      [9/5/13 20:21:36:372 CEST] 00000058 ConnectionEve A   J2CA0056I: The Connection Manager received a fatal connection error from the Resource Adapter for resource [email protected] The exception is: com.ibm.msg.client.jms.DetailedIllegalStateException: JMSCC0032: This message consumer is closed. An application called a method that must not be used after the message consumer is closed. Ensure that the message consumer is not closed before calling the method.

      When digging down into the issue, I found that the root cause was in the org.springframework.ws.transport.support.WebServiceMessageReceiverObjectSupport#logUri() method. This method calls a method: org.springframework.ws.transport.jms.JmsReceiverConnection#getUri() which crashes because requestMessage.getJMSDestination() resolves to null.

      However, the exception is not caught, so it bubbles up. And since it's outside of the try block, the rest of the code is not executed and the connection is not freed. In my local environment I fixed the issue by adding a catch clause to the logURI method, like this:

          private void logUri(WebServiceConnection connection) {
              if (logger.isDebugEnabled()) {
                  try {
                      logger.debug("Accepting incoming [" + connection + "] at [" + connection.getUri() + "]");
                  }
                  catch (URISyntaxException e) {
                      // ignore
                  }
                  catch (IllegalArgumentException e) {
                      if (logger.isWarnEnabled()) {
                          logger.warn("Error while trying to log WebServiceConnection URI " + e.getMessage());
                      } else {
                          logger.debug("Error while trying to log WebServiceConnection URI", e);
                      }
                  }
              }
          }

      This way, the logging statement doesn't have (a visible at least) side effect.

      Expanding the try block in handleConnection was also something I tried, but that had as a result that the connection is properly closed, but the rest of the code (my service endpoint) was still not executed. So that solution also had side effects

        Activity

        jkva Jan-Kees van Andel created issue -
        arjen.poutsma Arjen Poutsma made changes -
        Field Original Value New Value
        Assignee Arjen Poutsma [ arjen.poutsma ]
        arjen.poutsma Arjen Poutsma made changes -
        Fix Version/s 2.1.5 [ 14349 ]
        Hide
        arjen.poutsma Arjen Poutsma added a comment -

        Fixed. When the destination is null, the URI is null as well.

        Show
        arjen.poutsma Arjen Poutsma added a comment - Fixed. When the destination is null, the URI is null as well.
        arjen.poutsma Arjen Poutsma made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        arjen.poutsma Arjen Poutsma made changes -
        Fix Version/s 2.2 [ 12850 ]
        Fix Version/s 2.1.5 [ 14349 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        138d 3h 5m 1 Arjen Poutsma 27/Jan/14 3:13 AM

          People

          • Assignee:
            arjen.poutsma Arjen Poutsma
            Reporter:
            jkva Jan-Kees van Andel
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: