Logback instrumentation broken with with logback-classic 1.4.x

[nvollmar]

The new implementation which addressed #1212 does not properly work.
I've extended an internal test and there is about 50/50 chance that the mdc values are attached to the log or not. On deployed systems we see a similar behaviour.

The new LogbackMDCAdapter implementation uses two thread locals to store the MDC map, and getPropertyMap is only one entry point for it. There are also get/getKeys and put to access those properties.
I'm not yet sure where it exactly fails, but it seems to at least work when the property map is not yet set:

appendContext:66, ContextToMdcPropertyMapAppender$ (jaso.commons.kamon.instrumentation)
appendContext:-1, ContextToMdcPropertyMapAppender (jaso.commons.kamon.instrumentation)
getPropertyMap:146, LogbackMDCAdapter (ch.qos.logback.classic.util)
getMDCPropertyMap:410, LoggingEvent (ch.qos.logback.classic.spi)
prepareForDeferredProcessing:256, LoggingEvent (ch.qos.logback.classic.spi)
preprocess:45, AsyncAppender (ch.qos.logback.classic)
preprocess:29, AsyncAppender (ch.qos.logback.classic)
append:165, AsyncAppenderBase (ch.qos.logback.core)
doAppend:85, UnsynchronizedAppenderBase (ch.qos.logback.core)
appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi)
appendLoopOnAppenders:272, Logger (ch.qos.logback.classic)
callAppenders:259, Logger (ch.qos.logback.classic)
buildLoggingEventAndAppend:426, Logger (ch.qos.logback.classic)
filterAndLog_2:419, Logger (ch.qos.logback.classic)
error:535, Logger (ch.qos.logback.classic)
$anonfun$route$2:274, RemoteHTTPServerStub (jaso.commons.akka.http)
....

(This is a stack trace where it worked, I copied over the latest implementation to play around)

[nvollmar]

@ivantopo I've reverted back to the original intercept implementation but switched interception to LoggingEvent.getMDCPropertyMap instead of LogbackMDCAdapter.getPropertyMap:

  onType("ch.qos.logback.classic.spi.LoggingEvent")
    .intercept(method("getMDCPropertyMap"), GetPropertyMapMethodInterceptor)

This seems to work reliably on both Logback 1.2.10 and 1.4.5

[ivantopo]

Hey @nvollmar, thanks so much for bringing this up! Just to be sure on something, did you have this issue even when using the setting included on #1236? That would be:

kanela.modules.play-framework.order = 3

There were some random problems due to initialization order, but those should have been fixed after adding this setting.

[ivantopo]

@nvollmar see this comment too: #1234 (comment)

[nvollmar]

@ivantopo We don’t use play, we build directly on plain Akka.

[ivantopo]

Thanks for sharing @nvollmarl, I gave it a try on a few applications locally and worked as expected 💪

[ivantopo]

Fixed in #1252