When using a logging library associated with SLF4J to handle IOException of SseEmitter, the same exception for NIO cannot be caught.

[setruth]

Detailed description

During simulated heartbeat sending, when trying to catch IOExceptions in the SseEmiter.send operation, I found that while I could catch IOExceptions that occurred when the client disconnected, the same IOException was still thrown on the NIO thread. I understand this is NIO behavior; asynchronous operations cannot be caught on different threads. However, what I don't understand is that when I use the SLF4J logging library for logging output in the captured code block, the NIO logs are still printed. But when I don't use a logging library for output (e.g., using the print function), or don't perform any operation, the NIO logs are not printed. Why is this? I can't understand why the NIO logs are being printed, which prevents me from better handling this problem.

Use version

• springboot : 3.5.6
• jdk: 17

Reproduction Test

1. When I use curl http://localhost:8180/none-log to test none-log, it does not print the NIO IOException log.
2. When I use curl http://localhost:8180/use-log to test use-log, it can capture errors, but it also prints NIO IOException logs.

Test Demo Repository

https://github.com/setruth/sse-exception

[rstoyanchev]

This is likely related to a race between you trying to write from an application thread seeing the IOException, and the Servlet container detecting the closed connection and trying to notify the application of the closed connection. Depending on who wins the race you may or may not get an ASYNC dispatch to complete request handling.

In any case, it is not possible to prevent the Servlet container from trying to handle the IOException in parallel nor should you. Imagine for example that you have some time between SseEmitter emissions. This would ensure prompt completion. So I would focus on ensuring handling via @ExceptionHandler methods. Those should already be able to detect disconnected client errors, but unfortunately, I'm not able to reproduce the behavior.

[setruth]

This is likely related to a race between you trying to write from an application thread seeing the IOException, and the Servlet container detecting the closed connection and trying to notify the application of the closed connection. Depending on who wins the race you may or may not get an ASYNC dispatch to complete request handling.

In any case, it is not possible to prevent the Servlet container from trying to handle the IOException in parallel nor should you. Imagine for example that you have some time between SseEmitter emissions. This would ensure prompt completion. So I would focus on ensuring handling via @ExceptionHandler methods. Those should already be able to detect disconnected client errors, but unfortunately, I'm not able to reproduce the behavior.

I am currently using @ ExceptionHandler to handle exceptions on this Servlet, but I would like to know why IOException logs are sometimes triggered but not always. If you use curl http://localhost:8180/use -The log ` command did not encounter the problem I mentioned above. I suggest trying it multiple times because this trigger does not occur every time. I don't think using @ ExceptionHandler is a good way to handle it because it requires handling different IOExceptions. And now switching to Jetty won't cause any issues, I'm not sure if it's a problem with Tomacat's handling.

[rstoyanchev]

2025-12-04T11:56:18.346Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/use-log", parameters={}
2025-12-04T11:56:18.349Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.setruth.test.sseexception.Controller#api2()
2025-12-04T11:56:18.383Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : start heartbeat
2025-12-04T11:56:18.383Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : send ping
2025-12-04T11:56:18.384Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] o.s.w.c.request.async.WebAsyncManager    : Started async request for "/use-log"
2025-12-04T11:56:18.386Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting but response remains open for further handling
2025-12-04T11:56:19.388Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : send ping
2025-12-04T11:56:20.392Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : send ping
2025-12-04T11:56:21.398Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : client close
2025-12-04T11:56:21.398Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.w.c.request.async.WebAsyncManager    : Servlet container error notification for "/use-log"
2025-12-04T11:56:21.399Z DEBUG 97957 --- [SSEException] [atcher-worker-1] o.s.w.c.request.async.WebAsyncManager    : Async result set for "/use-log"
2025-12-04T11:56:21.399Z DEBUG 97957 --- [SSEException] [atcher-worker-1] o.s.w.c.request.async.WebAsyncManager    : Performing async dispatch for "/use-log"
2025-12-04T11:56:21.405Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.web.servlet.DispatcherServlet        : "INCLUDE" dispatch for GET "/error", parameters={}
2025-12-04T11:56:21.406Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2025-12-04T11:56:21.408Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] s.w.s.m.m.a.RequestMappingHandlerAdapter : Resume with async result [org.springframework.web.context.request.async.AsyncRequestNotUsableException: Response not usable af (truncated)...]
Exception in thread "DefaultDispatcher-worker-1" java.lang.IllegalStateException: A non-container (application) thread attempted to use the AsyncContext after an error had occurred and the call to AsyncListener.onError() had returned. This is not allowed to avoid race conditions.
	at org.apache.catalina.core.AsyncContextImpl.check(AsyncContextImpl.java:535)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:152)
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.dispatch(StandardServletAsyncWebRequest.java:171)
	at org.springframework.web.context.request.async.WebAsyncManager.setConcurrentResultAndDispatch(WebAsyncManager.java:525)
	at org.springframework.web.context.request.async.WebAsyncManager.lambda$startDeferredResultProcessing$8(WebAsyncManager.java:477)
	at org.springframework.web.context.request.async.DeferredResult.setResultInternal(DeferredResult.java:272)
	at org.springframework.web.context.request.async.DeferredResult.setErrorResult(DeferredResult.java:287)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$DefaultSseEmitterHandler.complete(ResponseBodyEmitterReturnValueHandler.java:329)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.complete(ResponseBodyEmitter.java:282)
	at com.setruth.test.sseexception.Controller$api2$1.invokeSuspend(Controller.kt:71)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:34)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
	at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111)
	at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702)
	Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [StandaloneCoroutine{Cancelling}@3463e6fb, Dispatchers.IO]
2025-12-04T11:56:21.413Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.w.s.handler.DisconnectedClient       : Looks like the client has gone away: org.springframework.web.context.request.async.AsyncRequestNotUsableException: Response not usable after response errors. (For a full stack trace, set the log category 'org.apache.commons.logging.LogAdapter$Slf4jLocationAwareLog@1d705246' to TRACE level.)
2025-12-04T11:56:21.414Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.web.servlet.DispatcherServlet        : Exiting from "INCLUDE" dispatch, status 200

You can see there is a race between the "Servlet container error notification" (Tomcat thread) and "Async result set" (application thread as a result of the controller calling sseEmitter.complete()). The application thread wins, and performs an ASYNC dispatch from within a synchronized block. That means the Servlet container thread cannot return from the notification callback before the ASYNC dispatch is performed, and in that case the dispatch should be possible, but it looks after the error callback returns, the async request is completed.

Possibly a Tomcat issue, yes. We recommend not trying to compete with Tomcat in this case. There is no need to complete the emitter in case of an IOError, and this is indicated on the JavaDoc of ResponseBodyEmitter#send. Changing the controller method to this works:

    @GetMapping("use-log")
    fun api2(): SseEmitter {
        val sseEmitter = SseEmitter(0)
        ioScope.launch {
            log.info { "start heartbeat" }
            while (true) {
                try {
                    sseEmitter.send("hello")
                } catch (_: IOException) {
                    log.info { "client close" }
                    break
                } catch (e: Exception) {
                    log.error { "unknow exception" }
                    sseEmitter.complete()  // <==
                    break
                }
                log.info{ "send ping"}
                delay(1.seconds)
            }
            // sseEmitter.complete()
            log.info { "sse finish" }
        }
        return sseEmitter
    }

[setruth]

2025-12-04T11:56:18.346Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/use-log", parameters={}
2025-12-04T11:56:18.349Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.setruth.test.sseexception.Controller#api2()
2025-12-04T11:56:18.383Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : start heartbeat
2025-12-04T11:56:18.383Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : send ping
2025-12-04T11:56:18.384Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] o.s.w.c.request.async.WebAsyncManager    : Started async request for "/use-log"
2025-12-04T11:56:18.386Z DEBUG 97957 --- [SSEException] [nio-8180-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting but response remains open for further handling
2025-12-04T11:56:19.388Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : send ping
2025-12-04T11:56:20.392Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : send ping
2025-12-04T11:56:21.398Z  INFO 97957 --- [SSEException] [atcher-worker-1] c.setruth.test.sseexception.Controller   : client close
2025-12-04T11:56:21.398Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.w.c.request.async.WebAsyncManager    : Servlet container error notification for "/use-log"
2025-12-04T11:56:21.399Z DEBUG 97957 --- [SSEException] [atcher-worker-1] o.s.w.c.request.async.WebAsyncManager    : Async result set for "/use-log"
2025-12-04T11:56:21.399Z DEBUG 97957 --- [SSEException] [atcher-worker-1] o.s.w.c.request.async.WebAsyncManager    : Performing async dispatch for "/use-log"
2025-12-04T11:56:21.405Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.web.servlet.DispatcherServlet        : "INCLUDE" dispatch for GET "/error", parameters={}
2025-12-04T11:56:21.406Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2025-12-04T11:56:21.408Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] s.w.s.m.m.a.RequestMappingHandlerAdapter : Resume with async result [org.springframework.web.context.request.async.AsyncRequestNotUsableException: Response not usable af (truncated)...]
Exception in thread "DefaultDispatcher-worker-1" java.lang.IllegalStateException: A non-container (application) thread attempted to use the AsyncContext after an error had occurred and the call to AsyncListener.onError() had returned. This is not allowed to avoid race conditions.
	at org.apache.catalina.core.AsyncContextImpl.check(AsyncContextImpl.java:535)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:152)
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.dispatch(StandardServletAsyncWebRequest.java:171)
	at org.springframework.web.context.request.async.WebAsyncManager.setConcurrentResultAndDispatch(WebAsyncManager.java:525)
	at org.springframework.web.context.request.async.WebAsyncManager.lambda$startDeferredResultProcessing$8(WebAsyncManager.java:477)
	at org.springframework.web.context.request.async.DeferredResult.setResultInternal(DeferredResult.java:272)
	at org.springframework.web.context.request.async.DeferredResult.setErrorResult(DeferredResult.java:287)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$DefaultSseEmitterHandler.complete(ResponseBodyEmitterReturnValueHandler.java:329)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.complete(ResponseBodyEmitter.java:282)
	at com.setruth.test.sseexception.Controller$api2$1.invokeSuspend(Controller.kt:71)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:34)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
	at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:111)
	at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:99)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702)
	Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [StandaloneCoroutine{Cancelling}@3463e6fb, Dispatchers.IO]
2025-12-04T11:56:21.413Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.w.s.handler.DisconnectedClient       : Looks like the client has gone away: org.springframework.web.context.request.async.AsyncRequestNotUsableException: Response not usable after response errors. (For a full stack trace, set the log category 'org.apache.commons.logging.LogAdapter$Slf4jLocationAwareLog@1d705246' to TRACE level.)
2025-12-04T11:56:21.414Z DEBUG 97957 --- [SSEException] [nio-8180-exec-2] o.s.web.servlet.DispatcherServlet        : Exiting from "INCLUDE" dispatch, status 200

You can see there is a race between the "Servlet container error notification" (Tomcat thread) and "Async result set" (application thread as a result of the controller calling sseEmitter.complete()). The application thread wins, and performs an ASYNC dispatch from within a synchronized block. That means the Servlet container thread cannot return from the notification callback before the ASYNC dispatch is performed, and in that case the dispatch should be possible, but it looks after the error callback returns, the async request is completed.

Possibly a Tomcat issue, yes. We recommend not trying to compete with Tomcat in this case. There is no need to complete the emitter in case of an IOError, and this is indicated on the JavaDoc of ResponseBodyEmitter#send. Changing the controller method to this works:

@GetMapping("use-log")
fun api2(): SseEmitter {
    val sseEmitter = SseEmitter(0)
    ioScope.launch {
        log.info { "start heartbeat" }
        while (true) {
            try {
                sseEmitter.send("hello")
            } catch (_: IOException) {
                log.info { "client close" }
                break
            } catch (e: Exception) {
                log.error { "unknow exception" }
                sseEmitter.complete()  // <==
                break
            }
            log.info{ "send ping"}
            delay(1.seconds)
        }
        // sseEmitter.complete()
        log.info { "sse finish" }
    }
    return sseEmitter
}

Thank you for your suggestion. My shouldn't attempt to execute the Complete operation after an IO exception occurs. However, even if an IOException occurs and isn't handled, the Servlet exception will still be displayed. I later asked AI, and AI said this might be due to Tomcat's handling; Tomcat logs, but Jetty considers this IOException acceptable and handles it internally, so Jetty doesn't display the Servlet logs. Is that correct? So, when using Tomcat, if you don't want to see Servlet exception logs, you still need to use @ExceptionHandler for global handling, right?

[rstoyanchev]

You do need an @ExceptionHandler. As I explained previously, the sequence is that the Servlet container provides an AsyncListener#onError error notification, which we handle by performing an ASYNC dispatch and that allows you to handles the exception through an @ExceptionHandler, but if you don't it will remain unhandled.

That said if you have ResponseEntityExceptionHandler configured it will handle this case transparently. We wrap the IOException as AsyncRequestNotUsableException and that's handled.

Furthermore, if you have error handling configured in Boot, that will also ensure the exception is handled. So typically, it shouldn't escape to Tomcat.

[setruth]

You do need an @ExceptionHandler. As I explained previously, the sequence is that the Servlet container provides an AsyncListener#onError error notification, which we handle by performing an ASYNC dispatch and that allows you to handles the exception through an @ExceptionHandler, but if you don't it will remain unhandled.

That said if you have ResponseEntityExceptionHandler configured it will handle this case transparently. We wrap the IOException as AsyncRequestNotUsableException and that's handled.

Furthermore, if you have error handling configured in Boot, that will also ensure the exception is handled. So typically, it shouldn't escape to Tomcat.

Yes, this is really the most reasonable way to deal with i.In my follow-up test, when I went from Tomcat after switching to Jetty, in the IOException catch middle to execute sseEmiter.Complete, He's not like Tomcat print the same Servlet of Exception log,I think jetty handles this async exception internally and does not print a log of this exception