Support for adding values to the MDC later on in the pipeline.

[alacoste]

Hi and thanks for this powerful library. In advance, apologies if I misunderstood some of the mechanics I describe here.

Currently, the CallLogging feature creates a "Logging" phase inserted before "Monitoring" and intercepts it to setup the MDC context for the rest of the pipeline with:

pipeline.intercept(loggingPhase) {
  withMDC {
    proceed()
    feature.logSuccess(call)
  }
}

This makes the MDC nicely available in all the sub-coroutines for reading. However any manual modification to the context in the rest of the pipeline is lost on suspension, making it effectively read-only. From what I understand, this is expected and similar to the caveat described in the kotlinx documentation about ThreadLocal & coroutines

As a result, it very hard to add values to the MDC that are not trivially available during the Logging phase. In our use-case, these are:

• The id of the user making the request (it is computed during the authentication phase).
• The graphql operation requested by the user (it is computed in the routing phase as our graphql library parses the request).

I will try to find a hacky way to handle this for now, but it seems to me that the general use-case (of adding additional data to the MDC context later-on in the pipeline) is legitimate and it would be great to have "native" ktor support for it!

[ColinHebert]

@cy6erGn0m or @alacoste, have we got a workaround for this?

[alacoste]

@cy6erGn0m or @alacoste, have we got a workaround for this?

I've found a very hack and unfortunately only partial workaround.

Looking into ktor implementation, what they do is (https://github.com/ktorio/ktor/blob/master/ktor-server/ktor-server-core/jvm/src/io/ktor/features/CallLogging.kt#L131):

pipeline.intercept(loggingPhase) {
  withMDC {
    proceed()
    feature.logSuccess(call)
  }
}

The withMDC lambda block uses its custom MDCSurvivalElement (https://github.com/ktorio/ktor/blob/master/ktor-server/ktor-server-core/jvm/src/io/ktor/features/CallLogging.kt#L194), which is very similar to kotlinx's MDCContext (https://github.com/Kotlin/kotlinx.coroutines/blob/master/integration/kotlinx-coroutines-slf4j/src/MDCContext.kt#L42).

It ensures that inside this block, all the coroutines (the one running the block and any child ones it starts) will get their thread-local MDC state restored to a fixed value upon being resumed on a new thread.

And (kind of guessing here) because proceed() moves on to the next step of the pipeline without exiting this current lambda block all of the pipeline gets executed inside that MDC-restoring context.

This is also the reason why adding things directly to the MDC context (MDC.put(...)) doesn't work: this mechanism will reset the MDC state pretty much as soon as the coroutine gets suspended.

To add "persistent" state to the MDC we can do something very similar to what ktor does.

pipeline.intercept(some phase after you computed a value you want to add to the MDC) {
  withContext(MDCContext(MDC.getCopyOfContextMap() + your added context)) {
    proceed()
  }
}

Why is it hacky: MDCSurvivalElement and MDCContext are effectively fighting to each set the MDC state. It seems to work but this is contingent to the order in which these two apply luckily being the right one. Ideally we'd reuse MDCSurvivalElement but it's private.

Why is it only a partial workaround:

• The first "proceed" will execute last, so the ktor logging will happen outside of our custom MDC block. So the logging of the call done by ktor's CallLogging will not have access to our added MDC context (however any logging before that will).
• We can't just add a value as we compute it, we need can only add it at the end of the phase it is computed in (and it may take some effort to intercept exactly the correct phase "right after this one"). This proved particularly bad for us as the authentication that identified our user happens in routing, so I couldn't get it to be available during routing which is essential to error reporting, etc...

For all of these reasons making my hack less-than-ideal, we resorted to a different "workaround" where our frontend passes these values we care about in the request, so we can use ktor's implementation as-is for the meantime.

[oleg-larshin]

Please check the following ticket on YouTrack for follow-ups to this issue. GitHub issues will be closed in the coming weeks.

[e5l]

Fixed in 2.0.0

[matteosimone]

@e5l, could you add a note or link on how to achieve this in 2.0.0? As a new-ish user, I am having trouble finding how I would achieve this