Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging on DEBUG breaks DefaultMessageListenerContainer on WebSphere MQ [SWS-848] #922

Closed
gregturn opened this issue Sep 11, 2013 · 1 comment
Assignees
Milestone

Comments

@gregturn
Copy link
Member

@gregturn gregturn commented Sep 11, 2013

Jan-Kees van Andel opened SWS-848 and commented

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 JMS$LQG00386-LQG00386$JMSManagedConnection@3. 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 JMS$LQG00386-LQG00386$JMSManagedConnection@4.
[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 JMS$LQG00386-LQG00386$JMSManagedConnection@4. 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


Affects: 2.1.3

Referenced from: commits 3571d6d

@gregturn
Copy link
Member Author

@gregturn gregturn commented Jan 27, 2014

Arjen Poutsma commented

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
2 participants