[SWS-848] Logging on DEBUG breaks DefaultMessageListenerContainer on WebSphere MQ Created: 11/Sep/13  Updated: 20/Mar/14  Resolved: 27/Jan/14

Status: Resolved
Project: Spring Web Services
Component/s: Core
Affects Version/s: 2.1.3
Fix Version/s: 2.2.RC1

Type: Bug Priority: Blocker
Reporter: Jan-Kees van Andel Assignee: Arjen Poutsma
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
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



 Comments   
Comment by Arjen Poutsma [ 27/Jan/14 ]

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

Generated at Sun Dec 17 08:04:24 UTC 2017 using JIRA 6.4.14#64029-sha1:ae256fe0fbb912241490ff1cecfb323ea0905ca5.