Thread-unsafe usage of HttpServletResponse corrupting jetty HttpFields state in reactive ResponseBodyEmitter handlers

[SpComb]

Affects: 5.2.5.RELEASE

---

We have a Spring Web MVC + jetty application using SSE for notifications. We recently converted our SSE controller from returning a SseEmitter to returning a Flux<ServerSentEvent<?>>, whereupon we started seeing sporadic NullPointerExceptions from jetty Response.setHeader calls for something on the order of 0.02% of requests for these SSE endpoints:

2020-05-12 11:15:53.837|WARN|1|qtp453671855-27|||org.eclipse.jetty.server.HttpChannel|MAIN||||/...
java.lang.NullPointerException: null
	at org.eclipse.jetty.http.HttpFields.put(HttpFields.java:630) ~[jetty-http-9.4.20.v20190813.jar!/:9.4.20.v20190813]
	at org.eclipse.jetty.http.HttpFields.put(HttpFields.java:658) ~[jetty-http-9.4.20.v20190813.jar!/:9.4.20.v20190813]
	at org.eclipse.jetty.server.Response.setHeader(Response.java:582) ~[jetty-server-9.4.20.v20190813.jar!/:9.4.20.v20190813]
	at javax.servlet.http.HttpServletResponseWrapper.setHeader(HttpServletResponseWrapper.java:203) ~[javax.servlet-api-3.1.0.jar!/:3.1.0]
	at org.springframework.security.web.firewall.FirewalledResponse.setHeader(FirewalledResponse.java:49) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.header.writers.frameoptions.XFrameOptionsHeaderWriter.writeHeaders(XFrameOptionsHeaderWriter.java:99) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
   ....

Looking at the jetty HttpFields implementation, these NPEs seem to be caused by a corrupted internal _fields state containing nulls.

With jetty 9.4.20 these exceptions cause the connection to be aborted, but with newer version of jetty (at least 9.4.27) these corrupted HttpFields put the jetty HttpChannel into a busyloop that crashes the entire server: jetty/jetty.project#4860

Investigating the underlying NPE issue together with the jetty maintainers we were unable to find any direct calls to the jetty APIs that would introduce null values in the HttpFields state, but looking at the implementation of the jetty HttpFields structure used in Response.setHeaders/addHeaders etc, it is suspectible to internal state corruption if called concurrently from multiple threads, and is documented as non-threadsafe:

* <p>This class is not synchronized as it is expected that modifications will only be performed by a
* single thread.

This kind of corruption caused by concurrent multi-threaded accesses also matches up with our observation of very rarely occuring state corruption/crashes. And indeed, using jdb to trace calls to these header-related methods for a single HTTP request, I can see calls from multiple different threads!

Some of the calls are from the jetty server thread, via the servlet filter chain, which is the correct usage:

  [1] org.eclipse.jetty.server.Response.addHeader (Response.java:627)
  [2] javax.servlet.http.HttpServletResponseWrapper.addHeader (HttpServletResponseWrapper.java:212)
  [3] org.springframework.security.web.firewall.FirewalledResponse.addHeader (FirewalledResponse.java:55)
  [4] javax.servlet.http.HttpServletResponseWrapper.addHeader (HttpServletResponseWrapper.java:212)
  [5] org.springframework.security.web.util.OnCommittedResponseWrapper.addHeader (OnCommittedResponseWrapper.java:63)
  [6] org.springframework.web.cors.DefaultCorsProcessor.processRequest (DefaultCorsProcessor.java:63)
  [7] org.springframework.web.servlet.handler.AbstractHandlerMapping$CorsInterceptor.preHandle (AbstractHandlerMapping.java:582)
  [8] org.springframework.web.servlet.HandlerExecutionChain.applyPreHandle (HandlerExecutionChain.java:141)
  [9] org.springframework.web.servlet.DispatcherServlet.doDispatch (DispatcherServlet.java:1,035)
  [10] org.springframework.web.servlet.DispatcherServlet.doService (DispatcherServlet.java:943)
  [11] org.springframework.web.servlet.FrameworkServlet.processRequest (FrameworkServlet.java:1,006)
  [12] org.springframework.web.servlet.FrameworkServlet.doGet (FrameworkServlet.java:898)
  [13] javax.servlet.http.HttpServlet.service (HttpServlet.java:687)
  [14] org.springframework.web.servlet.FrameworkServlet.service (FrameworkServlet.java:883)
  [15] javax.servlet.http.HttpServlet.service (HttpServlet.java:790)
  [16] org.eclipse.jetty.servlet.ServletHolder.handle (ServletHolder.java:755)
  [17] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,617)
  [18] com.example.common.audit.MDCLogFilter.doFilter (MDCLogFilter.java:67)
  [19] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,604)
  [20] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:320)
  [21] org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke (FilterSecurityInterceptor.java:126)
  [22] org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter (FilterSecurityInterceptor.java:90)
  [23] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [24] org.springframework.security.web.access.ExceptionTranslationFilter.doFilter (ExceptionTranslationFilter.java:118)
  [25] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [26] org.springframework.security.web.session.SessionManagementFilter.doFilter (SessionManagementFilter.java:137)
  [27] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [28] org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter (AnonymousAuthenticationFilter.java:111)
  [29] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [30] org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter (SecurityContextHolderAwareRequestFilter.java:158)
  [31] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [32] com.example.common.auth.WhitelistIpAuthenticationFilter.doFilter (WhitelistIpAuthenticationFilter.java:37)
  [33] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [34] org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal (BasicAuthenticationFilter.java:204)
  [35] org.springframework.web.filter.OncePerRequestFilter.doFilter (OncePerRequestFilter.java:119)
  [36] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [37] com.example.common.auth.StatelessAuthenticationFilter.doFilter (StatelessAuthenticationFilter.java:49)
  [38] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [39] org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter (HeaderWriterFilter.java:92)
  [40] org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal (HeaderWriterFilter.java:77)
  [41] org.springframework.web.filter.OncePerRequestFilter.doFilter (OncePerRequestFilter.java:119)
  [42] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [43] org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter (SecurityContextPersistenceFilter.java:105)
  [44] org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter (FilterChainProxy.java:334)
  [45] org.springframework.security.web.FilterChainProxy.doFilterInternal (FilterChainProxy.java:215)
  [46] org.springframework.security.web.FilterChainProxy.doFilter (FilterChainProxy.java:178)
  [47] org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate (DelegatingFilterProxy.java:358)
  [48] org.springframework.web.filter.DelegatingFilterProxy.doFilter (DelegatingFilterProxy.java:271)
  [49] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,604)
  [50] org.springframework.web.filter.RequestContextFilter.doFilterInternal (RequestContextFilter.java:100)
  [51] org.springframework.web.filter.OncePerRequestFilter.doFilter (OncePerRequestFilter.java:119)
  [52] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,604)
  [53] org.springframework.web.filter.FormContentFilter.doFilterInternal (FormContentFilter.java:93)
  [54] org.springframework.web.filter.OncePerRequestFilter.doFilter (OncePerRequestFilter.java:119)
  [55] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,604)
  [56] org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal (WebMvcMetricsFilter.java:109)
  [57] org.springframework.web.filter.OncePerRequestFilter.doFilter (OncePerRequestFilter.java:119)
  [58] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,604)
  [59] org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal (CharacterEncodingFilter.java:201)
  [60] org.springframework.web.filter.OncePerRequestFilter.doFilter (OncePerRequestFilter.java:119)
  [61] org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter (ServletHandler.java:1,604)
  [62] org.eclipse.jetty.servlet.ServletHandler.doHandle (ServletHandler.java:545)
  [63] org.eclipse.jetty.server.handler.ScopedHandler.handle (ScopedHandler.java:143)
  [64] org.eclipse.jetty.security.SecurityHandler.handle (SecurityHandler.java:590)
  [65] org.eclipse.jetty.server.handler.HandlerWrapper.handle (HandlerWrapper.java:127)
  [66] org.eclipse.jetty.server.handler.ScopedHandler.nextHandle (ScopedHandler.java:235)
  [67] org.eclipse.jetty.server.session.SessionHandler.doHandle (SessionHandler.java:1,610)
  [68] org.eclipse.jetty.server.handler.ScopedHandler.nextHandle (ScopedHandler.java:233)
  [69] org.eclipse.jetty.server.handler.ContextHandler.doHandle (ContextHandler.java:1,300)
  [70] org.eclipse.jetty.server.handler.ScopedHandler.nextScope (ScopedHandler.java:188)
  [71] org.eclipse.jetty.servlet.ServletHandler.doScope (ServletHandler.java:485)
  [72] org.eclipse.jetty.server.session.SessionHandler.doScope (SessionHandler.java:1,580)
  [73] org.eclipse.jetty.server.handler.ScopedHandler.nextScope (ScopedHandler.java:186)
  [74] org.eclipse.jetty.server.handler.ContextHandler.doScope (ContextHandler.java:1,215)
  [75] org.eclipse.jetty.server.handler.ScopedHandler.handle (ScopedHandler.java:141)
  [76] org.eclipse.jetty.server.handler.StatisticsHandler.handle (StatisticsHandler.java:173)
  [77] org.eclipse.jetty.server.handler.HandlerWrapper.handle (HandlerWrapper.java:127)
  [78] org.eclipse.jetty.server.Server.handle (Server.java:500)
  [79] org.eclipse.jetty.server.HttpChannel.lambda$handle$1 (HttpChannel.java:383)
  [80] org.eclipse.jetty.server.HttpChannel$$Lambda$1167.1412565883.dispatch (null)
  [81] org.eclipse.jetty.server.HttpChannel.dispatch (HttpChannel.java:547)
  [82] org.eclipse.jetty.server.HttpChannel.handle (HttpChannel.java:375)
  [83] org.eclipse.jetty.server.HttpConnection.onFillable (HttpConnection.java:273)
  [84] org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded (AbstractConnection.java:311)
  [85] org.eclipse.jetty.io.FillInterest.fillable (FillInterest.java:103)
  [86] org.eclipse.jetty.io.ChannelEndPoint$2.run (ChannelEndPoint.java:117)
  [87] org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask (EatWhatYouKill.java:336)
  [88] org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce (EatWhatYouKill.java:313)
  [89] org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce (EatWhatYouKill.java:171)
  [90] org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce (EatWhatYouKill.java:135)
  [91] org.eclipse.jetty.io.ManagedSelector$$Lambda$1140.431966204.run (null)
  [92] org.eclipse.jetty.util.thread.QueuedThreadPool.runJob (QueuedThreadPool.java:806)
  [93] org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run (QueuedThreadPool.java:938)
  [94] java.lang.Thread.run (Thread.java:834)

However, there are also calls to addHeader from the ThreadPoolExecutor used in the spring framework ResponseBodyEmitterReturnValueHandler implementation, via the org.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$SseEmitterSubscriber:

  [1] org.eclipse.jetty.server.Response.addHeader (Response.java:627)
  [2] javax.servlet.http.HttpServletResponseWrapper.addHeader (HttpServletResponseWrapper.java:212)
  [3] org.springframework.security.web.firewall.FirewalledResponse.addHeader (FirewalledResponse.java:55)
  [4] javax.servlet.http.HttpServletResponseWrapper.addHeader (HttpServletResponseWrapper.java:212)
  [5] org.springframework.security.web.util.OnCommittedResponseWrapper.addHeader (OnCommittedResponseWrapper.java:63)
  [6] org.springframework.http.server.ServletServerHttpResponse.lambda$writeHeaders$0 (ServletServerHttpResponse.java:104)
  [7] org.springframework.http.server.ServletServerHttpResponse$$Lambda$1241.488706756.accept (null)
  [8] java.util.Map.forEach (Map.java:661)
  [9] org.springframework.http.server.ServletServerHttpResponse.writeHeaders (ServletServerHttpResponse.java:102)
  [10] org.springframework.http.server.ServletServerHttpResponse.getBody (ServletServerHttpResponse.java:83)
  [11] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$StreamingServletServerHttpResponse.getBody (ResponseBodyEmitterReturnValueHandler.java:278)
  [12] org.springframework.http.converter.StringHttpMessageConverter.writeInternal (StringHttpMessageConverter.java:122)
  [13] org.springframework.http.converter.StringHttpMessageConverter.writeInternal (StringHttpMessageConverter.java:44)
  [14] org.springframework.http.converter.AbstractHttpMessageConverter.write (AbstractHttpMessageConverter.java:227)
  [15] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal (ResponseBodyEmitterReturnValueHandler.java:210)
  [16] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send (ResponseBodyEmitterReturnValueHandler.java:203)
  [17] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal (ResponseBodyEmitter.java:189)
  [18] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send (ResponseBodyEmitter.java:183)
  [19] org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send (SseEmitter.java:126)
  [20] org.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$SseEmitterSubscriber.send (ReactiveTypeHandler.java:365)
  [21] org.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$AbstractEmitterSubscriber.run (ReactiveTypeHandler.java:308)
  [22] java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1,128)
  [23] java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
  [24] java.lang.Thread.run (Thread.java:834)

Looking at the code, the ResponseBodyEmitter created by the ResponseBodyEmitterReturnValueHandler/ReactiveTypeHandler should not be writing any HTTP response headers outside of the extendResponse called in the servlet thread, but the ReactiveTypeHandler subscription's SseEmitter.send call in the TaskExecutor thread is also invoking ServletServerHttpResponse.writeHeaders via the HttpMessageConvertingHandler.sendInternal. EDIT: see comment below on spring-security HeaderWriterFilter behavior instead

Complete error log and jdb traces atttached:

• 20200508-jetty-httpfields-npe-busyloop.txt
• 20200512-spring-reactive-unsafe-headers.txt

EDIT: edited stack traces to censor custom package names; use the first task-9 thread stack from the jdb traces as the example

[SpComb]

Also just to confirm that it's the same jetty Response being called from the two threads: the _fields: instance of org.eclipse.jetty.http.HttpFields(id=13856) matches across both threads

Breakpoint hit: "thread=task-24", org.eclipse.jetty.server.Response.addHeader(), line=627 bci=0

task-24[1] where
  [1] org.eclipse.jetty.server.Response.addHeader (Response.java:627)
  [2] javax.servlet.http.HttpServletResponseWrapper.addHeader (HttpServletResponseWrapper.java:212)
  [3] org.springframework.security.web.firewall.FirewalledResponse.addHeader (FirewalledResponse.java:55)
  [4] javax.servlet.http.HttpServletResponseWrapper.addHeader (HttpServletResponseWrapper.java:212)
  [5] org.springframework.security.web.util.OnCommittedResponseWrapper.addHeader (OnCommittedResponseWrapper.java:63)
  [6] org.springframework.http.server.ServletServerHttpResponse.lambda$writeHeaders$0 (ServletServerHttpResponse.java:104)
  [7] org.springframework.http.server.ServletServerHttpResponse$$Lambda$1241.488706756.accept (null)
  [8] java.util.Map.forEach (Map.java:661)
  [9] org.springframework.http.server.ServletServerHttpResponse.writeHeaders (ServletServerHttpResponse.java:102)
  [10] org.springframework.http.server.ServletServerHttpResponse.getBody (ServletServerHttpResponse.java:83)
  [11] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$StreamingServletServerHttpResponse.getBody (ResponseBodyEmitterReturnValueHandler.java:278)
  [12] org.springframework.http.converter.StringHttpMessageConverter.writeInternal (StringHttpMessageConverter.java:122)
  [13] org.springframework.http.converter.StringHttpMessageConverter.writeInternal (StringHttpMessageConverter.java:44)
  [14] org.springframework.http.converter.AbstractHttpMessageConverter.write (AbstractHttpMessageConverter.java:227)
  [15] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal (ResponseBodyEmitterReturnValueHandler.java:210)
  [16] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send (ResponseBodyEmitterReturnValueHandler.java:203)
  [17] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal (ResponseBodyEmitter.java:189)
  [18] org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send (ResponseBodyEmitter.java:183)
  [19] org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send (SseEmitter.java:126)
  [20] org.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$SseEmitterSubscriber.send (ReactiveTypeHandler.java:365)
  [21] org.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$AbstractEmitterSubscriber.run (ReactiveTypeHandler.java:308)
  [22] java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1,128)
  [23] java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
  [24] java.lang.Thread.run (Thread.java:834)
task-24[1] dump this
 this = {
    LOG: instance of org.eclipse.jetty.util.log.Slf4jLog(id=13840)
    __MIN_BUFFER_SIZE: 1
    __EXPIRES_01JAN1970: instance of org.eclipse.jetty.http.PreEncodedHttpField(id=13841)
    SET_INCLUDE_HEADER_PREFIX: "org.eclipse.jetty.server.include."
    _channel: instance of org.eclipse.jetty.server.HttpChannelOverHttp(id=13855)
    _fields: instance of org.eclipse.jetty.http.HttpFields(id=13856)
    _errorSentAndIncludes: instance of org.eclipse.jetty.util.AtomicBiInteger(id=13857)
    _out: instance of org.eclipse.jetty.server.HttpOutput(id=13858)
    _status: 200
    _reason: null
    _locale: null
    _mimeType: null
    _characterEncoding: null
    _encodingFrom: instance of org.eclipse.jetty.server.Response$EncodingFrom(id=13846)
    _contentType: null
    _outputType: instance of org.eclipse.jetty.server.Response$OutputType(id=13847)
    _writer: null
    _contentLength: -1
    _trailers: null
    __localeOverride: instance of java.util.RegularEnumSet(id=13848)
    __explicitCharset: instance of java.util.RegularEnumSet(id=13849)
}
task-24[1] cont

Breakpoint hit: "thread=qtp761680655-29", org.eclipse.jetty.server.Response.setHeader(), line=577 bci=0

qtp761680655-29[1] dump this 
 this = {
    LOG: instance of org.eclipse.jetty.util.log.Slf4jLog(id=13840)
    __MIN_BUFFER_SIZE: 1
    __EXPIRES_01JAN1970: instance of org.eclipse.jetty.http.PreEncodedHttpField(id=13841)
    SET_INCLUDE_HEADER_PREFIX: "org.eclipse.jetty.server.include."
    _channel: instance of org.eclipse.jetty.server.HttpChannelOverHttp(id=13855)
    _fields: instance of org.eclipse.jetty.http.HttpFields(id=13856)
    _errorSentAndIncludes: instance of org.eclipse.jetty.util.AtomicBiInteger(id=13857)
    _out: instance of org.eclipse.jetty.server.HttpOutput(id=13858)
    _status: 200
    _reason: null
    _locale: null
    _mimeType: null
    _characterEncoding: null
    _encodingFrom: instance of org.eclipse.jetty.server.Response$EncodingFrom(id=13846)
    _contentType: "text/event-stream"
    _outputType: instance of org.eclipse.jetty.server.Response$OutputType(id=13860)
    _writer: null
    _contentLength: -1
    _trailers: null
    __localeOverride: instance of java.util.RegularEnumSet(id=13848)
    __explicitCharset: instance of java.util.RegularEnumSet(id=13849)
}
qtp761680655-29[1] cont

[SpComb]

Looking at the code, the ResponseBodyEmitter created by the ResponseBodyEmitterReturnValueHandler/ReactiveTypeHandler should not be writing any HTTP response headers outside of the extendResponse called in the servlet thread, but the ReactiveTypeHandler subscription's SseEmitter.send call in the TaskExecutor thread is also invoking ServletServerHttpResponse.writeHeaders via the HttpMessageConvertingHandler.sendInternal.

Looking a little further, that analysis of how the async servlet request/filter response header processing works isn't exactly correct. The ResponseBodyEmitterReturnValueHandler.handleReturnValue -> SseEmitter.extendResponse isn't writing any response headers, they're just being passed to the HttpMessageConvertingHandler in the outputMessage, and I suppose the expected behavior is for the servlet request to be handed off to the async handler thread for writing?

I suppose the key to reproducing this issue is probably our use of spring-security, and the HeaderWriterFilter in particular... the problematic code path involves doHeadersAfter conditionally invoking writeHeaders based on the OnCommittedResponseWrapper's onResponseCommitted() state... I guess that's what actually racing here, causing both the HeaderWriterFilter running in the jetty servlet thread's filter chain as well as the ServletServerHttpResponse used in the async handler thread to race and both set the servlet response headers concurrently?

java.lang.NullPointerException: null
	at org.eclipse.jetty.http.HttpFields.put(HttpFields.java:630) ~[jetty-http-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.http.HttpFields.put(HttpFields.java:658) ~[jetty-http-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.Response.setHeader(Response.java:592) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at javax.servlet.http.HttpServletResponseWrapper.setHeader(HttpServletResponseWrapper.java:203) ~[javax.servlet-api-3.1.0.jar!/:3.1.0]
	at org.springframework.security.web.firewall.FirewalledResponse.setHeader(FirewalledResponse.java:49) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.header.writers.frameoptions.XFrameOptionsHeaderWriter.writeHeaders(XFrameOptionsHeaderWriter.java:99) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.header.HeaderWriterFilter.writeHeaders(HeaderWriterFilter.java:100) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.header.HeaderWriterFilter$HeaderWriterResponse.writeHeaders(HeaderWriterFilter.java:139) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:94) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178) ~[spring-security-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:109) ~[spring-boot-actuator-2.2.6.RELEASE.jar!/:2.2.6.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.5.RELEASE.jar!/:5.2.5.RELEASE]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590) ~[jetty-security-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485) ~[jetty-servlet-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:173) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.Server.handle(Server.java:500) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) ~[jetty-server-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[jetty-io-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[jetty-io-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[jetty-io-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) ~[jetty-util-9.4.27.v20200227.jar!/:9.4.27.v20200227]
	at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

[navdeepsekhon]

@SpComb we faced the same issue recently. What I found was that we had two web configurations one for @EnableWebSecurity and one for @EnableWebMvc which were interfering with each other. The solution that worked for us was to headers().disable() in @EnableWebSecurity

@Override
protected void configure(HttpSecurity http) throws Exception{

http.headers().disable()...;

Hope this helps

[rstoyanchev]

I'm a little confused. On the one hand you say:

We recently converted our SSE controller from returning a SseEmitter to returning a Flux<ServerSentEvent<?>>, whereupon we started seeing sporadic NullPointerExceptions

On the other hand, the stacktraces and the explanations are about SseEmitter.

[rstoyanchev]

Never mind, I see now.

So we subscribe immediately to the Flux and start writing from a scheduled thread (to avoid blocking the Flux). Meanwhile, as the main thread is on its way out of the filter chain, Spring Security also tries to write to the headers, is this correct?

@rwinch can you take a look at the stacktrace for Spring Security. What I don't understand is how it could write a header reliably after the DispatcherServlet given that the response may have been committed? Perhaps there are some checks or guards missing.

[SpComb]

Never mind, I see now.

Yes, the ReactiveTypeHandler adapts the Flux<ServerSentEvent<?>> into a SseEmitter.

So we subscribe immediately to the Flux and start writing from a scheduled thread (to avoid blocking the Flux). Meanwhile, as the main thread is on its way out of the filter chain, Spring Security also tries to write to the headers, is this correct?

That is my interpretation. My understanding is that this issue is down to how async servlet responses and servlet filter chains interact, but my knowledge of async servlet processing is too weak to say how it should be fixed.

@rwinch can you take a look at the stacktrace for Spring Security. What I don't understand is how it could write a header reliably after the DispatcherServlet given that the response may have been committed? Perhaps there are some checks or guards missing.

The org.springframework.security.web.util.OnCommittedResponseWrapper used by the spring security header filter shows up in the ReactiveTypeHandler's flux thread, so I suppose it's attempting to intercept the response-committing, but that logic is also racing between the jetty servlet filter thread and the flux thread?

[rwinch]

@rstoyanchev It looks like @SpComb analysis is correct. Spring Security's OnComittedResponseWrapper is detecting that the response is about to be committed, so it then tries to write the headers before allowing the operation that commits the response.

I'm curious what happens if you set HeaderWriterFilter.shouldWriteHeadersEagerly = true using something like this:

@Override
protected void configure(HttpSecurity http) throws Exception {
	http
		.headers(headers -> headers
			.withObjectPostProcessor(new ObjectPostProcessor<HeaderWriterFilter>() {
				@Override
				public HeaderWriterFilter postProcess(HeaderWriterFilter headerWriterFilter) {
					headerWriterFilter.setShouldWriteHeadersEagerly(true);
					return headerWriterFilter;
				}
			})
		)
...

This ensures the headers are written immediately. However, this can cause problems with cache control. In particular if someone overrides the cache control header to anything but Cache-Control: no-cache, no-store, max-age=0, must-revalidate Pragma: no-cache it can cause issues since Spring Security will also attempt to set other cache related headers like Expires: 0. The problem is that servlet spec allows the value of a header to be overridden, but not removed (which is what should happen).

[rstoyanchev]

@rwinch so if I understand correctly what happens is this. For a Flux<ServerSentEvent> we subscribe immediately and when values are published, we switch to a different thread to absorb the blocking write. The first write commits the response and Spring Security's FirewalledResponse gets involved via OnCommittedResponseWrapper. In the mean time we are also exiting the Servlet container thread and in the filter chain FirewalledResponse gets involved as well, possibly in parallel.

Assuming the cause for the NPE is this attempt to set the same header from two threads, I'm not quite sure what we can do in the Spring Framework to protect. Synchronizing in ServletServerHttpResponse#writeHeaders won't help against races with any other uses of the HttpServletResponse that don't go through the ServletServerHttpResponse wrapper. It seems that such synchronization would be more effective in Spring Security which aims to intercept both the case where a commit occurs and also the case of exiting the filter chain. As is the case here those two could compete with each other.

@SpComb I wonder if you've tried again after the fix for jetty/jetty.project#4860, has that changed anything for your case?

[joakime]

At a minimum, the FirewalledResponse should be aware of the value on HttpServletResponse.isCommitted() not attempt to do anything if that returns true (indicating the response is committed and no header manipulation is now possible)

[Chr3is]

Any new information about this issue? We're affected by this as well and we can't use the mentioned fix by @rwinch because we use cache-control.

[SpComb]

The problematic spring backend in our case did not need to override any Cache-Control headers, so we were able to deploy the headerWriterFilter.setShouldWriteHeadersEagerly(true) workaround. We can confirm that we are no longer seeing these NPEs as a result.