[logback-user] Seeking help with Logback-related race condition in Dropwizard

[Evan Meagher]

Greetings Logback community,

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.

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.

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 recycled
<http://download.eclipse.org/jetty/9.3.11.v20160721/apidocs/org/eclipse/jetty/server/Request.html>
for
each individual HTTP request.

We seem to get into trouble when Logback's RequestLogImpl is used in
conjunction with AsyncAppenderBase. `AccessEvent#
prepareForDeferredProcessing`
<https://github.com/qos-ch/logback/blob/master/logback-access/src/main/java/ch/qos/logback/access/spi/AccessEvent.java#L576>
, 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?

For the complete background, the bug(s) span the following Dropwizard
issues:

   - https://github.com/dropwizard/dropwizard/issues/1672
   - https://github.com/dropwizard/dropwizard/issues/1686
   - https://github.com/dropwizard/dropwizard/issues/1699

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.

Any guidance on Logback usage related to this would be a very helpful.

Thanks,

-- 
Evan Meagher
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20160924/7c7f4bcb/attachment.html>