Seeking help with Logback-related race condition in Dropwizard

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
participants (1)
-
Evan Meagher