Structured Logging with Play Framework

Introduction

Text logs are unstructured and this makes them simple but also harder to query. You need to write a grok parser which can be a nightmare especially because you need to update the parser whenever you want to add extra details in logs. Using structured logs with JSON has become a standard as popular tools such as Datadog and Kibana made analyzing logs very easy. In this article, we are going to look into how to output JSON logs with Logback in PlayFramework. However these examples are unique to Play, they can be used with any other API framework too.

Logback JSON Encoder

Play Framework already ships with Logback and defaults to text output. We need to add logstash-logback-encoder to build.sbt to enable JSON logging.

libraryDependencies += "net.logstash.logback" % "logstash-logback-encoder" % "5.3"

This library requires jackson-databind, jackson-core and jackson-annotations. These should already be included from Play but make sure the versions required by logstash-logback-encoder matches with the ones that come with Play.

After this configure the logger.xml to use the new encoder like this:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
</appender>

And output a message

Logger logger = LoggerFactory.getLogger("application");
logger.info("hello");

Logback will start to print logs in JSON format in one line:

{
  "@timestamp": "2021-02-25T21:10:29.178+01:00",
  "@version": 1,
  "message": "hello",
  "logger_name": "application",
  "thread_name": "Thread-1",
  "level": "INFO",
  "level_value": 20000
}

JSON logs are great for log aggregation tools to analyze but it can be hard to read in a dev environment when you don't have a tool enabled. You can create a different log config and pass that in sbt start task to use in tests and development that outputs string logs with this flag:

-Dlogger.resource=test-logger.xml

Customising Logging

Logstash logback encoder provides default fields such as @timestamp, logger_name and stack_trace. You can rename these easily. Some

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
      <fieldNames>
         <timestamp>time</timestamp>
         <logger>loggerName</logger>
         <thread>threadName</thread>
         <stackTrace>stacktrace</stackTrace>
      </fieldNames>
   </encoder>
</appender>

You can also remove fields:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
      <fieldNames>
         <version>[ignore]</version>
      </fieldNames>
   </encoder>
</appender>

Logger will output all config items application.conf and any other default ones. This makes the log massive and you don't really need these in the log output. This can be disabled using context:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
  <includeContext>false</includeContext>
  ...
</encode>

You can also add global key values in logback config:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
  <customFields>{"appname":"helloWorld", "environment":"production"}</customFields>
</encoder>

Using structured arguments

You can easily add extra details in your logs.

import static net.logstash.logback.argument.StructuredArguments.keyValue;

logger.info("GET /cats 200", keyValue("duration", "12ms"), keyValue("referer", "http://foo.bar"));

The output will include default fields and the extra fields we added:

{
   "time": "2021-02-10T22:12:58.011+00:00",
   ...
   "message": "GET /cats 200",
   "duration": "12ms",
   "referrer": "http://foo.bar"
}

Summary

Producing logs in JSON format makes it easier to analyze logs using popular tools such as Kibana and adding more structured information logs becomes simple.