Spring boot shutdown hangs when using ibm.mq.pool.enabled=true or spring.jms.cache.enabled=true

[JanICT]

Using spring-boot 2.6.4 with mq-jms-spring-boot-starter 2.6.4 with Zulu Java 11

I have created a simple test application that listens to one queue.

@Component
public class InputListener implements MessageListener {
    private static final Logger LOG = LoggerFactory.getLogger(InputListener.class);

    @Override
    @JmsListener(destination = "${input.queue}")
    public void onMessage(Message message) {
        try {
            String text = ((TextMessage) message).getText();
            LOG.info(text);
            if (text.contains("error")) {
                //test backout-queue
                throw new IllegalArgumentException("test execption");
            }
        } catch (JMSException e) {
            LOG.error(e.getMessage(), e);
        }
    }
}

with the following JmsConfig

@Configuration
@EnableSniffy
@EnableJms
@EnableTransactionManagement
public class JmsConfig {

    @Bean
    public JmsListenerContainerFactory<DefaultMessageListenerContainer> jmsListenerContainerFactory(ConnectionFactory connectionFactory,
                                                                                                    PlatformTransactionManager transactionManager) {
        DefaultJmsListenerContainerFactory jmsListenerContainerFactory = new DefaultJmsListenerContainerFactory();
        jmsListenerContainerFactory.setConnectionFactory(connectionFactory);
        jmsListenerContainerFactory.setTransactionManager(transactionManager);
        jmsListenerContainerFactory.setBackOff(new ExponentialBackOff(500, 2));

        return jmsListenerContainerFactory;
    }

    @Bean
    public PlatformTransactionManager jmsTransactionManager(ConnectionFactory connectionFactory) {
        JmsTransactionManager jmsTransactionManager = new JmsTransactionManager();
        jmsTransactionManager.setConnectionFactory(connectionFactory);
        return jmsTransactionManager;
    }

}

and with the following application.properties

input.queue=ONT.TEST.LQ
ibm.mq.conn-name=172.x.x.x(1415)
ibm.mq.queue-manager=WINONT
ibm.mq.channel=ASC.CH
ibm.mq.user=
ibm.mq.password=
ibm.mq.applicationName=ASC_ONT
ibm.mq.clientId=AC
ibm.mq.pool.enabled=true
spring.jms.cache.enabled=false
logging.level.ROOT=INFO
logging.level.com.ibm.mq.spring.boot=TRACE
logging.level.org.messaginghub.pooled.jms=TRACE

When I use sniffy (https://sniffy.io/) to close the connection to the queuemanager with a delay of 300000ms (5 min) the application enters some kind of sleep mode. It just waits until the 30000ms is reached. I am also unable to shutdown the application. It just keeps waiting.

The reason I tried this is that we experience the same problems in our production environment when the systems and networks are being updated. The connection to the queue manager is lost and no messages are picked up from the queue manager. The application will not respond anymore and looks like it entered a sleep mode. A graceful restart does not work, we see the same behavior as described above.

It looks like that the JmsPoolConnectionFactory does not listen to a timeout or something but just waits until the connection is closed.

Example logging with ibm.mq.pool.enabled=true and spring.jms.cache.enabled=false At 15:05:12.838 I close the connection. Then I do a shutdown. The shutdown will hang until the timeout of 300000ms is reached, which is on 15:10:12.815, exactly 5 min later.

com.ibm.msg.client.jms.DetailedIllegalStateException: JMSCC0020: This session is closed.
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:na]
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:na]
    at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[na:na]
    at com.ibm.msg.client.commonservices.j2se.NLSServices.createException(NLSServices.java:319) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at com.ibm.msg.client.commonservices.nls.NLSServices.createException(NLSServices.java:226) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at com.ibm.msg.client.jms.internal.JmsErrorUtils.createException(JmsErrorUtils.java:126) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at com.ibm.msg.client.jms.internal.State.checkNotClosed(State.java:142) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at com.ibm.msg.client.jms.internal.JmsSessionImpl.checkNotClosed(JmsSessionImpl.java:3035) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at com.ibm.msg.client.jms.internal.JmsSessionImpl.setMessageListener(JmsSessionImpl.java:2156) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at com.ibm.mq.jms.MQSession.setMessageListener(MQSession.java:1014) ~[com.ibm.mq.allclient-9.2.5.0.jar:9.2.5.0 - p925-L220207]
    at org.messaginghub.pooled.jms.JmsPoolSession.close(JmsPoolSession.java:91) ~[pooled-jms-1.2.3.jar:na]
    at org.springframework.jms.connection.JmsResourceHolder.closeAll(JmsResourceHolder.java:286) ~[spring-jms-5.3.16.jar:5.3.16]
    at org.springframework.jms.connection.JmsTransactionManager.doCleanupAfterCompletion(JmsTransactionManager.java:318) ~[spring-jms-5.3.16.jar:5.3.16]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.cleanupAfterCompletion(AbstractPlatformTransactionManager.java:992) ~[spring-tx-5.3.16.jar:5.3.16]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:790) ~[spring-tx-5.3.16.jar:5.3.16]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) ~[spring-tx-5.3.16.jar:5.3.16]
    at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:253) ~[spring-jms-5.3.16.jar:5.3.16]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1237) ~[spring-jms-5.3.16.jar:5.3.16]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1227) ~[spring-jms-5.3.16.jar:5.3.16]
    at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1120) ~[spring-jms-5.3.16.jar:5.3.16]
    at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]

2022-03-24 15:05:46.576  INFO 4188 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Failed to shut down 1 bean with phase value 2147483647 within timeout of 30000ms: [org.springframework.jms.config.internalJmsListenerEndpointRegistry]
2022-03-24 15:05:46.639 DEBUG 4188 --- [ionShutdownHook] o.m.pooled.jms.JmsPoolConnectionFactory  : Stopping the JmsPoolConnectionFactory, number of connections in cache: 0
2022-03-24 15:05:46.639 TRACE 4188 --- [ionShutdownHook] o.m.pooled.jms.JmsPoolConnectionFactory  : Destroying connection: ConnectionPool[{"ConnectionId":"414D514357494E4F4E5420202020202085213A625680A725","ObjectId":"com.ibm.msg.client.wmq.internal.WMQConnection@6fe7836b","Channel":"ASC.CH","Port":"1415","ConnectionMode":"WMQ_CM_CLIENT","Host":"app1104.qaz.ota/172.x.x.x","ResolvedQueueManager":"WINONT","QueueManager":"WINONT"}]
2022-03-24 15:10:12.815  WARN 4188 --- [ntContainer#0-1] o.s.j.l.DefaultMessageListenerContainer  : Setup of JMS message listener invoker failed for destination 'ONT.TEST.LQ' - trying to recover. Cause: Could not commit JMS transaction; nested exception is com.ibm.msg.client.jms.DetailedJMSException: JMSCMQ0002: The method 'MQCMIT' failed.
An IBM MQ call failed.
Please see the linked exception for more information.

Process finished with exit code 1

[ibmmqmet]

There's not a lot I can do through this repo about the core MQ JMS client behaviour (or indeed the base Spring JMS Listener behaviour). So you might need to open a support case with IBM to discuss client timeouts.

But one question would be how the SVRCONN is configured on the queue manager - what's the SHARECNV value?

• If it's zero, then there's no heartbeating going on between client and server, and broken connections are detected only when there's a real operation waiting to complete and timeouts are typically based on system TCP configuration

• Non-zero values of SHARECNV do setup heartbeats based on the HBINT value.

[JanICT]

The SHARECNV value is 10 and HBINT is 300 (seconds). I found out another department in the company faced the same problem and their advice was to set the property com.ibm.mq.cfg.MQRCVBLKTO. When I looked into com.ibm.mq.jmqi.internal.Configuration I saw more options to configure. I added the following static block to our configuration class:

@Configuration
@EnableJms
@EnableTransactionManagement
public class JmsConfig {

    static {
        System.setProperty("com.ibm.mq.cfg.MQRCVBLKTO", "5");
        System.setProperty("com.ibm.mq.cfg.TCP.Connect_Timeout", "5");
        System.setProperty("com.ibm.mq.cfg.TCP.KeepAlive", "YES");        
    }

    @Bean
    public JmsListenerContainerFactory<DefaultMessageListenerContainer> jmsListenerContainerFactory(ConnectionFactory connectionFactory,
                                                                                                    PlatformTransactionManager transactionManager) {
...........

We hope these settings resolves the issue.