The benefits of structured logging

Introduction

Applications that you build should always have logging. During your systems development life cycle you should be thinking about what could I log to help present and future developers understand what the code is doing. Logging is very important for identifying errors and bugs in your production applications. Logs can also provide you with much-needed insight when you are building and running your applications in a development environment as well.

This post is to give you an introduction into structured logging and how it can make your lives easier when the time comes for you to search your logs.

If you would like to follow along you can find the source code here.

Technology used

• Java
• Spring Boot
• Maven
• AWS Cloudwatch

Why use structured logging?

The main difference between structured logging and unstructured logging is the former is machine-readable, but the latter is human-readable. This distinction becomes relevant when you need a system to search your logs. At the end of the day this will be a machine and not a human being.

The machine would need to aggregate and parse your applications logs so formatting logs in our application in a data structure and not plain text is key. In this example we will be using JSON that, at the time of writing this, is the most common format. It’s handy that JSON is also easy for a human being to read.

Here is an example of a plain text log:

13:57:29.827 [main] INFO com.beardeddeveloper.structuredlogging
.StructuredLoggingApplication - Order successful. User ID 1234. 
Order ID 9876. Total sale value: 12.67.

You can see there is some interesting information in this log if we wanted to search on the user ID, order ID or aggregate the total sale price this would be difficult without first telling our logging software how to parse this log.

Here is an example of the same log but in a JSON format we want to get to:

{
   "@timestamp":"2021-03-22T14:54:13.843Z",
   "@version":"1",
   "message":"Order successful",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000,
   "userId":1234,
   "orderId":9876,
   "totalSaleValue":12.67
}

The user ID, order ID and total sale value are properties in the JSON rather than as a string in the message. This will make it easier to search than the text log. We will be able to target the property we want to search against without having to target it in our text log. We could also aggregate the total sale value over a certain period if we wanted.

Structured logging in Spring Boot

Create a project

The first thing you need to do is create a new Spring Boot application. The easiest way to do this is by using the Spring Boot Initializr, if you already have a project you can skip this step.

Create a log

Inside the main method of the application class create a logger using the logger factory and add an info log. For example:

@SpringBootApplication
public class StructuredLoggingApplication {

	private static final Logger logger = LoggerFactory.getLogger(StructuredLoggingApplication.class);

	public static void main(String[] args) {
		logger.info("Order successful. User ID 1234. Order ID 9876. Total sale price: 12.67.");
		SpringApplication.run(StructuredLoggingApplication.class, args);
	}
}

Run the application you will see this log printed out in the console as text.

Add Logstash JSON encoder as a dependency

We need to bring in the Logstash JSON encoder that will give us what we need to configure our application to log in JSON.

Add the following dependency to your pom.xml.

<dependency>
  <groupId>net.logstash.logback</groupId>
  <artifactId>logstash-logback-encoder</artifactId>
  <version>6.6</version>
</dependency>

Configure logback to use JSON

Create a logback.xml file in your resources directory if you don’t have one already and add the following configuration.

<configuration>
    <appender name="jsonConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
    </appender>
    <root level="INFO">
        <appender-ref ref="jsonConsoleAppender"/>
    </root>
</configuration>

This is all we need to turn our text logs in to JSON logs.

Run the application again, and you will see the same log message but this time is will be in a JSON format.

{
   "@timestamp":"2021-03-22T14:28:02.274Z",
   "@version":"1",
   "message":"Order successful. User ID 1234. Order ID 9876. Total sale value: 12.67.",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000
}

This is a good start, but we can do better. It would be ideal if the user ID, order ID and total sale value are properties of the JSON.

Use structure arguments in our log

We can change our log line to look like this.

logger.info("Order successful", kv("userId", 1234), kv("orderId", 9876), kv("totalSaleValue", 12.67));

The function kv stands for key value and is part of the structured arguments package provided by logback. This takes the first argument, the key, as the property name in the JSON, and the second argument, the value as the value of the property in the JSON.

The resulting log line will be.

{
   "@timestamp":"2021-03-22T14:54:13.843Z",
   "@version":"1",
   "message":"Order successful",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000,
   "userId":1234,
   "orderId":9876,
   "totalSaleValue":12.67
}

There are some other ways we can get variables into our logs which may come in useful depending on the scenario.

We can write the key and value to the message as well as adding properties to the JSON. You can do this with the following log line.

logger.info("Order successful {} {} {}", kv("userId", 1234), kv("orderId", 9876), kv("totalSaleValue", 12.67));

This will give the following log.

{
   "@timestamp":"2021-03-22T20:46:54.998Z",
   "@version":"1",
   "message":"Order successful userId=1234 orderId=9876 totalSaleValue=12.67",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000,
   "userId":1234,
   "orderId":9876,
   "totalSaleValue":12.67
}

If you need a custom format you can pass in a third argument to kv to define your own format for the log message.

logger.info("Order successful {} {} {}", kv("userId", 1234, "{0} equals {1}"), kv("orderId", 9876, "{0} equals {1}"), kv("totalSaleValue", 12.67, "{0} equals {1}"));

This would log the following.

{
   "@timestamp":"2021-03-27T21:39:38.041Z",
   "@version":"1",
   "message":"Order successful userId equals 1234 orderId equals 9876 totalSaleValue equals 12.67",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000,
   "userId":1234,
   "orderId":9876,
   "totalSaleValue":12.67
}

You can also log a value object to a property of the JSON. For example.

// Definition of value object
public class Order {

    private final int userId;
    private final int orderId;
    private final BigDecimal totalSaleValue;

    public Order(int userId, int orderId, BigDecimal totalSaleValue) {
        this.userId = userId;
        this.orderId = orderId;
        this.totalSaleValue = totalSaleValue;
    }

    public int getUserId() {
        return userId;
    }

    public int getOrderId() {
        return orderId;
    }

    public BigDecimal getTotalSaleValue() {
        return totalSaleValue;
    }
}

// Log line
Order order = new Order(1234, 9876, new BigDecimal("12.67"));
logger.info("Order successful", kv("order", order));

This will log the following.

{
   "@timestamp":"2021-03-22T21:20:03.027Z",
   "@version":"1",
   "message":"Order successful",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000,
   "order":{
      "userId":1234,
      "orderId":9876,
      "totalSaleValue":12.67
   }
}

You can log just the value to the log message while still putting the key and value into the JSON structure.

logger.info("Order successful {} {} {}", v("userId", 1234), v("orderId", 9876), v("totalSaleValue", 12.67));

This will give you the following log.

{
   "@timestamp":"2021-03-27T21:03:01.588Z",
   "@version":"1",
   "message":"Order successful 1234 9876 12.67",
   "logger_name":"com.beardeddeveloper.structuredlogging.StructuredLoggingApplication",
   "thread_name":"main",
   "level":"INFO",
   "level_value":20000,
   "userId":1234,
   "orderId":9876,
   "totalSaleValue":12.67
}

Searching our structured logs

Now that we have logging coming from our application lets take a look at some examples of queries we might use when querying our logs using AWS Cloudwatch Insights.

Let’s say we wanted to get all logs associated to a particular user. We can use the following query.

fields @timestamp, @message
| filter userId = 1234
| sort @timestamp desc
| limit 20

We can also search for all logs associated with a particular order.

fields @timestamp, @message
| filter orderId = 9876
| sort @timestamp desc
| limit 20

There we have it. This was a high level introduction of what we can do with structured logging in Java. Thank you for visiting, I hope you found this useful.

Recommended reading

• Logback documentation