Dazed & Confused

Logs are an essential tool for monitoring and observing system behavior in test and especially production. They provide a wealth of detailed information and are particularly useful for troubleshooting complex issues. When other tools fall short, logs are where you turn to uncover the root cause of problems.

Single log statements are important, but the true power of logs lies in being able to comprehend the information across statements. Connect them across various dimensions like requests, users, instances or countries.

Let me show you how to configure Logback to get even more data and information to analyze.

Subscribe for updates:

This configuration is for Logback, but it should be possible in most logging tools. If your tool cannot do this, consider switching to something that can. 🙂

Logs are not designed to store information forever. If this information is vital for your business, consider storing it in a database or long term metrics.

1. Log to JSON

It all starts with JSON. Structured data is much easier to analyze and search than regular log lines. You can use the following tips without JSON formatting, but then you need to add each and every one (MDC/Marker) into the output format. 🙂

Most logging tools (Links to: Splunk, Grafana/Loki) now have efficient tools for writing queries against JSON data. So start logging to JSON and query better (than just string matching).

Your favorite framework for development (Spring etc) might have a feature for enabling this, but if not, this is the basics for configuring Logback without a framework:

implementation("net.logstash.logback:logstash-logback-encoder:7.3")

<?xml version="1.1" encoding="UTF-8"?>
<configuration>
    <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <includeMdc>true</includeMdc>
        </encoder>
    </appender>


    <root level="INFO">
        <appender-ref ref="JSON"/>
    </root>
</configuration>

After this you should get output like this in your logs:

{
  "@timestamp": "2023-06-17T13:41:01.134+01:00",
  "@version": "1",
  "message": "Hello World",
  "logger_name": "no.f12.application",
  "userId": "user-id-something",
  "documentId": "document-id",
  "documentType": "legal",
  "thread_name": "somethread",
  "level": "INFO",
  "level_value": 20000
}

Notice the userId, documentId, documentType attributes added. Those are MDC and Marker values. Read on to figure out how to add them. 🙂

If you miss the old format you can have different output in tests, and even output the old to a file. Just remember to log JSON in your environments. 🙂

2. Use the Mapped Diagnostic Context to add contextual information

The Mapped Diagnostic Context (MDC) is a powerful tool in logging, allowing you to add contextual information to log statements. When you put something in the MDC, it will be automatically added to all log statements in the same thread or request. This feature can greatly enhance the clarity and usefulness of your log output, providing additional context for troubleshooting and analysis.

Most servers and frameworks should have automatic support for managing MDC. Some can also add extra information, like this KTor example or something similar in Spring Boot. If you can not find a default support in your tool all you have to do (in a filter or just in the controller) is:

MDC.put("userId", headers.getUserIdFromJwt())

Voila! It will be included with the other log statements related to that request. You can write a query in your preferred log tool to display all log entries for the past hour for a particular user. Just remember to review the documentation regarding clean up if you are not using the support in your framework or server.

MDC.put("traceId", headers.getTraceId())

If you look at the JSON configuration above I have added the includeMdc parameter to the JSON output. That way any MDC parameters are automatically added to the log statements.

3. Use Logback Markers to add structured data to a log-statement

Just like MDC, Markers is Logbacks way of adding additional data to a log statement. But this only applies to that specific statement, where you usually have more specific data than at places in your code where you do MDC.

It works best with JSON (again automatically added as noted before), and it opens up possibilities for querying and analysis.

To add additional data to a log statement:

// Kotlin helpers for creating a map of key, value
val markers = Markers.appendEntries(mapOf(
  "documentId" to document.id,
  "documentType" to document.type
))
logger.info(markers, "Document retrieved")

This requires a dependency like this:

implementation("net.logstash.logback:logstash-logback-encoder:7.4")

And you will get it added to the JSON structure for querying. Here’s the output example again:

{
  "@timestamp": "2023-06-17T13:41:01.134+01:00",
  "@version": "1",
  "message": "Hello World",
  "logger_name": "no.f12.application",
  "userId": "user-id-something",
  "documentId": "document-id",
  "documentType": "legal",
  "thread_name": "somethread",
  "level": "INFO",
  "level_value": 20000
}

To Marker or not?

It may be a bit unclear what sets Markers and MDC apart, as they both serve similar purposes. Don’t worry, though, as you’ll understand which one to use as you gain more experience them.

Generally, I recommend to start with MDC. You can use it in situations such as “we’re currently updating the document with id” or “this payment is being processed now.”

On the other hand, Markers are suitable when you only require the details provided by a single log statement.

They are both powerful tools. Good luck. 🙂

What’s your favorite tips for logging? Let me know in the comments below.