Regression: ApplicationContext.stop() Hangs for 30s When Inactive Container(s) Present

[lukaseckert]

In what version(s) of Spring AMQP are you seeing this issue?
The issue appeared after updating Spring Boot from 2.7.13 to 2.7.14, which bumps spring-amq to 2.4.14.
The problem does not show up anymore when reverting (only) the spring-amqp version to 2.4.13.

Describe the bug

When the Spring Boot application shuts down (e.g. via stop button in IntelliJ), it will not immediately shutdown anymore. Instead, there is a delay of 30sec, followed by a Spring error message:
...ecycleProcessor$LifecycleGroup | Failed to shut down 1 bean with phase value 2147483647 within timeout of 30000ms: [org.springframework.amqp.rabbit.config.internalRabbitListenerEndpointRegistry] [stop(), DefaultLifecycleProcessor.java:384]

Expected behavior

Upon application shutdown, all listener containers are either already stopped or will be stopped within a few seconds, so there is no bean shutdown timeout error after 30 sec.

To Reproduce

I guess this could be related to the changes to the shutdown behaviour in 95631d8

I was not able to create a small-scale sample yet, but I've debugged the related Spring code and think I might have found the the reason and a possible solution for the delayed shutdown. See the "sample" below :) However I don't understand why the code worked in earlier versions of spring-amqp.

Analysis

To analyze what is happening, I defined several logging debugger breakpoints in spring-amqp and then triggered an application exit.
These breakpoints log the current method and the queues of the listener container. Here is what`s happening:

shutdown() called in AbstractMessageListenerContainer:1366 with queues: [reporting-service.Replication-4ulJUMIkRnG2K-fG4aDp1g]
  -> shutdownAndWaitOrCallback called in SimpleMessageListenerContainer with queues: [reporting-service.Replication-4ulJUMIkRnG2K-fG4aDp1g]
    -> stopping consumer: [reporting-service.Replication-4ulJUMIkRnG2K-fG4aDp1g]
    -> stopped consumer: [reporting-service.Replication-4ulJUMIkRnG2K-fG4aDp1g]
    -> callback executed? true
shutdown() called in AbstractMessageListenerContainer:1366 with queues: [reporting-service.LiveSync]
  -> shutdownAndWaitOrCallback called in SimpleMessageListenerContainer with queues: [reporting-service.LiveSync]
    -> stopping consumer: [reporting-service.LiveSync]
    -> stopped consumer: [reporting-service.LiveSync]
    -> callback executed? true
shutdown() called in AbstractMessageListenerContainer:1366 with queues: [reporting-service.SnapshotSync-4ulJUMIkRnG2K-fG4aDp1g]
  -> returning because if(!isActive), but not executed the callback although one is defined!

My conclusion:

• there are 3 SimpleMessageListenerContainer beans in the application context (2 active, 1 inactive)
• on app shutdown, Spring`s DefaultLifecycleProcessor creates a countdown latch of 3 and calls shutdown(Runnable callback) on all 3 container beans. The callback function will decrease the latch when executed.
• only the currently active listener containers do execute the callback
• an inactive listener container does not execute the (non-null) callback method before the return in AbstractMessageListenerContainer.java:1370. However Spring seems to rely on the callback being executed by shutdown() in any state.
• therefore the countdown latch is never decreased to 0, so the timeout exception is raised after 30sec

Just for fun, I made the breakpoint execute the callback function in AbstractMessageListenerContainer.java:1370.
That fixes the problem and the application shuts down immediately.

[lukaseckert]

Some notes on the setup:

That "reporting-service.SnapshotSync" queue is started and stopped later by the application. It is running only during a certain phase of the application lifetime. This is done by auto-wiring the RabbitListenerEndpointRegistry and calling start()/stop() as in the following snippet:

endpointRegistry.getListenerContainer(RabbitConfig.LISTENER_ID_SNAPSHOT_SYNC).start()
// ...
endpointRegistry.getListenerContainer(RabbitConfig.LISTENER_ID_SNAPSHOT_SYNC).stop()

The problematic queue is an non-auto-startup, exclusive queue as defined by

@RabbitListener(
    queues = "#{snapshotSyncQueue.name}",
    autoStartup = "false",
    id = RabbitConfig.LISTENER_ID_SNAPSHOT_SYNC,
    exclusive = true
)
public class SnapshotSyncRabbitController {
// ...

[artembilan]

The fix you are mentioning has not been released yet: #2492.

Probably this b98847c or this 95631d8.

It would be great if you can test your project against 2.4.15-SNAPSHOT. It is going to be released in a couple weeks: https://calendar.spring.io/

[lukaseckert]

Hi @artembilan ,
thanks for your response, but unfortunately using the 2.4.15-SNAPSHOT versions of spring-amqp and spring-rabbit does not fix the issue. I think it is not related to the forceStop() flag, which I already tried to set on my own via a ContainerCustomizer bean.
The error message stays the same:
Failed to shut down 1 bean with phase value 2147483647 within timeout of 30000ms: [org.springframework.amqp.rabbit.config.internalRabbitListenerEndpointRegistry] [stop(), DefaultLifecycleProcessor.java:384]

I double-checked the classpath of the running app to ensure it is using the snapshot version:

.gradle\caches\modules-2\files-2.1\org.springframework.amqp\spring-rabbit\2.4.15-SNAPSHOT\b3a16ac4af72a8cc4aca73236df4d90cde140442\spring-rabbit-2.4.15-SNAPSHOT.jar
.gradle\caches\modules-2\files-2.1\org.springframework.amqp\spring-amqp\2.4.15-SNAPSHOT\389a7a17bb5c73e1ed4cc09d11ac427a6f22845\spring-amqp-2.4.15-SNAPSHOT.jar

I know it is a long text 😉 But I guess the problem is the same as in my original issue conclusion:
In AbstractMessageListenerContainer.java:1370 the method can return without executing a given (non-nulll) shutdown callback, therefore missing to decrease a countdown latch in the DefaultLifecycleProcessor.

[lukaseckert]

This is a minimal sample app that reproduces the issue with 2.4.15-SNAPSHOT. Just start and then stop the application to see the issue:

DemoApplication.java

@SpringBootApplication
@EnableRabbit
public class DemoApplication {

    @Bean
    public Queue queue1() {
        return new Queue("reporting-service.queue1", false);
    }

    @Bean
    public Queue queue2() {
        return new Queue("reporting-service.queue2", false);
    }

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }
}

DemoRabbitController.java

@Controller
public class DemoRabbitController {

    @RabbitListener(queues = "#{queue1.name}")
    public void receive1(String message) {
        System.out.println(message);
    }

    @RabbitListener(queues = "#{queue2.name}", autoStartup = "false")
    public void receive2(String message) {
        System.out.println(message);
    }

}

Result
The graceful shutdown hangs for 30sec and then prints the Failed to shut down 1 bean error before the process exits:

...
2023-08-09 10:21:03.267  INFO 6860 --- [           main] o.s.amqp.rabbit.core.RabbitAdmin         : Auto-declaring a non-durable, auto-delete, or exclusive Queue (reporting-service.queue1) durable:false, auto-delete:false, exclusive:false. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
2023-08-09 10:21:03.267  INFO 6860 --- [           main] o.s.amqp.rabbit.core.RabbitAdmin         : Auto-declaring a non-durable, auto-delete, or exclusive Queue (reporting-service.queue2) durable:false, auto-delete:false, exclusive:false. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
2023-08-09 10:21:03.302  INFO 6860 --- [           main] c.example.shutdownhang.DemoApplication   : Started DemoApplication in 1.67 seconds (JVM running for 2.138)
// --------  triggered application stop via InteliJ --------
2023-08-09 10:21:13.318  INFO 6860 --- [ntContainer#0-2] o.s.a.r.l.SimpleMessageListenerContainer : Waiting for workers to finish.
2023-08-09 10:21:14.319  INFO 6860 --- [ntContainer#0-2] o.s.a.r.l.SimpleMessageListenerContainer : Successfully waited for workers to finish.
2023-08-09 10:21:43.320  INFO 6860 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Failed to shut down 1 bean with phase value 2147483647 within timeout of 30000ms: [org.springframework.amqp.rabbit.config.internalRabbitListenerEndpointRegistry]

Process finished with exit code 130

[garyrussell]

Confirmed regression; probably caused by 1fdfe65