Springboot asynchronous mvc uses the correct posture of threadlocal.

  springboot

log

2017-02-08 23:13:25.902  INFO 1516 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:13:25.904  INFO 1516 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:13:25.906  INFO 1516 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:13:25.909  INFO 1516 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.914  INFO 1516 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.914  INFO 1516 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.914  INFO 1516 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:13:30.937  INFO 1516 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

The received request and the returned response are not the same thread.
BeforeConcurrentHandling is executed in the receiving thread
PreProcess is executed in asynchronous threads
PostProcess is executed in an asynchronous thread.
AfterCompletion is in response thread

Or ..

2017-02-08 23:13:57.555  INFO 1516 --- [nio-8080-exec-3] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-3,5,main]
2017-02-08 23:13:57.555  INFO 1516 --- [nio-8080-exec-3] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-3,5,main]
2017-02-08 23:13:57.555  INFO 1516 --- [nio-8080-exec-3] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-3,5,main]
2017-02-08 23:13:57.556  INFO 1516 --- [      MvcAsync2] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.559  INFO 1516 --- [      MvcAsync2] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.560  INFO 1516 --- [      MvcAsync2] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.560  INFO 1516 --- [      MvcAsync2] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync2,5,main]
2017-02-08 23:14:02.566  INFO 1516 --- [nio-8080-exec-4] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-4,5,main]

3s timeout, processing sleep 5s

2017-02-08 23:15:26.660  INFO 1530 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:15:26.662  INFO 1530 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:15:26.664  INFO 1530 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:15:26.667  INFO 1530 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:15:30.076  INFO 1530 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : handleTimeout CALLED,thread:Thread[http-nio-8080-exec-2,5,main]
2017-02-08 23:15:30.089  INFO 1530 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]
2017-02-08 23:15:31.668  INFO 1530 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:15:31.668  INFO 1530 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:15:31.668  INFO 1530 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]

HandleTimeout is executed in the response thread.
AfterCompletion is in response thread
After 3 seconds timeout, return the requesting thread to execute handleTimeout, and then execute afterCompletion.
At 5 seconds, the asynchronous thread finishes executing and performs postProcess

There was no timeout, but task threw an exception

2017-02-08 23:27:31.164  INFO 1551 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:27:31.166  INFO 1551 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:27:31.168  INFO 1551 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-08 23:27:31.171  INFO 1551 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.174  INFO 1551 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.174  INFO 1551 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.174  INFO 1551 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-08 23:27:36.196 ERROR 1551 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet dispatcherServlet threw exception
java.lang.RuntimeException: test
    at com.xixicat.service.TaskService.execute(TaskService.java:17) ~[classes/:na]
    at org.springframework.web.context.request.async.WebAsyncManager$4.run(WebAsyncManager.java:316) ~[spring-web-4.3.5.RELEASE.jar:4.3.5.RELEASE]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_71]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_71]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_71]
2017-02-08 23:27:36.197 ERROR 1551 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: test] with root cause
java.lang.RuntimeException: test
    at com.xixicat.service.TaskService.execute(TaskService.java:17) ~[classes/:na]
    at org.springframework.web.context.request.async.WebAsyncManager$4.run(WebAsyncManager.java:316) ~[spring-web-4.3.5.RELEASE.jar:4.3.5.RELEASE]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_71]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_71]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_71]
2017-02-08 23:27:36.238  INFO 1551 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]
2017-02-08 23:27:36.238  INFO 1551 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

Task throws an exception or calls postProcess.
AfterCompletion was executed twice on the response thread.

Plus spring filter

2017-02-09 00:03:17.711  INFO 1672 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter before,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.724  INFO 1672 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.724  INFO 1672 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.726  INFO 1672 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:null,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:17.729  INFO 1672 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:17.729  INFO 1672 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter after,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:03:22.730  INFO 1672 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:localhost get by mdc,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:22.730  INFO 1672 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:22.730  INFO 1672 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:03:22.750  INFO 1672 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

Plus MDC

2017-02-09 00:05:46.870  INFO 1682 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter before,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.883  INFO 1682 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.884  INFO 1682 --- [nio-8080-exec-1] c.p.controller.AsyncCallableController   : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.886  INFO 1682 --- [nio-8080-exec-1] c.p.config.TraceAsyncRequestInterceptor  : beforeConcurrentHandling get from mdc:remote ip set from OncePerRequestFilter,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:46.889  INFO 1682 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : preProcess get from mdc:null,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:46.889  INFO 1682 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter after,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:05:51.891  INFO 1682 --- [      MvcAsync1] com.xixicat.service.TaskService       : task service get from mdc:remote ip set from OncePerRequestFilter,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:51.891  INFO 1682 --- [      MvcAsync1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:51.891  INFO 1682 --- [      MvcAsync1] c.p.config.TraceAsyncRequestInterceptor  : postProcess CALLED,thread:Thread[MvcAsync1,5,main]
2017-02-09 00:05:51.914  INFO 1682 --- [nio-8080-exec-2] c.p.config.TraceAsyncRequestInterceptor  : afterCompletion CALLED,thread:Thread[http-nio-8080-exec-2,5,main]

block

2017-02-09 00:08:52.271  INFO 1691 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter before,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:52.284  INFO 1691 --- [nio-8080-exec-1] c.p.controller.BlockingController        : Request received,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.291  INFO 1691 --- [nio-8080-exec-1] com.xixicat.service.TaskService       : task service get from mdc:remote ip set from OncePerRequestFilter,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.291  INFO 1691 --- [nio-8080-exec-1] com.xixicat.service.TaskService       : Slow task executed,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.291  INFO 1691 --- [nio-8080-exec-1] c.p.controller.BlockingController        : Servlet thread released,thread:Thread[http-nio-8080-exec-1,5,main]
2017-02-09 00:08:57.305  INFO 1691 --- [nio-8080-exec-1] com.xixicat.config.TraceFilter        : OncePerRequestFilter after,thread:Thread[http-nio-8080-exec-1,5,main]

Summary

  • In OncePerRequestFilter, MDC is added before, and MDC is deleted MDC,after. this is for the requesting thread.

  • CallableProcessingInterceptorAdapter This preProcess is added to the asynchronous thread MDC, and PostProcess deletes the asynchronous thread MDC

doc