Log format not applied with logback to `java.lang.IllegalStateException: A non-container (application) thread attempted to use the AsyncContext...` log

[collabintel]

We have seen a certain log which is not formatted according to our logback appender, which formats our logs in json in our application. All of the other logs are formatted in json, except this one.

We think this problem started happening after this fix: #33421. This comment also explains after the fix we started getting this log: #33421 (comment).

Reproduced with Spring Boot 3.3.4 and logstash-logback-encoder 8.0 version.

Steps to reproduce:

See the minimalist example attached, with the following steps to reproduce:

• Launch the main class
• Using a browser as an http client, go to the index.html via url : http://localhost:8080
• Refresh the browser multiple times(the faster the better chance of getting the log)
• For each additional refresh, an additional log may appear

Example of not correctly formatted log

Exception in thread "task-6" 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:537)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:175)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:170)
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.dispatch(StandardServletAsyncWebRequest.java:170)
	at org.springframework.web.context.request.async.WebAsyncManager.setConcurrentResultAndDispatch(WebAsyncManager.java:411)
	at org.springframework.web.context.request.async.WebAsyncManager.lambda$startDeferredResultProcessing$8(WebAsyncManager.java:489)
	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$HttpMessageConvertingHandler.completeWithError(ResponseBodyEmitterReturnValueHandler.java:241)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.completeWithError(ResponseBodyEmitter.java:267)
	at org.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$AbstractEmitterSubscriber.run(ReactiveTypeHandler.java:340)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)

demowronglogformat.zip

[rstoyanchev]

I was able to reproduce the issue.

The write fails with a "Connection reset by peer" IOException in in a Spring MVC TaskExecutor thread. The exception remains not handled, and is logged to the system output. The exception is not supposed to happen, so I've opened #34192 and it should no longer appear.

For the logging, you can customize the TaskExecutor in Boot, which gets plugged in as the Spring MVC TaskExecutor, to ensure proper logging as follows:

@Bean
public ThreadPoolTaskExecutorCustomizer threadPoolTaskExecutorCustomizer() {
    return executor -> executor.setTaskDecorator(runnable ->
            () -> {
                try {
                    runnable.run();
                }
                catch (Throwable ex) {
                    logger.error("Handled error " + ex.getMessage(), ex);
                }
            });
}

[rstoyanchev]

I'm closing as superseded by #34192 .

[ugurberkecan]

I was able to reproduce the issue.

The write fails with a "Connection reset by peer" IOException in in a Spring MVC TaskExecutor thread. The exception remains not handled, and is logged to the system output. The exception is not supposed to happen, so I've opened #34192 and it should no longer appear.

For the logging, you can customize the TaskExecutor in Boot, which gets plugged in as the Spring MVC TaskExecutor, to ensure proper logging as follows:

@bean
public ThreadPoolTaskExecutorCustomizer threadPoolTaskExecutorCustomizer() {
return executor -> executor.setTaskDecorator(runnable ->
() -> {
try {
runnable.run();
}
catch (Throwable ex) {
logger.error("Handled error " + ex.getMessage(), ex);
}
});
}

This changes work but it basically brake other logs so we need to removed it, do you have any other suggestion about it ?