To reproduce add a Thread.sleep to a MVC+Actuator app then force close it from the command line.
java.lang.NullPointerException: null
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.stopLongTaskTimers(LongTaskTimingHandlerInterceptor.java:123) ~[spring-boot-actuator-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.afterCompletion(LongTaskTimingHandlerInterceptor.java:79) ~[spring-boot-actuator-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
at org.springframework.web.servlet.HandlerExecutionChain.triggerAfterCompletion(HandlerExecutionChain.java:179) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1427) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:93) ~[spring-boot-actuator-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.35.jar!/:9.0.35]
at java.base/java.lang.Thread.run(Thread.java:832) ~[na:na]
Comment From: dreis2211
A simple fix could be to check for LongTaskTimingContext.get(request) being null and only stopping the timers if it exists.
The bigger question here probably is why the previously added attribute is removed.
Comment From: philwebb
Ahh, I remember now. We've seen this before in #16407.
Comment From: OrangeDog
I'm getting the same stacktrace during normal operation as well. No shutdown involved. Same scenario as https://github.com/spring-projects/spring-boot/issues/16407#issuecomment-645987594 - Undertow, Spring Security.
Comment From: wilkinsona
@OrangeDog I've been working with @aheritier but we haven't yet figured out what's clearing the request attributes when using Undertow. If you can share a sample that reproduces it, I'd love to take a look at it too.
Comment From: aheritier
@OrangeDog I can confirm now that it's not related to a shutdown. I will try to plug a debugger to our staging environment to get more details for @wilkinsona I sadly cannot reproduce locally the issue on dev env :(
Comment From: OrangeDog
As far as I can tell it has nothing to do with the request being slow either.
I caught one on a favicon.ico request. I don't know what you're looking for but here are some details at the afterCompletion call.
request: FirewalledRequest[ org.springframework.web.servlet.resource.ResourceUrlEncodingFilter$ResourceUrlEncodingRequestWrapper@1af9caef]`
response: FirewalledResponse
handler: ResourceHttpRequestHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/", "/"]
ex: java.io.IOException: An established connection was aborted by the software in your host machine
at java.base/sun.nio.ch.SocketDispatcher.write0(Native Method)
at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:51)
at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:113)
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:58)
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:50)
at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466)
at org.xnio.nio.NioSocketConduit.write(NioSocketConduit.java:153)
at io.undertow.server.protocol.http.HttpResponseConduit.write(HttpResponseConduit.java:617)
at io.undertow.conduits.AbstractFixedLengthStreamSinkConduit.write(AbstractFixedLengthStreamSinkConduit.java:106)
at org.xnio.conduits.Conduits.writeFinalBasic(Conduits.java:132)
at io.undertow.conduits.AbstractFixedLengthStreamSinkConduit.writeFinal(AbstractFixedLengthStreamSinkConduit.java:175)
at org.xnio.conduits.ConduitStreamSinkChannel.writeFinal(ConduitStreamSinkChannel.java:104)
at io.undertow.channels.DetachableStreamSinkChannel.writeFinal(DetachableStreamSinkChannel.java:195)
at io.undertow.server.HttpServerExchange$WriteDispatchChannel.writeFinal(HttpServerExchange.java:2090)
at io.undertow.servlet.spec.ServletOutputStreamImpl.writeBufferBlocking(ServletOutputStreamImpl.java:573)
at io.undertow.servlet.spec.ServletOutputStreamImpl.close(ServletOutputStreamImpl.java:610)
at io.undertow.servlet.spec.ServletOutputStreamImpl.updateWritten(ServletOutputStreamImpl.java:372)
at io.undertow.servlet.spec.ServletOutputStreamImpl.write(ServletOutputStreamImpl.java:154)
at org.springframework.session.web.http.OnCommittedResponseWrapper$SaveContextServletOutputStream.write(OnCommittedResponseWrapper.java:624)
at org.springframework.util.StreamUtils.copy(StreamUtils.java:166)
at org.springframework.http.converter.ResourceHttpMessageConverter.writeContent(ResourceHttpMessageConverter.java:137)
at org.springframework.http.converter.ResourceHttpMessageConverter.writeInternal(ResourceHttpMessageConverter.java:129)
at org.springframework.http.converter.ResourceHttpMessageConverter.writeInternal(ResourceHttpMessageConverter.java:45)
at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227)
at org.springframework.web.servlet.resource.ResourceHttpRequestHandler.handleRequest(ResourceHttpRequestHandler.java:522)
at org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter.handle(HttpRequestHandlerAdapter.java:53)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:503)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:209)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.servlet.resource.ResourceUrlEncodingFilter.doFilter(ResourceUrlEncodingFilter.java:64)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:141)
at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:82)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:269)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:370)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2019)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1558)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1449)
at java.base/java.lang.Thread.run(Thread.java:834)
Comment From: wilkinsona
@OrangeDog That's a different problem to the one being tracked here. This issue is about a NullPointerException being thrown by LongTaskTimingHandlerInterceptor.stopLongTaskTimers because the attribute that it sets on the request has disappeared. The exception that you are seeing seems to be due to something closing the connection before the response could be written to it.
Comment From: OrangeDog
@wilkinsona I caught the NPE in stopLongTaskTimers. These are the arguments one frame up in afterCompletion, in case they aid in a reproduction.
Comment From: wilkinsona
Sorry, I misunderstood. That's really useful, thank you. So that's the stack trace of the exception that's passed into LongTaskTimingHandlerInterceptor.afterCompletion? That gives me somewhere to start investigating what is clearing the request attribute.
Comment From: wilkinsona
I've managed to reproduce the problem by debugging and throwing an IOException from within the depths of Undertow's HTTP layer. Thanks again for the pointer, @OrangeDog.
Comment From: wilkinsona
Ok, it looks like a bug in Undertow to me. It's clearing out the request attributes too soon. Here's where it happens:
clearAttributes:1200, HttpServletRequestImpl (io.undertow.servlet.spec)
closeAndDrainRequest:694, HttpServletRequestImpl (io.undertow.servlet.spec)
close:89, ServletBlockingHttpExchange (io.undertow.servlet.core)
endExchange:1626, HttpServerExchange (io.undertow.server)
handleEvent:316, AbstractServerConnection$CloseSetter (io.undertow.server)
handleEvent:296, AbstractServerConnection$CloseSetter (io.undertow.server)
invokeChannelListener:92, ChannelListeners (org.xnio)
invokeCloseListener:80, StreamConnection (org.xnio)
close:142, Connection (org.xnio)
close:159, AbstractServerConnection (io.undertow.server)
safeClose:152, IoUtils (org.xnio)
write:624, HttpResponseConduit (io.undertow.server.protocol.http)
write:106, AbstractFixedLengthStreamSinkConduit (io.undertow.conduits)
writeFinalBasic:132, Conduits (org.xnio.conduits)
writeFinal:175, AbstractFixedLengthStreamSinkConduit (io.undertow.conduits)
writeFinal:104, ConduitStreamSinkChannel (org.xnio.conduits)
writeFinal:195, DetachableStreamSinkChannel (io.undertow.channels)
writeFinal:2090, HttpServerExchange$WriteDispatchChannel (io.undertow.server)
writeBufferBlocking:573, ServletOutputStreamImpl (io.undertow.servlet.spec)
close:610, ServletOutputStreamImpl (io.undertow.servlet.spec)
updateWritten:372, ServletOutputStreamImpl (io.undertow.servlet.spec)
write:154, ServletOutputStreamImpl (io.undertow.servlet.spec)
copy:166, StreamUtils (org.springframework.util)
writeContent:137, ResourceHttpMessageConverter (org.springframework.http.converter)
writeInternal:129, ResourceHttpMessageConverter (org.springframework.http.converter)
writeInternal:45, ResourceHttpMessageConverter (org.springframework.http.converter)
write:227, AbstractHttpMessageConverter (org.springframework.http.converter)
writeWithMessageConverters:290, AbstractMessageConverterMethodProcessor (org.springframework.web.servlet.mvc.method.annotation)
handleReturnValue:181, RequestResponseBodyMethodProcessor (org.springframework.web.servlet.mvc.method.annotation)
handleReturnValue:82, HandlerMethodReturnValueHandlerComposite (org.springframework.web.method.support)
invokeAndHandle:123, ServletInvocableHandlerMethod (org.springframework.web.servlet.mvc.method.annotation)
invokeHandlerMethod:879, RequestMappingHandlerAdapter (org.springframework.web.servlet.mvc.method.annotation)
handleInternal:793, RequestMappingHandlerAdapter (org.springframework.web.servlet.mvc.method.annotation)
handle:87, AbstractHandlerMethodAdapter (org.springframework.web.servlet.mvc.method)
doDispatch:1040, DispatcherServlet (org.springframework.web.servlet)
doService:943, DispatcherServlet (org.springframework.web.servlet)
processRequest:1006, FrameworkServlet (org.springframework.web.servlet)
doGet:898, FrameworkServlet (org.springframework.web.servlet)
service:503, HttpServlet (javax.servlet.http)
service:883, FrameworkServlet (org.springframework.web.servlet)
service:590, HttpServlet (javax.servlet.http)
handleRequest:74, ServletHandler (io.undertow.servlet.handlers)
doFilter:129, FilterHandler$FilterChainImpl (io.undertow.servlet.handlers)
doFilterInternal:100, RequestContextFilter (org.springframework.web.filter)
doFilter:119, OncePerRequestFilter (org.springframework.web.filter)
doFilter:61, ManagedFilter (io.undertow.servlet.core)
doFilter:131, FilterHandler$FilterChainImpl (io.undertow.servlet.handlers)
doFilterInternal:93, FormContentFilter (org.springframework.web.filter)
doFilter:119, OncePerRequestFilter (org.springframework.web.filter)
doFilter:61, ManagedFilter (io.undertow.servlet.core)
doFilter:131, FilterHandler$FilterChainImpl (io.undertow.servlet.handlers)
doFilterInternal:93, WebMvcMetricsFilter (org.springframework.boot.actuate.metrics.web.servlet)
doFilter:119, OncePerRequestFilter (org.springframework.web.filter)
doFilter:61, ManagedFilter (io.undertow.servlet.core)
doFilter:131, FilterHandler$FilterChainImpl (io.undertow.servlet.handlers)
doFilterInternal:201, CharacterEncodingFilter (org.springframework.web.filter)
doFilter:119, OncePerRequestFilter (org.springframework.web.filter)
doFilter:61, ManagedFilter (io.undertow.servlet.core)
doFilter:131, FilterHandler$FilterChainImpl (io.undertow.servlet.handlers)
handleRequest:84, FilterHandler (io.undertow.servlet.handlers)
handleRequest:62, ServletSecurityRoleHandler (io.undertow.servlet.handlers.security)
handleRequest:68, ServletChain$1 (io.undertow.servlet.handlers)
handleRequest:36, ServletDispatchingHandler (io.undertow.servlet.handlers)
handleRequest:68, RedirectDirHandler (io.undertow.servlet.handlers)
handleRequest:132, SSLInformationAssociationHandler (io.undertow.servlet.handlers.security)
handleRequest:57, ServletAuthenticationCallHandler (io.undertow.servlet.handlers.security)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:46, AbstractConfidentialityHandler (io.undertow.security.handlers)
handleRequest:64, ServletConfidentialityConstraintHandler (io.undertow.servlet.handlers.security)
handleRequest:60, AuthenticationMechanismsHandler (io.undertow.security.handlers)
handleRequest:77, CachedAuthenticatedSessionHandler (io.undertow.servlet.handlers.security)
handleRequest:43, AbstractSecurityContextAssociationHandler (io.undertow.security.handlers)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleRequest:43, PredicateHandler (io.undertow.server.handlers)
handleFirstRequest:269, ServletInitialHandler (io.undertow.servlet.handlers)
access$100:78, ServletInitialHandler (io.undertow.servlet.handlers)
call:133, ServletInitialHandler$2 (io.undertow.servlet.handlers)
call:130, ServletInitialHandler$2 (io.undertow.servlet.handlers)
call:48, ServletRequestContextThreadSetupAction$1 (io.undertow.servlet.core)
call:43, ContextClassLoaderSetupAction$1 (io.undertow.servlet.core)
dispatchRequest:249, ServletInitialHandler (io.undertow.servlet.handlers)
access$000:78, ServletInitialHandler (io.undertow.servlet.handlers)
handleRequest:99, ServletInitialHandler$1 (io.undertow.servlet.handlers)
executeRootHandler:370, Connectors (io.undertow.server)
run:830, HttpServerExchange$1 (io.undertow.server)
run:35, ContextClassLoaderSavingRunnable (org.jboss.threads)
safeRun:2019, EnhancedQueueExecutor (org.jboss.threads)
doRunTask:1558, EnhancedQueueExecutor$ThreadBody (org.jboss.threads)
run:1449, EnhancedQueueExecutor$ThreadBody (org.jboss.threads)
run:748, Thread (java.lang)
It closes its view of the connection when the write fails. As part of this close processing, the HTTP server exchange is ended which clears the attributes on the request. The exception is then rethrown. It's caught by Spring MVC and it drives after completion so that things can be tidied up at the end of the request handling. At this point the attribute used to track long-task timing has gone so it doesn't get cleaned up properly.
Comment From: OrangeDog
So workaround is to downgrade Undertow? Any idea which is the latest that doesn't have the bug?
Comment From: aheritier
Awesome finding @wilkinsona let's hope to have now a good reactivity in the Undertow side. Thanks a lot @OrangeDog. You are also on Spring Boot 2.3.1 (Undertow 2.1.3)? I never saw this issue with Spring Boot 2.2.x. It's perhaps related to https://github.com/undertow-io/undertow/commit/a549027dc129ae61c94c08b046086aa2377c06a6 https://issues.redhat.com/browse/UNDERTOW-1722 It was introduced in undertow 2.1.2. @fl4via did you receive any similar feedback in undertow side after this change ?
Comment From: wilkinsona
Nicely found, @aheritier. That change in Undertow 2.1.2 looks like the cause of the regression.
Comment From: aheritier
@wilkinsona should we open a ticket on Undertow side ? @OrangeDog if you can easily reproduce the issue can you check if you have the same issue with undertow 2.1.1 ? (you shouldn't I hope)
Comment From: wilkinsona
@aheritier I've finally managed to reduce things down to something fairly minimal that reproduces the failure. I've opened https://issues.redhat.com/browse/UNDERTOW-1743.
Comment From: aheritier
awesome @wilkinsona Thanks a lot for your help
Comment From: martinvisser
We had this issue also in Spring Boot 2.2.8 with Tomcat (at least 9.0.36). What I don't know is what triggered this call, only that this was printed in our log right before: InterruptedException: sleep interrupted
Comment From: OrangeDog
@martinvisser https://github.com/spring-projects/spring-boot/issues/16407#issuecomment-656070722
Comment From: OrangeDog
CVE-2020-10687 requires an update, meaning this problem can no longer be avoided.
Is there an easy way to disable this interceptor?
I tried management.metrics.web.server.request.autotime.enabled, but it wasn't that.
Edit: excluding WebMvcMetricsAutoConfiguration will do it
Comment From: wilkinsona
Given the lack of traction on Undertow issues that we have raised such as UNDERTOW-1743 and the Undertow team choosing not to fix CVEs in 2.1 which GAed only 5 months ago, I think it's worth anyone using Undertow re-evaluating the benefits that attracted them to it.
Bugs not being fixed and requiring minor upgrades to avoid security vulnerabilities would weigh very heavily for me against any other benefits. I'd want to be using a container with a maintenance approach that better met my needs.
Comment From: aheritier
I agree @wilkinsona :( I will consider others options if they don't move. I know that in my case Undertow was better to handle large uploads but maybe others are better today.
Comment From: chadlwilson
Does anyone know if any changes in Spring Boot 2.3.5 or the linked Spring FW version might have made this much more likely to happen than previously in 2.3.4? We just upgraded and we are now seeing this where we didn't see it before - during regular operation with some long-poll type of endpoints.
We are on Undertow 2.2.0 (with override to Spring Boot's dependencies to address the CVE referred to above); otherwise we are on Spring Boot-managed versions for everything else.
Our RestControllerAdvice with an @ExceptionHandler sees java.io.IOException: Broken pipe trying to write response (probably a race; connection closed by caller) and then the same NPE above from LongTaskTimingHandlerInterceptor.stopLongTaskTimers.
I also note the thoughts above on concerns around maintenance of Undertow. Concerning to me too. Not sure about other containers, but the features that earlier attracted me were its fast start-up time inside test automation; relatively modern codebase, small footprint, top level support for NIO via XNIO, relative lack of bloat, performance etc. But this was a few years ago, and perhaps this may be an outdated view of the world c.f Tomcat or Jetty as they currently stand.
Comment From: wilkinsona
I'm not aware of any specific changes that would have affected this behaviour, particularly in Boot. @rstoyanchev @bclozel, have there been any changes in the latest Framework releases around flushing responses and the like that would affect the timing of when a response is actually written to the client?
probably a race; connection closed by caller
I wouldn't expect a client to close the connection until it has received the entire response. At that point, I wouldn't expect Undertow to complain of a broken pipe if the connection was closed. What client are you using? My understanding of the Undertow bug is that it will occur whenever an IOException is thrown while writing the response. If anything is making the problem occur more frequently, I would suspect that it's most likely to be on the client side.
Comment From: chadlwilson
Thanks @wilkinsona .
I wouldn't expect a client to close the connection until it has received the entire response.
Sorry, probably should have been a bit clearer. Since on our side these are long-poll types of endpoints intended for browser/AJAX/fetch consumption, a browser could give up on them at any time - or in this specific case, some automated Locust performance tests which run for 'n' minutes, and then close all the outstanding connections.
To add some additional complexity, we also have Istio service mesh proxies in front of the actual Spring Boot service networking, so the proxy has its own pool of internal HTTP connection to Undertow which is really the "true" client in this case. In theory these connections should actually be kept open almost indefinitely, so the broken pipe is a bit of a mystery in that regard - but we didn't change anything here, and we have alerts on all ERROR logs to keep on top of such noise. We haven't seen these errors from Undertow before that we can recall.
I was theorising that there is possibly a race because we also have a server-side timeout on the long polls, upon which we return a 408 to the client and expect it to retry if it is still interested. If this happens at the same time as the client has closed the connection; perhaps there is a chance of a race where we trying to write to a connection which is being closed? This internal timeout was the cause of the internal exception thrown which the @ExceptionHandler was trying to handle.
Comment From: rstoyanchev
We have a regression in 5.2.10 related to the closing of the response after use of Jackson. This could long running requests that write periodically but I don't know if that's applicable.
Comment From: chadlwilson
We do use Jackson, and the broken pipe is experienced when trying to take an object representing an error to serialize it. So this does sound possibly related.
https://github.com/spring-projects/spring-framework/issues/25987
Will try specifically downgrading Spring FW to 5.2.9 and see if the problem goes away.
Comment From: wilkinsona
I'm really pleased to report that there's been some movement on UNDERTOW-1743 with fixes made in the yet-to-be-released 2.0.33.Final, 2.1.5.Final, and 2.2.3.Final. We'll keep this issue open until those releases have happened and we have upgraded.
Comment From: tderoock
Still seeing this issue, although UNDERTOW-1743 is fixed.
$ mvn dependency:tree | grep undertow
[INFO] +- org.springframework.boot:spring-boot-starter-undertow:jar:2.4.1:compile
[INFO] | +- io.undertow:undertow-core:jar:2.2.3.Final:compile
[INFO] | +- io.undertow:undertow-servlet:jar:2.2.3.Final:compile
[INFO] | +- io.undertow:undertow-websockets-jsr:jar:2.2.3.Final:compile
Stacktrace:
2021-01-11 15:17:43.844 [user:] 347425756 [XNIO-1 task-5] ERROR o.s.w.servlet.HandlerExecutionChain -
HandlerInterceptor.afterCompletion threw exceptionjava.lang.NullPointerException: null
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.stopLongTaskTimers(LongTaskTimingHandlerInterceptor.java:123)
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.afterCompletion(LongTaskTimingHandlerInterceptor.java:79)
at org.springframework.web.servlet.HandlerExecutionChain.triggerAfterCompletion(HandlerExecutionChain.java:178)
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1448)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:497)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:584)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:106)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:119)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:87)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:110)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:80)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:269)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:186)
at io.undertow.servlet.spec.AsyncContextImpl$2$1.handleRequest(AsyncContextImpl.java:201)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:387)
at io.undertow.servlet.spec.AsyncContextImpl$2.run(AsyncContextImpl.java:195)
at io.undertow.servlet.spec.AsyncContextImpl$6.run(AsyncContextImpl.java:472)
at io.undertow.servlet.spec.AsyncContextImpl$TaskDispatchRunnable.run(AsyncContextImpl.java:591)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2019)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1558)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1449)
at java.base/java.lang.Thread.run(Thread.java:834)
Comment From: wilkinsona
@tderoock Oh dear. In that case it would appear that the fix in Undertow is faulty or incomplete. Please open a new Undertow issue so that they are aware. If you comment here with a link to it, I'll do my best to help with the problem diagnosis.
Comment From: wilkinsona
I've just tried my reproducer from UNDERTOW-1743 with Undertow 2.2.3 and the null pointer exception does not occur so it would appear that there's another code path within Undertow that may cause it to prematurely clear the request attributes. @tderoock If you open an Undertow issue, please take the time to describe to them in detail the situation in which the NPE occurs and, ideally, provide a sample similar to mine from UNDERTOW-1743 that reproduces the problem.
I'm going to close this issue now as I don't think there's anything we can do in Boot to mitigate a container that clears request attributes incorrectly. Checking for null would just hide the problem, leading to inaccurate metrics with no indication why. For the Tomcat side of things, please refer to https://github.com/spring-projects/spring-boot/issues/16407.