New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix request attribute-related race condition in Logback request logging #1678

Merged
merged 2 commits into from Aug 9, 2016

Conversation

Projects
None yet
4 participants
@evnm
Member

evnm commented Aug 7, 2016

Addresses #1672

i.d.request.logging.async.AsyncAccessEventAppenderFactory invokes AccessEvent. prepareForDeferredProcessing, which triggers a race with an identical invocation within Logback itself. The reported issue indicates that the race manifests in inconsistent logging behavior when request attributes are set within a resource class.

This change removes the prepareForDeferredProcessing call from dropwizard-request-logging. As far as I know, all IAccessEvents encountered by this class will be of concrete type AccessEvent and all non-async appenders extend OutputStreamAppender, so the prepareForDeferredProcessing method should always be invoked exactly once.

@coveralls

This comment has been minimized.

coveralls commented Aug 7, 2016

Coverage Status

Coverage increased (+0.02%) to 82.423% when pulling d968d6a on evnm:dropwizard-request-logging/logback-attr-map-race-condition into 1e40fef on dropwizard:master.

@arteam

This comment has been minimized.

Member

arteam commented Aug 9, 2016

It's very strange to step on those thread-safety issues with Logback (or the SLF4J bridge). Let's see if the fix helps, I even don't known how to write a unit to reproduce it.

event.prepareForDeferredProcessing();
}
};
return new AsyncAppenderBase<IAccessEvent>();

This comment has been minimized.

@arteam

arteam Aug 9, 2016

Member

Could you please also update the Javadoc for this method? In looks a lit bit wrong for me.

  • It should link to AsyncAppenderBase rather than to AsyncAppenderFactory (not-related issue to this change)
  • I think we should remove a claim about deferred processing.

This comment has been minimized.

@evnm

evnm Aug 9, 2016

Member

Definitely, thanks for mentioning. It would be nice to collapse this and io.dropwizard.logging.async.AsyncLoggingEventAppenderFactory into a single class parameterized on the type of event, since they're now almost identical. This would be a breaking change, though.

I took the liberty of updating AsyncLoggingEventAppenderFactory's Javadoc too, since it also incorrectly links to AsyncAppenderFactory.

@coveralls

This comment has been minimized.

coveralls commented Aug 9, 2016

Coverage Status

Coverage increased (+0.02%) to 82.41% when pulling 77eb5f8 on evnm:dropwizard-request-logging/logback-attr-map-race-condition into e077d2c on dropwizard:master.

@arteam arteam merged commit e7c16c9 into dropwizard:master Aug 9, 2016

@arteam

This comment has been minimized.

Member

arteam commented Aug 9, 2016

Thanks, @evnm!

@arteam

This comment has been minimized.

Member

arteam commented Aug 9, 2016

Cherry-picked to the 1.0,x branch.

@evnm evnm referenced this pull request Aug 12, 2016

Closed

Inconsistent request logging #1686

@jplock jplock added the bug label Aug 13, 2016

@jplock jplock added this to the 1.1.0 milestone Aug 13, 2016

arteam added a commit that referenced this pull request Sep 23, 2016

Revert "Merge pull request #1678 from evnm/dropwizard-request-logging…
…/logback-attr-map-race-condition"

This reverts commit e7c16c9, reversing
changes made to e077d2c.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment