I encountered the following NPE in Spring Boot Actuator 2.1.3.RELEASE:
java.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:78)
at org.springframework.web.servlet.HandlerExecutionChain.triggerAfterCompletion(HandlerExecutionChain.java:174)
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1424)
…
I believe the assumption is that LongTaskTimingContext#get(HttpServletRequest) never returns null. However, it appears that there can be a case where the request does not contain the required attribute.
I think the code should check for null to be safe.
Comment From: wilkinsona
Thanks for the report. It's not immediately clear why the context would be null and I'd prefer not to introduce a null check without understanding why it's happening. If we just add a null check we may be addressing a symptom of a problem elsewhere and making that problem harder to diagnose. To allow us to understand the problem you're seeing, can you please provide a minimal sample that reproduces it?
Comment From: MenschNestor
I appreciate your concern. I'll try and come up with a sample; right now, I only have the stack trace from a production log.
Comment From: MenschNestor
After some trial-and-error, I've come to the conclusion that the NPE happens on service shutdown. I've created a sample at https://github.com/MenschNestor/spring-boot-16407 that exhibits the problem. I would expect the service to shutdown cleanly. Please let me know if the sample needs more explanation.
Comment From: wilkinsona
Thanks for the sample. I've been able to reproduce the problem and have also discovered that it only occurs when using Tomcat. With Undertow and Jetty the problem does not occur.
When using Tomcat, killing the process results in the http-nio-8080-ClientPoller-1 thread recycling the request while it's still be handled. The stack trace of the recycling is the following:
MessageBytes.recycle() line: 97
MappingData.recycle() line: 58
Request.recycle() line: 505
CoyoteAdapter.log(Request, Response, long) line: 497
CoyoteAdapter.checkRecycled(Request, Response) line: 521
Http11Processor.recycle() line: 1322
AbstractProtocol$ConnectionHandler<S>.release(Processor) line: 1016
AbstractProtocol$ConnectionHandler<S>.release(SocketWrapperBase<S>) line: 1038
NioEndpoint$Poller.cancelledKey(SelectionKey) line: 675
NioEndpoint$Poller.processKey(SelectionKey, NioEndpoint$NioSocketWrapper) line: 792
NioEndpoint$Poller.timeout(int, boolean) line: 971
NioEndpoint$Poller.run() line: 749
Thread.run() line: 748
The thread handling the request (http-nio-8080-exec-1) is then interrupted and the controller returns its response. During the response handling, a NullPointerException occurs beneath org.springframework.web.util.UrlPathHelper.getOriginatingRequestUri(HttpServletRequest) due to HttpServletRequest.getRequestURI() returning null. null is returned due to the earlier recycling of the request. After completion processing is then performed at which point LongTaskTimingHandlerInterceptor.stopLongTaskTimers is called and another NullPointerException occurs because the recycling has cleared the request's attributes.
This race between a request being recycled and its handling completing feels like a Tomcat bug to me. What do you think, @markt-asf?
Comment From: markt-asf
It depends how long the request takes to complete before Tomcat shuts down. Once the shutdown sequence starts, Tomcat will reject new requests and give in-flight requests at least Context.unloadDelay (default 2s) to complete (Servlets are stopped serially and each gets up to unloadDelay - in practise it is usually only one Servlet that has all the long running requests so you only see a wait of ~2s). 9.0.15 extended this delay to async requests. Once unloadDelay has expired, Tomcat continues with shut down. Any remaining in-flight requests are almost certain to see exceptions. If you have long running requests and you want a clean shutdown, you need to increase unloadDelay to > longest expected request processing time.
Comment From: wilkinsona
Thanks, Mark.
Exceptions being thrown seems reasonable to me, but I am surprised that Tomcat can get into a state where it will return values that, as far as I can tell, are not spec compliant from methods in the Servlet API. The place where things start going wrong is HttpServletRequest.getRequestURI(). Its javadoc makes no mention of null ever being returned. It would make code that uses the Servlet API quite a bit more complex to cope with null being returned. This complexity would increase further if tolerating null was only done during container shutdown which would seem like the right thing to do as that should be the only time at which it can occur.
Could an enhancement to Tomcat be considered so that code written to the Servlet spec doesn't experience different and undocumented behaviour during shutdown?
Comment From: markt-asf
Given the way the Tomcat internals work I think making better use of the hooks that are available to signal web application and/or server shutdown and ensuring that they are working as intended is the way to handle this. Is the request async or sync?
Comment From: wilkinsona
The request in the sample that's linked to above is sync but I believe the same problem will also occur with an async request.
Comment From: markt-asf
An async request should receive an AsyncListener.onTimeout() event. If it didn't - or it was too late - then that would be something we can look at. For sync events there is very little we can do since there is no mechanism in the Servlet spec to cancel an in-flight request. There is this open enhancement request (https://bz.apache.org/bugzilla/show_bug.cgi?id=59203) to call Thread.interrupt() which is probably the best we can do. The other answer for sync requests is to set the unloadDelay to > than the maximum sync request time. Generally, the expectation is that long running requests use the async API rather than the sync API.
Comment From: wilkinsona
Thanks, Mark. Let me try to recreate the problem with an async request. Sounds like my belief above may have been based on a faulty assumption.
Comment From: wilkinsona
My assumption was indeed faulty. Sorry. With an async request the NPE does not occur and everything shuts down cleanly.
Comment From: MenschNestor
I can confirm that the issue disappears when I set the unloadDelay to an appropriate value (longer than the sleep in the example). I had previously assumed that the sleep would be interrupted which would have made the request finish as well.
Comment From: wilkinsona
Thanks, @MenschNestor.
Given Tomcat's current behaviour, the ability to avoid the problem by tuning unloadDelay, and the recommendation to use async API, I don't think we should do anything here. To fully address the problem, we'd need changes in both Spring Framework and Spring Boot to handle null responses to Servlet API calls that should not return null and only do so when using Tomcat and then only in certain circumstances during shutdown.
Comment From: mlubavin-vg
Hi all, this is happening for me on a regular sync mvc request.
I followed this tutorial and added a jvm shutdown hook that calls tomcat connector to shutdown with waiting for long requests to finish. But right at the end of the long request I see this exception. Using unloadDelay has not helped at all, that seems to only help for async requests.
java.lang.NullPointerException: null
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.stopLongTaskTimers(LongTaskTimingHandlerInterceptor.java:120)
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.afterCompletion(LongTaskTimingHandlerInterceptor.java:77)
at org.springframework.web.servlet.HandlerExecutionChain.triggerAfterCompletion(HandlerExecutionChain.java:174)
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1425)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1059)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1005)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:897)
exception
Any other ideas would be appreciated.
Comment From: wilkinsona
Hi all, this is happening for me on a regular sync mvc request.
This is expected. The problem only occurs with sync requests. It does not occur with async requests. The recommendation remains to use async when a request may be long running. In a Spring MVC controller that can be achieved by returning a DeferredResult or similar.
Comment From: aheritier
@wilkinsona I just saw the same stacktrace (from my POV) in an application we are developing (spring-boot 2.3.1). Strangely it occurred multiple times (it's not when the app shutdowns) and we are using Undertow.
Like mentioned in this ticket I think it is related to a new end-point we wrote which is sync and should be async
2020-06-18 11:20:23.444 ERROR 1 --- [ XNIO-1 task-11] o.s.web.servlet.HandlerExecutionChain : HandlerInterceptor.afterCompletion threw exception
java.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:179)
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1427)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060)
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.doPost(FrameworkServlet.java:909)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:523)
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.web.multipart.support.MultipartFilter.doFilterInternal(MultipartFilter.java:125)
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.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:126)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:118)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:158)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:155)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:92)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
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.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.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
That's intriguing. Thank you, @aheritier. It does look like the same stack trace – I suspect the slightly different line numbers are just due to version differences. I wonder what has reset the request's attributes while it was still in-flight. Can you describe your sync-but-should-have-been-async request in a bit more detail, please? I'd like to try and reproduce the problem with Undertow so that we can verify my theory and learn what's clearing the attributes.
Comment From: aheritier
Here is the code a bit cleaned
@PostMapping(value = "/api/somewhere", produces = "application/json")
public ResponseEntity<SomeResult> upload(@RequestParam(value = "file") MultipartFile file) {
var version = buildProperties.getVersion();
try {
//CompletableFuture<Result> doSomething
return someService.doSomething(new SomethingElse(toSomething(file)))
.thenApply(result -> ResponseEntity.ok(new SomeResult(true, new MarkdownReportWriter(result).run(), SomeResult.AnalysisStatus.DONE, version)))
.exceptionally(e -> ResponseEntity.ok(new SomeResult(false, "", SomeResult.AnalysisStatus.ERROR, version)))
.join();
} catch (Exception e) {
return ResponseEntity.ok(new SomeResult(false, "", SomeResult.AnalysisStatus.NOT_A_FILE, version));
}
}
You see that our error is that we have an Async service (which can take several minutes to complete) which is converted to a Sync controller answer ... I am 99% sure that we will fix the issue by making the Controller Async (We'll test it tomorrow)
Comment From: aheritier
@wilkinsona FYI we updated the controller to be async and the error is gone ... I hope you will identify the issue and potentially have a fix. If someone get this error you should have a look at the duration of your request ...
Comment From: wilkinsona
Thanks again, @aheritier. I've spent some time trying to reproduce this in an app using Undertow and Spring Security. A request that takes 10 minutes completed successfully with no NullPointerException so I'm still stumped. We could protect against the attribute in the request being null, but that will leave some long task timers running. Can you share any more information about your app's configuration, the client making the request, etc?
Comment From: aheritier
@wilkinsona Fail we got again the issue :(
2020-06-19 21:05:20.399 ERROR 1 --- [ XNIO-1 task-2] o.s.web.servlet.HandlerExecutionChain : HandlerInterceptor.afterCompletion threw exception
java.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:179)
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1427)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060)
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.doPost(FrameworkServlet.java:909)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:523)
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.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.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:118)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:84)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:158)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
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.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:370)
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)
I will have to dig more. I can share with you privately the code of the project but not sure if it will help ?
Comment From: wilkinsona
I can share with you privately the code of the project but not sure if it will help ?
Yes please. It might not help, but, if you're happy to share the code, it certainly won't do any harm. If it's in a private repo on GitHub, could you add me as a collaborator please?
Comment From: aheritier
@wilkinsona I just shared with you few more details privately and the access to the code. From my POV the error happens a request process took a long time (10min) and the client connection was dropped (it received a 504 from the load balancer)
Comment From: urosht
Hi @wilkinsona , in the related issue #21557, I see you have opened a ticket for Undertow but we are experiencing this issue with Tomcat on 2 different apps (Spring Boot 2.1.6 and 2.2.1). Both started happening after we've included micrometer dependency for exporting metrics. 2 questions: - Will this issue be used to track the Tomcat and the other one Undertow? - Is there anything needed to help with the investigation?
Thanks
Comment From: wilkinsona
@urosht As far as we know, the problem only occurs in Tomcat during shutdown with a long-running synchronous response. As explained in this comment we are not planning to make any changes to address things with Tomcat. The problem can and should be avoided by using an async response via DeferredResult or similar and tuning the unload delay.
The Undertow problem is different as it can occur at any time if a client closes a connection to which the server was still writing data. This will have to be fixed in Undertow.
Comment From: carrypann
Hi @wilkinsona , is there any temporary solution to avoid NPE before Undertow's bug be fixed?
Comment From: wilkinsona
@pop0505 I don't believe so.
Comment From: doronl
@wilkinsona Seeing this exception in our logs... can we disable or replace the LongTaskTimingHandlerInterceptor? doesn't look trivial at first glance...
Comment From: wilkinsona
Rather than removing the interceptor, I think it would be better to diagnose and resolve the problem that's causing the NPE. The two causes of which we're aware are a bug in Undertow (which I think has been fixed by now) and a long-running sync request in Tomcat that should be replaced by an async request.
If you really want to remove the interceptor, I believe you could do so via a BeanFactoryPostProcessor that removes the metricsWebMvcConfigurer bean.
Comment From: doronl
Basically I agree with you but since it has been some time since this issue was first posted and there is no solution yet... I need to do something for our PR pipeline that runs integration tests on deployed services and checks if there are errors in logs, this error fails PR for us with no good reason, so I need to either silence the logger or remove the interceptor in the tests profile...
Below is my stacktrace (sring webmvc 5.3.14, spring boot 2.5.8) if it contributes anything new...
HandlerInterceptor.afterCompletion threw exception
java.lang.NullPointerException: Cannot invoke "org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor$LongTaskTimingContext.getLongTaskTimerSamples()" because "timingContext" is null
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.stopLongTaskTimers(LongTaskTimingHandlerInterceptor.java:133)
at org.springframework.boot.actuate.metrics.web.servlet.LongTaskTimingHandlerInterceptor.afterCompletion(LongTaskTimingHandlerInterceptor.java:83)
at org.springframework.web.servlet.HandlerExecutionChain.triggerAfterCompletion(HandlerExecutionChain.java:178)
at org.springframework.web.servlet.DispatcherServlet.triggerAfterCompletion(DispatcherServlet.java:1455)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1087)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:706)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:769)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:833)
Comment From: wilkinsona
@doronl It helps in that I can see that you're using Tomcat. You should ensure that you're using async requests and have tuned Tomcat's unload delay to meet your application's needs. Please review the comments earlier in this issue for further details.
Comment From: doronl
@wilkinsona OK, will give it a try, Thanks!
Comment From: doronl
@wilkinsona this might be a bit off topic, but is a result of suggested solution... when moving to @Async in the Controller when we call org.springframework.web.context.request.RequestContextHolder.getRequestAttributes() while the request it returns null and not the expected... is there any solution to this?
Comment From: wilkinsona
RequestContextHolder is thread-bound so it's to be expected that calling getRequestAttributes() from a non-web-request thread will return null. I would retrieve the attributes that you need in your controller before you initiate the async processing.