MessageDeliveryException on shutdown with open WebSocket connections

[daspilker]

After updating an application from Spring Boot 3.1.x to 3.2.2, an exception is logged when shutting down the application while a websocket client is connected. The exception is not logged when using 3.1.x.

This can be reproduced with the Stomp Messaging guide:

• Checkout https://github.com/spring-guides/gs-messaging-stomp-websocket/tree/main/complete
• Start the application
• Open http://localhost:8080 and click "Connect"
• Shut down the application

2024-01-31T20:04:42.693+01:00  WARN 15392 --- [ionShutdownHook] w.s.h.ExceptionWebSocketHandlerDecorator : Unhandled exception after connection closed for ExceptionWebSocketHandlerDecorator [delegate=LoggingWebSocketHandlerDecorator [delegate=SubProtocolWebSocketHandler[StompSubProtocolHandler[v10.stomp, v11.stomp, v12.stomp]]]]

org.springframework.messaging.MessageDeliveryException: Failed to send message to ExecutorSubscribableChannel[clientInboundChannel]
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:149) ~[spring-messaging-6.1.3.jar:6.1.3]
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:125) ~[spring-messaging-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.messaging.StompSubProtocolHandler.afterSessionEnded(StompSubProtocolHandler.java:685) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.clearSession(SubProtocolWebSocketHandler.java:531) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.afterConnectionClosed(SubProtocolWebSocketHandler.java:400) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.handler.WebSocketHandlerDecorator.afterConnectionClosed(WebSocketHandlerDecorator.java:85) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.afterConnectionClosed(LoggingWebSocketHandlerDecorator.java:72) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.afterConnectionClosed(ExceptionWebSocketHandlerDecorator.java:78) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.onClose(StandardWebSocketHandlerAdapter.java:144) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.apache.tomcat.websocket.WsSession.fireEndpointOnClose(WsSession.java:662) ~[tomcat-embed-websocket-10.1.18.jar:10.1.18]
    at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:588) ~[tomcat-embed-websocket-10.1.18.jar:10.1.18]
    at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:554) ~[tomcat-embed-websocket-10.1.18.jar:10.1.18]
    at org.apache.tomcat.websocket.WsSession.close(WsSession.java:542) ~[tomcat-embed-websocket-10.1.18.jar:10.1.18]
    at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.closeInternal(StandardWebSocketSession.java:235) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.adapter.AbstractWebSocketSession.close(AbstractWebSocketSession.java:144) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.handler.WebSocketSessionDecorator.close(WebSocketSessionDecorator.java:160) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.close(ConcurrentWebSocketSessionDecorator.java:271) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.stop(SubProtocolWebSocketHandler.java:289) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.stop(SubProtocolWebSocketHandler.java:302) ~[spring-websocket-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:344) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:483) ~[spring-context-6.1.3.jar:6.1.3]
    at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]
    at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:313) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:214) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1136) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:174) ~[spring-boot-3.2.2.jar:3.2.2]
    at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1090) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.boot.SpringApplicationShutdownHook.closeAndWait(SpringApplicationShutdownHook.java:145) ~[spring-boot-3.2.2.jar:3.2.2]
    at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]
    at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:114) ~[spring-boot-3.2.2.jar:3.2.2]
    at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: org.springframework.core.task.TaskRejectedException: ExecutorService in shutdown state did not accept task: org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask@7c5e9d93
    at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:365) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.messaging.support.ExecutorSubscribableChannel.sendInternal(ExecutorSubscribableChannel.java:103) ~[spring-messaging-6.1.3.jar:6.1.3]
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:139) ~[spring-messaging-6.1.3.jar:6.1.3]
    ... 30 common frames omitted
Caused by: java.util.concurrent.RejectedExecutionException: Task org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask@7c5e9d93 rejected from org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor$1@1619912c[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 6]
    at java.base/java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2065) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:833) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1365) ~[na:na]
    at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor$1.execute(ThreadPoolTaskExecutor.java:269) ~[spring-context-6.1.3.jar:6.1.3]
    at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:362) ~[spring-context-6.1.3.jar:6.1.3]
    ... 32 common frames omitted

[jhoeller]

You might have to configure your ThreadPoolTaskExecutor bean with acceptTasksAfterContextClose=true or waitForTasksToCompleteOnShutdown=true. As of 6.1, Spring's standard graceful shutdown arrangement does not accept new tasks after context close otherwise.

It looks like we need to revisit the stop phase interaction between SubProtocolWebSocketHandler and the ThreadPoolTaskExecutor that it delegates to, so that the former's stop step completes before the latter's stop phase begins.

[jhoeller]

I'm going with a different solution for resilient behavior in such a scenario: If the executor rejects a task (typically on shutdown but could also be due to a configured rejection policy on overload), we simply run that task locally if there is such a code path already. That's the case for ExecutorSubscribableChannel as well as SimpleApplicationEventMulticaster where the executor is optional to begin with. On shutdown, running tasks locally as a fallback (just like if no executor was configured) is definitely preferable to just dropping the affected tasks.

[daspilker]

I tested the current 6.1.4-SNAPSHOT and can confirm that the exception is gone. Thank you!

[jhoeller]

Good to hear, thanks for checking!