What is Structured Logging?

For a long period in my development career, I assumed logging was only good for applications that didn’t have a UI. We only ever used it for diagnosing error conditions. Once the software reached production, we’d get notified whenever operations reported a stack trace. Sometimes we’d know right away what the problem was. More often, we wouldn’t have enough information about the sequence of events that led to the problem, and the resolution would involve a lot of inspired guessing and detective work.

Then I noticed that Thoughtworks recommended adopting something called “Structured Logging” in their Technology Radar in May of 2015. What the heck was that all about? Clearly, I was missing something important…

I have since come to understand that logging can- and probably should- be used for much more than just error diagnostics. A well-designed logging system can also be used for business analytics (e.g., how is the system being used) as well as for system monitoring (e.g., what kind of load are we experiencing).

Currently, I am a member of an agile development team. As such, we take responsibility for doing automated testing, deployment, and monitoring of the systems we develop. Designing a useful and effective logging system can and does make these tasks much, much simpler. In this article, I advocate the use of structured logging in your project right from the very beginning.

What Can Structured Logging Do For Us?

Customers often feel that support for business analytics is a much lower priority than adding new features. After all, we can always add that stuff later, right? My experience is that by the time "later" comes, the effort to modify the software has become prohibitive… unless you’ve been using structured logging all along. In that case, adding business analytics support turns out to be very easy to do. In many cases, all you need to do is to create some canned reports using the log analysis tools.

Here are a few other questions that structured logging can help us answer easily if it is implemented from the very beginning:

• Diagnostics

  • What caused this stack trace?

  • What was the sequence of events that led up to this request failing unexpectedly?

• Analytics

  • Who is using our service?

  • What does usage look like over time?

  • What are our customers using our system to do?

• Monitoring

  • How long is it taking to process a request?

  • How much available memory is there?

Practical Concerns

There is a big data explosion going on in our industry. There is massive growth in machine and infrastructure size. The ability to spot errors and correlate information from distributed systems is becoming critically important. Our logging system needs to provide the ability to trace operations across many machines and systems. That is only really practical if we use a standard logging format, make our logs machine-readable, and introduce tokens that identify operations that cross machine boundaries.

Logging Format

So what is a good format to make our logs machine-readable (as well as human readable)? While there are alternatives- XML, name-value pairs, fixed width columns, etc.- the most obvious format for a machine-readable logging event format is JSON, and it turns out that there are quite a few tools available that are happy to consume JSON logs. Rather than have intermediate tools like logstash convert our logs to JSON, it seems more efficient to just log in JSON in the first place.

What Should we be Logging?

Standard logging libraries like Simple Logging Facade for Java (SLF4J) already include a lot of useful information: timestamp, pid, thread, level, loggername, etc. We just need to extend this list with attributes that are specific to our software.

If we want to follow an operation across multiple machines and systems, we need to include an identifying token in the logs. This is sometimes called a request id or a transaction ID. Inclusion of this token will allow our logging tools to extract only those events that relate to that request- even though multiple systems may be involved in servicing it.

Values like a transaction ID will need to be transported between our systems for this to work. Some ways to do this are custom HTTP headers, additional message fields, and database columns.

Standardized Logging Levels

The various components of our system need to be consistent about the use of logging levels. Typically, a system in production is going to use the INFO logging level, while in development it will use the DEBUG logging level. With this as a starting point, here’s a suggestion for when the other levels should be used:

• ERROR: Unexpected errors, e.g., loss of connectivity, logic errors, misconfiguration.

• WARN: Expected errors, e.g., user authentication failed.

• INFO: Anything we need to see in a production system related to business analytics, diagnostics or monitoring, e.g., user request started/completed, resource usage snapshots, timing information.

• DEBUG: Stuff developers need to see, e.g., entry to different architectural layers with parameters.

• TRACE: Stuff developers might turn on temporarily, e.g., complex branching logic, dumps of data structures.

Some Logging Tools

There is a growing set of tools available for doing this kind of log analysis. Some examples are Graylog, Elasticsearch/Logstash/Kibana (ELK), Loggly, and Splunk.

All of these can consume and search logging events in JSON format. However, installing and using these tools is outside the scope of this article.

In my next blog, I’ll discuss implementing structured logging in Groovy.