Purpose

In web application logs, messages come from different users and requests. When a problem occurs, it can be difficult to determine which ones are related to the issue, especially under load.

In traditional Java development models (e.g. Spring or Java EE), the server implements a one thread per request design. As a consequence, it is possible to store contextual data in ThreadLocal variables and use it when logging. Both logback and log4j2 name this Mapped Diagnostic Context (MDC).

Vert.x implements the reactor pattern. In practice, this means many concurrent requests can be handled by the same thread, thus preventing usage of ThreadLocals to store contextual data.

This project uses an alternative storage method for contextual data and makes it possible to have MDC logging in Vert.x applications.

Supported logging libraries

  • Logback

  • Log4j2

  • JUL

How it works

Vert.x 4.0 introduced a Tracing SPI. To transport distributed traces information, a new localContext data map is attached to standard and worker contexts.

This library:

  • uses the localContext data map to store contextual data

  • implements logging extensions that retrieve contextual data from the localContext data map

Dependency setup

Maven

<dependency>
  <groupId>io.reactiverse</groupId>
  <artifactId>reactiverse-contextual-logging</artifactId>
  <version>1.2.1</version>
</dependency>

Gradle Kotlin DSL

implementation("io.reactiverse:reactiverse-contextual-logging:1.2.1")

Gradle Groovy DSL

implementation 'io.reactiverse:reactiverse-contextual-logging:1.2.1'

Usage

Configuration

Logback

Declare the converter class and assign it a conversion word:

<conversionRule conversionWord="vcl"
                converterClass="io.reactiverse.contextual.logging.LogbackConverter"/>

Then use the conversion word in conversion patterns:

<pattern>%d{HH:mm:ss.SSS} [%thread] [%vcl{requestId}] %-5level %logger{36} - %msg%n</pattern>

In the example above, the requestId will be added to the logs.

A default value can be provided:

%vcl{requestId:-foobar}

In this case, foobar will be added to the logs if:

  • the requestId is missing in contextual data, or

  • the logger is used on a non Vert.x thread.

Below is a sample Logback configuration:

<configuration>

  <conversionRule conversionWord="vcl"
                  converterClass="io.reactiverse.contextual.logging.LogbackConverter"/>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] [%vcl{requestId}] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="STDOUT"/>
  </root>

</configuration>

Log4j2

With Log4j2, you can either use:

Pattern Converter

The Log4j2 pattern converter is configured automatically. It works like the Logback converter, except the conversion word is fixed to vcl.

Below is a sample Log4j2 configuration:

<Configuration status="INFO">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout>
        <pattern>%d{HH:mm:ss.SSS} [%thread] [%vcl{requestId}] %-5level %logger{36} - %msg%n</pattern>
      </PatternLayout>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="INFO">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>
</Configuration>
Context Data Provider

The context data provider supplies log4j2 logging events with contextual data. The data can then be retrieved using context map lookups.

To enable the provider, create a META-INF/services/org.apache.logging.log4j.core.util.ContextDataProvider file which this content:

io.reactiverse.contextual.logging.VertxContextDataProvider
Comparison

The pattern converter:

  • can only be used in pattern layouts

  • is only invoked if the appender actually writes event data to the destination

The context data provider:

JUL

With JUL, the converter is a formatter that follows the SimpleFormatter implementation. JUL parameters are located by index, not name, however this formatter allows referring to them by name using the extended format:

%{nameOfVariable}

Be aware that JUL reserves the following variable names:

  • date

  • source

  • logger

  • level

  • message

  • thrown

Optionally a default value is allowed to be given using the :- suffix:

%{nameOfVariable:-defaultValue}

In order to format the value itself, follow the standard formatter rules, for example to format as String:

%{nameOfVariable:-defaultValue}$s

To add it to any kind of Handler just specify the class JULContextualDataFormatter as the handler Formatter.

handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.formatter=io.reactiverse.contextual.logging.JULContextualDataFormatter
io.reactiverse.contextual.logging.JULContextualDataFormatter.format="%{requestId:-foobar}$s ### %5$s%n"

Saving values in the contextual data map

Import the io.reactiverse.contextual.logging.ContextualData class.

In the server implementation, store contextual data when the request is received:

vertx.createHttpServer().requestHandler(req -> {
  String requestId = generateId(req);
  ContextualData.put("requestId", requestId);

  log.info("Received HTTP server request");

  // ... handle request
  httpClient.request(HttpMethod.GET, "/my-service")
    .compose(HttpClientRequest::send)
    .compose(HttpClientResponse::body)
    .onComplete(ar -> {

      // ... requestId is still present in contextual data map here
      log.info("Received HTTP client response");

    });
}).listen(8080);

In Vert.x Web applications, it is possible to create a catch-all route for this and add it at the top of the router setup.

Propagation

Contextual data is restored when asynchronous result handlers are invoked. For example, it is restored when using the Vert.x:

  • Web Client

  • Mongo Client

  • Cassandra Client

  • SQL Clients (PostgreSQL, MySQL)

  • …​ etc

It’s also restored when a timer fires or when a task is submitted to executeBlocking or completes.

However, contextual data is not propagated over the EventBus. In this case, it must be:

  • added to message headers on the sender side

  • retrieved from headers and saved again on the receiver side

This process can be automated with EventBus interceptors:

vertx.eventBus().addOutboundInterceptor(event -> {
  String requestId = ContextualData.get("requestId");
  if (requestId != null) {
    event.message().headers().add("requestId", requestId);
  }
  event.next();
});

vertx.eventBus().addInboundInterceptor(event -> {
  String requestId = event.message().headers().get("requestId");
  if (requestId != null) {
    ContextualData.put("requestId", requestId);
  }
  event.next();
});

License

Apache License version 2.0.