Structured logging in Spring Boot with Log4j2, Part 2: Logging objects

Logging structured objects with Log4j using ObjectMessage

In my previous post, we explored how to achieve structured logging in Spring Boot with Log4j2. As we saw, log aggregation tools such as DataDog, Kibana, etc. usually allow for indexing, filtering, or querying of logs structured as a JSON object.

In that post, however, all of our logs just recorded a simple string as their message property. For example, if we ran the following:

log.info("Database connection successful!");

We would see logs such as (simplified):

{"level":"INFO","message":"Database connection successful"}

While the message “Database connection successful!” was itself wrapped in a larger structured object wrapper, the message itself is still only a simple string.

In this post, we’ll cover how to log structured data, as opposed to just simple string messages.

Logging structured objects

Building on our Order application example from Part 1, let’s say that we want to log out the total items retrieved, as well as the items themselves for further analysis, so that we can use our logs to answer questions such as “What kinds of order items are typically present in orders with more than 5 items?’

Ideally we would be able to run a filter on our logs to find messages where message.totalItems > 5, and then inspect the filtered log messages to see what was present in an itemsarray logged with those messages.

The easiest way to do this in Log4j is to log an ObjectMessage , whose constructor takes any java object. For example, if we add a simple wrapper class with two propertiestotalItems and items , we can then log an ObjectMessage with an instance of that class:

{
  "instant" : {
    "epochSecond" : 1641661845,
    "nanoOfSecond" : 325499000
  },
  "thread" : "http-nio-8080-exec-1",
  "level" : "INFO",
  "loggerName" : "com.zachelrath.springboot.structuredloggingdemo.OrderController",
  "message" : "items=\"[com.zachelrath.springboot.structuredloggingdemo.OrderItem@5b1da447]\" totalItems=\"1\"",
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
  "contextMap" : {
    "orderNumber" : "123",
    "retailer" : "acme"
  },
  "threadId" : 24,
  "threadPriority" : 5
}

Yikes — that message property looks pretty gross.. what’s going on?

By default, when using Log4j’s JsonLayout, Log4j outputs ObjectMessage instances— basically any message which is not a simple string — as a stringified representation of the message. I’m not sure why this is the default, but, it’s pretty easy to fix. You just have to add the property objectMessageAsJsonObject="true" to your JsonLayout in your log4j2.xml file (documentation here):

<JsonLayout complete="false" compact="false" eventEol="true" properties="true" objectMessageAsJsonObject="true" />

Restart the app, and voilá!

{
  "instant" : {
    "epochSecond" : 1644938669,
    "nanoOfSecond" : 242305000
  },
  "thread" : "http-nio-8080-exec-1",
  "level" : "INFO",
  "loggerName" : "com.zachelrath.springboot.structuredloggingdemo.OrderController",
  "message" : {
    "totalItems" : 1,
    "items" : [ {
      "id" : "1234",
      "sku" : "chair-blue",
      "description" : "Very comfy chair"
    } ]
  },
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
  "contextMap" : {
    "orderNumber" : "123",
    "retailer" : "acme"
  },
  "threadId" : 27,
  "threadPriority" : 5
}

Okay, that’s pretty cool. We can now filter and query our logs based on the structured properties within particular log messages!

But you may be wondering — — why do we need that wrapper class at all? That seems like a lot of boilerplate just to get some key-value data into our logs. Can’t we just pass in a Map or something?

Yep! We can do that instead:

Which yields the exact same result — — no wrapper class required!

Which approach you prefer really just depends on how often you will be logging this structure — — if you’re going to be logging this same structure repeatedly, a wrapper class might make sense just to cut back on boilerplate. But for one-off logs, the new ObjectMessage(Map.of(...)) pattern is simple and convenient. Just throw any Map inside of an ObjectMessage and Log4j will handle it.

Bonus: How do we do this in Logback ?

If you are stumbling across this article and you’re a Logback user and wondering how you log structured messages in Logback, well, you’re in luck, it’s pretty easy in Logback as well.

Logback provides support for Map logging via the StructuredArguments.kv API which provides a really nice logging experience. However, I won’t waste time as this is covered very well in other articles, e.g. https://www.innoq.com/en/blog/structured-logging/

Conclusion

With that — go forth, structure your logs, and start leveraging the advanced indexing/filtering/querying capabilities of your log aggregation tools!

The full source code for the Order example app is available here:

https://github.com/zachelrath/structured-logging-spring-boot