Documentation

Logback Trace Token Converter

Our Logback integration is extremely simple as it just provides a single converter that allows you to include the current trace token in your log patterns. The entire implementation looks like this:

class LogbackTraceTokenConverter extends ClassicConverter {

  def convert(event: ILoggingEvent): String =
    Tracer.currentContext.collect(_.token).getOrElse("undefined")
}

That doesn’t sound like a big deal, but there are many benefits that can be derived from logging the trace token from the currently available TraceContext in your application, let’s explore that idea with a simple example: suppose you have a process that involves a couple actors and you want to make sense of the logs generated by that process. The actors might look like this:

class UpperCaser extends Actor with ActorLogging {
  val lengthCalculator = context.actorOf(Props[LengthCalculator].withDispatcher("my-dispatcher"), "length-calculator")

  def receive = {
    case anyString: String =>
      log.info("Upper casing [{}]", anyString)
      lengthCalculator.forward(anyString.toUpperCase)
  }
}

class LengthCalculator extends Actor with ActorLogging {
  def receive = {
    case anyString: String =>
      log.info("Calculating the length of: [{}]", anyString)
  }
}
public static class UpperCaser extends UntypedActor {
    private final LoggingAdapter log = Logging.getLogger(getContext().system(), this);
    private final ActorRef lengthCalculator = context().actorOf(Props.create(LengthCalculator.class), "length-calculator");

    @Override
    public void onReceive(Object message) throws Exception {
      if(message instanceof String) {
        log.info("Upper casing [{}]", message);
        lengthCalculator.forward(((String) message).toUpperCase(), getContext());
      }
    }
  }

  public static class LengthCalculator extends UntypedActor {
    private final LoggingAdapter log = Logging.getLogger(getContext().system(), this);

    @Override
    public void onReceive(Object message) throws Exception {
      if(message instanceof String) {
        log.info("Calculating the length of: [{}]", message);
      }
    }
  }

If we spawn a UpperCaser actor and send it five string messages the log should contain something like this:

Example output without logging the trace token:

06:59:42.538 INFO  [undefined][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:42.541 INFO  [undefined][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:42.542 INFO  [undefined][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:42.543 INFO  [undefined][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:42.544 INFO  [undefined][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:42.545 INFO  [undefined][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:42.545 INFO  [undefined][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:42.545 INFO  [undefined][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:42.546 INFO  [undefined][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:42.546 INFO  [undefined][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]

Can you tell which log statement from the LengthCalculator actor corresponds to each log statement from UpperCaser actor?, seems easy to figure it out manually in this case, but as the number of events happening concurrently in your application grows it becomes harder to answer that question without some extra help. Let’s see how Kamon can help us in this situation:

// Send five messages with a TraceContext
  for(_ <- 1 to 5) {
    Tracer.withNewContext("simple-test") {
      upperCaser ! "Hello World with TraceContext"
    }
  }
// Send five messages with a TraceContext
    for(int i = 0; i < 5; i++) {
      Tracer.withNewContext("simple-test", () -> {
          upperCaser.tell("Hello without context", ActorRef.noSender());
          return null;
      });
    }

When using the TraceRecorder.withNewContext(..) method, Kamon will create a new TraceContext and make it available during the execution of the piece of code passed as argument. This time, we are sending a message to an actor which happens to be one of the situations under which Kamon will automatically propagate a TraceContext if you have the kamon-akka module in place, so we can expect the current context to be available to the actor when processing the message we just sent, and only when processing that message. Let’s repeat the exercise of sending five messages to this actor, now doing it with a new TraceContext each time and look at the log:

Example output logging the trace token:

06:59:43.533 INFO  [ivantopo-desktop-1][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:43.533 INFO  [ivantopo-desktop-1][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:43.534 INFO  [ivantopo-desktop-2][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:43.534 INFO  [ivantopo-desktop-3][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:43.534 INFO  [ivantopo-desktop-2][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:43.534 INFO  [ivantopo-desktop-3][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:43.534 INFO  [ivantopo-desktop-4][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:43.535 INFO  [ivantopo-desktop-4][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]
06:59:43.535 INFO  [ivantopo-desktop-5][akka://trace-token-logging/user/upper-caser] kamon.examples.java.TraceTokenLogging$UpperCaser - Upper casing [Hello without context]
06:59:43.535 INFO  [ivantopo-desktop-5][akka://trace-token-logging/user/upper-caser/length-calculator] kamon.examples.java.TraceTokenLogging$LengthCalculator - Calculating the length of: [HELLO WITHOUT CONTEXT]

Can you tell which log statement from LengthCalculator corresponds to each log statement from UpperCaser now?, it has become a no-brainer: each TraceContext created by Kamon gets a unique trace token that we are including in the log patterns (the first value between square brackets) and with that small but important piece of information the relation between each log line is absolutely clear.

Including the Trace Token in your Application Logs

Kamon has built in support for logging the trace token via the kamon.trace.logging.LogbackTraceTokenConverter converter for Logback, which is included in the kamon-core artifact but as you saw at the beginning of this section, it’s implementation is rather simple and you could easily port it to the equivalent in other logging toolkits.

To log the trace token with Logback, simply add the converter to your logback.xml configuration file and use it in your logging patterns as show bellow:

<configuration scan="true">
    <conversionRule conversionWord="traceToken" converterClass="kamon.trace.logging.LogbackTraceTokenConverter"/>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date{HH:mm:ss.SSS} %-5level [%traceToken][%X{akkaSource}] %logger{55} %X{X-ApplicationId} - %msg%n</pattern>
        </encoder>
    </appender>

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

</configuration>