<div dir="ltr"><span style="font-size:12.8px">Greetings Logback community,</span><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">I'm one of the maintainers of Dropwizard, a Java REST service library. We're dealing with an race condition that may have something to do with Logback and I wanted to reach out to see if our issue smells like anything the Logback team has encountered before.</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">We've been trying to diagnose a small handful of related bugs that all seem to stem from a race condition somewhere within the interaction between Jetty's request-handling lifecycle, Logback's RequestLogImpl, and Logback's async appender functionality. My best assessment of the issue is as follows.</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Jetty defines a Request class to encapsulate state specific to a single request (i.e. HTTP headers, query parameters, etc). Jetty servers reuse instances of this Request class for each connection (presumably in order to reduce memory pressure), and thus requests have to be <a href="http://download.eclipse.org/jetty/9.3.11.v20160721/apidocs/org/eclipse/jetty/server/Request.html" target="_blank">recycled</a> for each individual HTTP request.</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">We seem to get into trouble when Logback's RequestLogImpl is used in conjunction with AsyncAppenderBase. <a href="https://github.com/qos-ch/logback/blob/master/logback-access/src/main/java/ch/qos/logback/access/spi/AccessEvent.java#L576" target="_blank">`AccessEvent#<wbr>prepareForDeferredProcessing`</a>,<wbr> which populates the event with request data, is invoked by both of these codepaths. Could it be possible that Jetty's use of a mutable Request object per connection could be getting in the way of asynchronous request logging by Logback?</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">For the complete background, the bug(s) span the following Dropwizard issues:</div><div style="font-size:12.8px"><ul><li style="margin-left:15px"><a href="https://github.com/dropwizard/dropwizard/issues/1672" target="_blank">https://github.com/dropwizard/<wbr>dropwizard/issues/1672</a></li><li style="margin-left:15px"><a href="https://github.com/dropwizard/dropwizard/issues/1686" target="_blank">https://github.com/dropwizard/<wbr>dropwizard/issues/1686</a><br></li><li style="margin-left:15px"><a href="https://github.com/dropwizard/dropwizard/issues/1699" target="_blank">https://github.com/dropwizard/<wbr>dropwizard/issues/1699</a><br></li></ul><div>Unfortunately, we don't have a single representative test case to illustrate the issue. In this latter GitHub issue (#1699), Nick Babcock and I traded notes back and forth as we spelunked through Dropwizard, Jetty, and Logback trying to root out the issue, and found that forcing synchronous request logging prevented the inconsistent behavior.</div><div><br></div><div>Any guidance on Logback usage related to this would be a very helpful.</div><div><br></div><div>Thanks,</div></div><div><br></div>-- <br><div class="gmail_signature">Evan Meagher</div>
</div>