Tom Lambrechts opened SPR-4938 and commented

DefaultMessageListenerContainer stops listening because all listener threads are stopped without being rescheduled. This bug is very difficult to reproduce but has a large impact. The fix is however simple, please handle this with high priority.

This issue occures when the concurrentConsumers=1 and maxConcurrentConsumers > 1. It is caused by a race condition in the AsyncMessageListenerInvoker.run method.

Consider the following logging and code: DEBUG : org.springframework.jms.listener.DefaultMessageListenerContainer > Received message of type [class progress.message.jimpl.TextMessage] from consumer [progress.message.jimpl.QueueReceiver@18ad9a0] of session [] 08/06/18 12:36:15.539, jms://x4.cti.AgentService?id=AgentService-525 DEBUG : org.springframework.jms.listener.DefaultMessageListenerContainer > Raised scheduled invoker count: 2 08/06/18 12:36:15.539, jms://x4.cti.AgentService?id=AgentService-525 DEBUG : org.springframework.jms.listener.DefaultMessageListenerContainer > Lowered scheduled invoker count: 1 08/06/18 12:36:18.554, jms://x4.cti.AgentService?id=AgentService-526 DEBUG : org.springframework.jms.listener.DefaultMessageListenerContainer > Lowered scheduled invoker count: 0 08/06/18 12:36:18.554, jms://x4.cti.AgentService?id=AgentService-527

You can see that two threads lower the invoker count at the same time, cause the scheduled count to be 0 and stopping the container. AsyncMessageListenerInvoker.run() { ...

Line: x
if (!shouldRescheduleInvoker(this.idleTaskExecutionCount) || !rescheduleTaskIfNecessary(this)) { Line: y synchronized (activeInvokerMonitor) { scheduledInvokers.remove(this); if (logger.isDebugEnabled()) { logger.debug("Lowered scheduled invoker count: " + scheduledInvokers.size()); } activeInvokerMonitor.notifyAll();

           clearResources();
    }
}

...

}

If we have two active threads A and B at line x. Because shouldRescheduleInvoker() is synchronized(activeInvokerMonitor) thread A will do the check and stop at line y. Then thread B will do the same check with the same result (becaus thread A did not yet do the remove) and also stop at line Y. Both threads will proceed by removing themself from the scheduled invokers ending up with an emty scheduledInvokers list causing the end of both trheads, instead of the minimum of 1. No new thread is scheduled and the listenercontainer just stops working at all.

The check shouldRescheduleInvoker() and the update of scheduledInvokers.remove() should be in the same syncronized block: AsyncMessageListenerInvoker.run() { ...

synchronized (activeInvokerMonitor) {
    if (!shouldRescheduleInvoker(this.idleTaskExecutionCount) || !rescheduleTaskIfNecessary(this)) {

        scheduledInvokers.remove(this);
        if (logger.isDebugEnabled()) {
            logger.debug("Lowered scheduled invoker count: " + scheduledInvokers.size());
        }
        activeInvokerMonitor.notifyAll();

        clearResources();
    }
    else if (isRunning()) {
        int nonPausedConsumers = getScheduledConsumerCount() - getPausedTaskCount();
        if (nonPausedConsumers < 1) {
            logger.error("All scheduled consumers have been paused, probably due to tasks having been rejected. " +
                    "Check your thread pool configuration! Manual recovery necessary through a start() call.");
        }
        else if (nonPausedConsumers < getConcurrentConsumers()) {
            logger.warn("Number of scheduled consumers has dropped below concurrentConsumers limit, probably " +
                    "due to tasks having been rejected. Check your thread pool configuration! Automatic recovery " +
                    "to be triggered by remaining consumers.");
        }
    }
}
    ...

}

Please also check if the same issue occures in the class DefaultMessageListenerContainer102. R. Tom


Affects: 2.5.4

1 votes, 1 watchers

Comment From: spring-projects-issues

Juergen Hoeller commented

Thanks for raising this! As of Spring 2.5.5, we're avoiding the race condition through a lock on a unified monitor now: lifecycleMonitor and activeInvokerMonitor have been merged. With those two having been separate, a deadlock might have been caused by that suggested sequence of code otherwise (obtaining an encompassing activeInvokerMonitor lock first, then selective lifecycleMonitor locks inbetween).

Juergen

Comment From: parisiprem

I am still facing this issue.... I am using below spring-boot version

org.springframework.boot spring-boot-starter-parent 2.3.3.RELEASE

The below is my threadpool configuration and also set concurrency to 1 for JmsListenerContainer: threadPool: corePoolSize: 2 maxPoolSize: 3 threadNamePrefix: "queue_executor" queueCapacity: 0 awaitTerminationSeconds: 30

@Bean(destroyMethod = "shutdown") public ThreadPoolTaskExecutor mqThreadPoolExecutor() { ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor(); executor.setCorePoolSize (corePoolSize); executor.setThreadNamePrefix (threadNamePrefix); executor.setMaxPoolSize (maxPoolSize); executor.setQueueCapacity (queueCapacity); executor.initialize (); return executor; }

@Bean("queueListenerFactory")
public JmsListenerContainerFactory<?> jmsListenerContainerFactory() {
    DefaultJmsListenerContainerFactory factory = new DefaultJmsListenerContainerFactory();
    factory.setConnectionFactory(mqConnectionFactory);
    factory.setTaskExecutor(mqThreadPoolExecutor());
    factory.setSessionTransacted(true);
    factory.setConcurrency(concurrency);
    factory.setAutoStartup(autoStartUp);
    return factory;
}

Error Details:

2021-03-01 05:51:05.206 ERROR [hjs-notification-listener,9b285f23f20655e3,9b285f23f20655e3,true] 1 --- [queue_executor3] o.s.j.l.DefaultMessageListenerContainer : All scheduled consumers have been paused, probably due to tasks having been rejected. Check your thread pool configuration! Manual recovery necessary through a start() call.