SpComb
commented
4 years ago 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] contBreakpoint 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
navdeepsekhon
rstoyanchev
rwinch
joakime
Chr3is
waschmittel
AhrazA
ogaltsov
2is10
WeihmannDev
jwedel
tomasged
oleg-astakhov
jtaub
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
SseEmitterto returning aFlux<ServerSentEvent<?>>, whereupon we started seeing sporadicNullPointerExceptions from jettyResponse.setHeadercalls for something on the order of 0.02% of requests for these SSE endpoints:Looking at the jetty
HttpFieldsimplementation, these NPEs seem to be caused by a corrupted internal_fieldsstate containingnulls.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
HttpFieldsput the jettyHttpChannelinto a busyloop that crashes the entire server: https://github.com/eclipse/jetty.project/issues/4860Investigating the underlying NPE issue together with the jetty maintainers we were unable to find any direct calls to the jetty APIs that would introduce
nullvalues in theHttpFieldsstate, but looking at the implementation of the jettyHttpFieldsstructure used inResponse.setHeaders/addHeadersetc, it is suspectible to internal state corruption if called concurrently from multiple threads, and is documented as non-threadsafe: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
jdbto 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~:
However, there are also calls to
addHeaderfrom theThreadPoolExecutorused in the spring frameworkResponseBodyEmitterReturnValueHandlerimplementation, via theorg.springframework.web.servlet.mvc.method.annotation.ReactiveTypeHandler$SseEmitterSubscriber:~Looking at the code, the
ResponseBodyEmittercreated by theResponseBodyEmitterReturnValueHandler/ReactiveTypeHandlershould not be writing any HTTP response headers outside of theextendResponsecalled in the servlet thread, but theReactiveTypeHandlersubscription'sSseEmitter.sendcall in theTaskExecutorthread is also invokingServletServerHttpResponse.writeHeadersvia theHttpMessageConvertingHandler.sendInternal.~ EDIT: see comment below on spring-security HeaderWriterFilter behavior insteadComplete error log and
jdbtraces atttached:EDIT: edited stack traces to censor custom package names; use the first
task-9thread stack from the jdb traces as the example