Using MDC with SLF4J

[Garrick Olson]

I have been seeing problems while trying to use the MDC class provided as part of the SLF4J API. The logging provider is Log4J.

The MDC appears to work correctly at first, propagating keys and values from the event thread to worker threads when I call executeBlocking(). Eventually, however, when a worker gets reused, the original MDC appears to dominate over any new values that should be set.

Here is a test case to illustrate what I mean:

import io.vertx.core.Vertx;
import io.vertx.ext.unit.Async;
import io.vertx.ext.unit.TestContext;
import io.vertx.ext.unit.junit.VertxUnitRunner;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

/**
 * Make sure the SLF4J MDC feature behaves well with Vertx.
 */
@RunWith(VertxUnitRunner.class)
public class LogMdcTest {
  private Logger log = LoggerFactory.getLogger(LogMdcTest.class);
  int times = 0;

  @Test
  public void testMdcTransferToWorker(TestContext context) {
    Async async = context.async();

    Vertx vertx = Vertx.vertx();
    vertx.createHttpServer()
        .requestHandler(r -> {
//          context.assertNull(MDC.getCopyOfContextMap());
          MDC.put("userId", "joe");
          MDC.put("requestId", "1");
          log.debug("Request before blocking: " + MDC.getCopyOfContextMap());
          vertx.executeBlocking(f -> {
            log.debug("Request inside blocking: " + MDC.getCopyOfContextMap());
            context.assertEquals("joe", MDC.get("userId"));
            context.assertEquals("1", MDC.get("requestId"));
            f.complete();
          }, result -> {
            log.debug("Request after blocking: " + MDC.getCopyOfContextMap());
            context.assertEquals("joe", MDC.get("userId"));
            context.assertEquals("1", MDC.get("requestId"));
            r.response().end();
          });
        }).listen(8101, server -> {
          vertx.createHttpClient().get(8101, "localhost", "/foo").handler(response ->
              context.assertEquals(200, response.statusCode())
          ).end();
        });

    vertx.setPeriodic(100, id -> {
      // Make sure we repeat enough times to cycle through all workers
      if (times++ > 100) {
        async.complete();
      }
//      context.assertNull(MDC.getCopyOfContextMap());
      MDC.put("userId", "<server>");
      log.debug("Timer before blocking: " + MDC.getCopyOfContextMap());
      vertx.executeBlocking(f -> {
        log.debug("Timer inside blocking: " + MDC.getCopyOfContextMap());
        context.assertEquals("<server>", MDC.get("userId"));
        context.assertNull(MDC.get("requestId"));
      }, result -> {
        log.debug("Timer after blocking: " + MDC.getCopyOfContextMap());
        context.assertEquals("<server>", MDC.get("userId"));
        context.assertNull(MDC.get("requestId"));
      });
    });
  }
}

When I run this, it fails because eventually the periodic timer runs with the worker originally run as "joe", and in this case the worker continues to run as "joe", disregarding the "<server>" value from the calling event thread:

[vert.x-eventloop-thread-0] joe 1 Request before blocking: {userId=joe, requestId=1}

[vert.x-worker-thread-0] joe 1 Request inside blocking: {userId=joe, requestId=1}

[vert.x-eventloop-thread-0] joe 1 Request after blocking: {userId=joe, requestId=1}

[vert.x-eventloop-thread-1] <server>  Timer before blocking: {userId=<server>}

[vert.x-worker-thread-1] <server>  Timer inside blocking: {userId=<server>}

[vert.x-eventloop-thread-1] <server>  Timer after blocking: {userId=<server>}

...snip Timer stuff for other worker threads...

[vert.x-eventloop-thread-1] <server>  Timer before blocking: {userId=<server>}

[vert.x-worker-thread-0] joe 1 Timer inside blocking: {userId=joe, requestId=1}

[vert.x-eventloop-thread-1] <server>  Timer after blocking: {userId=<server>}

java.lang.AssertionError: Not equals : <server> != joe

Any ideas how to avoid this behavior?

Thanks,

Garrick

[shailender arya]

+1. I want to log all the requests with a unique request Id across verticles so that With every log i can trace where all it went and what all happened to that request

[Clement Escoffier]

Hi,

The behavior you see is the expected one. MDC use a thread local to store the data (http://logback.qos.ch/manual/mdc.html), however, this is definitely not recommended in vert.x as the thread can be used by different tasks, and so MDC values may be overridden. 

In addition in your case, the function passed to the executeBlocking construct runs in a a worker thread, different from the caller thread, so MDC would not work there. 

Clement

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/9e562d37-90bf-4b8b-88c6-a76c02628b18%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Clement Escoffier]

Hi,

If you are using the Vert.x Web Request Context, you can add data in this context using `put` and retrieve this data in your log using `get` or `data`. You can even have a Route Handler setting some data, and having the other handlers consuming it. That’s one way to have some kind of MDC equivalent.

Clement

On 27 mai 2016, at 07:27, shailender arya <arya.sh...@gmail.com> wrote:

[Garrick Olson]

In case it helps others, I ended up working around it by wrapping the executeBlocking() calls:

https://github.com/susom/database/blob/master/src/main/java/com/github/susom/database/VertxUtil.java

https://github.com/susom/database/blob/master/src/test/java/com/github/susom/database/test/VertxLoggingTest.java

Of course it isn't a general solution, and you have to call these alternative executeBlocking() everywhere, but hopefully there aren't very many of those calls.

[Dominic Rübelzahn]

MCD can't be used and the logging framework does not have access to the context Clement mentioned.

One other dirty way arround could be (only works for your own code!):
* Add own logger
** Use vertx logger as delegate
* Extend your logger to accept required parameter
** Add that paramater to the delegate array parameter
* Create own converter (for logback) that extracts data from array into new variable
* Configure logging to have the variable in logging pattern

This works pretty good for us so far. But - as mentioned already - only for your own code where you use your own logger. Else the variable is always empty or however you implemented the converter.

[Amit Ranjan]

@Dominic, Do you have an example code on this ?