Monday, November 10, 2014

rxjava, logback and MDC / ThreadLocal

Problem: logback tries to be smart and its MDC implementation uses InheritableThreadLocal. As a result MDC propagates to new threads from the parent thread.

This might work in simple scenarios, but fails completely when it comes to resizable thread pools. In such case threads in the pool are starting with MDC inherited from whichever thread caused the pool to grow.

Test code below creates 3 observables which log numbers every second. The expectation is that the observable uses the MDC values present in the "main" thread at the moment subscribe() is called
(Log format: "%-5p %X{requestId} [%d{ISO8601,UTC}] %c{25}: %m%n%rEx")
Output with some comments added:



Ok. Now how to solve it? Obviously we don’t want our observers to execute with effectively random MDC if we’re using it. Fortunately RxJava provides some mechanism allowing to fix this.

The missing piece is RxJavaSchedulersPlugin which I used to:
erase MDC of newly created threads
possibly fill MDC with necessary data before the call and erase afterwards


(note - this code is very similar to the one from here: https://groups.google.com/forum/#!msg/rxjava/9L04__vPCB8/va_yFR318eMJ, but it solves a different problem)

After registering the plugin:
RxJavaPlugins.getInstance().registerSchedulersHook(new RequestContextSchedulersHook());

The output looks better:
the copy of MDC for given action is made at the moment the observer/action is subscribed - that’s why third_observable is logging CCC. Following code is equivalent (without registering the plugin):


Other things to consider:

  • Making a copy of the context map every time might degrade performance. It might be better to explicitly wrap action with something that would handle MDC in situations requiring high-performance. In such case erasing MDC would still be required - can be done when scheduler thread is created - achievable through the same hook.
  • errors logged while handling the action, but outside of it (e.g. logging the exception caused by missing onError definition) have blank MDC
  • maybe it would be better to erase MDC in new threads and always set it explicitly?


4 comments:

  1. This post saved me a lot of time. Thank you very much.

    ReplyDelete
  2. Isn't there a concern that calling MDC.clear() could happen on the main thread if you didn't appropriately schedule it to another pool? I would think this would lead to undersireable behavior.

    ReplyDelete
    Replies
    1. I think it could be a problem, but it should be possible protect from this situation by comparing the current thread inside WrappedAction0.call() with the one which created WrappedAction0

      Delete