Structured Logging

This is another post triggered by writing The Art of Monitoring. You can join the mailing list on that site for further information and updates.

Most logging mechanisms emit log entries that contain a string value: the message or description of the error. The classic example of this is Syslog, used by many hosts, services and applications as a default logging format. A typical Syslog message looks like:

1

Dec  6 23:17:01 logstash CRON[5849]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)

In addition to the payload, in this case a report on a Cron job, it has a date stamp and a source (the host logstash). Whilst versatile and readable, the Syslog format is not ideal as it’s basically one long string. This string is awesome from a human readability perspective. It’s very easy to glance at a Syslog string and know what’s happened. But are you the target audience of a string-based message? Probably back in the day when you had a small volume of hosts and you were connecting to them to read the logs you were the audience. Now you have a pool of hosts, services and applications and your log entries are centralized. That means between you, the human audience, there is now a machine that first consumes the log message before you see it. And because of the eminently readable string format that consumption is not easy.

That format means we’re likely to be forced to resort to regular expressions to parse it. Additionally, probably more than one regular expression. Again Syslog is a good example. Implementations across platforms are sometimes subtly different and this often means more than one regular expression needs to be implemented and then maintained. This additional overhead means it’s much harder to extract the value, diagnostic or operational, from our log data.

There is, however, a better way of generating logs: structured logs (also known as semantic or typed logs). There’s no standard currently for structured logging. There are some examples of attempts to formalize a structured logging formats like the Common Event Expression and Project Lumberjack. None of them got much traction and are largely unmaintained. But we can still describe the concept of structured logging. Instead of a string, like our Syslog examples, structured logs try to preserve typed, rich data rather than convert it. Let’s look at an example of some code that produces an unstructured string:

1

Logger.error("The system had a hiccup trying to create user" + username)

Let’s assume the user being created was james@example.com. This pseudo-code would generate a message like:

1

The system had a hiccup trying to create user james@example.com.

We’d then have to send that message somewhere, to Logstash for example, and parse it into a useful form.

Alternatively, we can create a more structured message.

1

Logger.error(event="user_creation_failed", user=username)

You can see in our structured message that we’ve gotten a head start on any parsing. Assuming we send the log message in some encoded format, JSON for example or a binary format like protocol buffers, then we get an event name, user_creation_failed, and a variable user which contains the user name of the user that we failed to create (or even a user object containing all the parameters of the user being created).

Let’s look at what our JSON encoded event might look like:

1
2
3
4
5
6
7
8

[
  {
    "time":1449454008,
    "priority":"error",
    "event":"user_creation_failed",
    "user":"james@example.com"
  }
]

We can see instead of a string we’ve got a JSON array containing a structured log entry: a time, a priority, an event identifier, and some rich data from that event, the user which our application failed to create. We’re now logging a series of objects which are easily consumed by a machine rather than a string we need to parse.

Let’s extend an example Rails application with some structured log events. This is a simple Ruby on Rails application that allows us to create and delete users and not much else. We’re going to add two structured logging libraries, the first called Lograge and the second called Logstash-logger to our application. The Lograge library formats Rails-style request logs into a structured format, by default JSON, but can also generate Logstash-structured events. The second library, Logstash-logger, allows us to hijack Rails existing logging framework and emit much more structured events and then send them directly to Logstash. Let’s install them now and then see what some structured logging messages might look like.

We first need to add three gems, lograge, logstash-event and logstash-logger, to our application to enable our structured logging support.

The lograge gem enables Lograge’s request log re-formatting. The logstash-event gem allows Lograge to format requests into Logstash events. The logstash-logger gem allows you to output log events in Logstash’s event format and enables a variety of potential logging destinations, including Logstash. We’re going to start by adding the gems to our Rails application’s Gemfile.

1
2
3
4
5
6
7
8

source 'https://rubygems.org'
ruby '2.2.2'
gem 'rails', '4.2.4'
. . .
gem 'lograge'
gem 'logstash-event'
gem 'logstash-logger'
. . .

We then install the new gems using the bundle command.

1
2
3
4
5
6
7
8
9

$ sudo bundle install
Fetching gem metadata from https://rubygems.org/...........
Fetching version metadata from https://rubygems.org/...
Fetching dependency metadata from https://rubygems.org/..
. . .
Installing lograge
Installing logstash-event
Installing logstash-logger
. . .

Next, we need to enable all of our new logging components inside our Rails application’s configuration. We’re only going to enable each component for the production environment. To do this we add our configuration to the config/environments/production.rb file.

1
2
3
4
5
6
7
8
9

Rails.application.configure do
  # Settings specified here will take precedence over those in config/application.rb.

. . .
  config.log_level = :info
  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Logstash.new
  config.logger = LogStashLogger.new(type: :tcp, host: 'logstash.example.com', port: 2020)
end

Here we’ve configured four options. The first, config.log_level, is a Rails logging default for the log level, here we’re telling Rails to only log events of an :info level or higher. By default, Rails logs at a :debug level. We generally don’t need that kind of detail. The second option, config.lograge.enabled turns on Lograge, taking over Rails default logging for requests. The third option, config.lograge.formatter, controls the format those log events are emitted in, here we’re using Logstash’s event format. Lograge has a series of other formats available including raw JSON. The last option, config.logger, takes over Rails default logging with Logstash-logger. It creates a new instance of the LogStashLogger class that connects to our Logstash server, logstash.example.com via TCP on port 2020.

Let’s look at the corresponding required configuration on our Logstash server. We need to add a new tcp input to receive our application events.

1
2
3
4
5
6
7

input {
  tcp {
    port  => 2020
    type  => "apps"
    codec => "json"
  }
. . .

We can see we’ve added a tcp input running on port 2020. We set a type of apps for any events received on this input and we use the json codec to parse any incoming events into Logstash’s message format from JSON. To enable our configuration we would need to restart Logstash.

1

$ sudo service logstash restart

So what does this do for our sample application? Well enabling Lograge will convert Rails default request logs into something a lot more structured and a lot more useful. A traditional request log might look like:

1
2
3
4

Started GET "/" for 127.0.0.1 at 2015-12-10 09:21:45 +0400
Processing by UsersController#index as HTML
  Rendered users/_user.html.erb (6.0ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)

With Lograge enabled a log request like this would appear more like:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

{
  "method":"GET",
  "path":"/users",
  "format":"html",
  "controller":"users",
  "action":"index",
  "status":200,
  "duration":189.35,
  "view":186.35,
  "db":0.92,
  "@timestamp":"2015-12-11T13:35:47.062+00:00",
  "@version":"1",
  "message":"[200] GET /users (users#index)",
  "severity":"INFO",
  "host":"app1-web1",
  "type":"apps"
}

We can see that the log event has been converted in a Logstash event. The original base message is now in the message field and each element of the request has been parsed into a field, for example the request’s method is in the method field and the controller in the controller field. Logstash-logger will then send this structured event to our Logstash server where we can parse it, create metrics from it (you can see we have things like the HTTP status code and timings from the request), or store it in Kibana where you will be able to query it.

We can also send stand-alone log events too using Logstash-logger’s override of Rails default logger method. Let’s specify a message that gets sent when we delete a user.

1
2
3
4
5

  def destroy
    @user.destroy
    logger.info message: 'user_deleted', user: @user
    redirect_to users_path, :notice => "User deleted."
  end

Here we’ve added a logger.info call to the destroy method. We’ve passed it two arguments, message and user. The message argument will become the value of our message field in the Logstash event. The user field will also become a field containing the @user instance variable, which in turn contains the details of the user being deleted. Let’s look at an event that might be generated when we delete the user james.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

{
  "message":"user_deleted",
  "user": {
    "id":6,
    "email":"james@example.com",
    "created_at":"2015-12-11T04:31:46.828Z",
    "updated_at":"2015-12-11T04:32:18.340Z",
    "name":"james",
    "role":"user",
    "invitation_token":null,
    "invitation_created_at":null,
    "invitation_sent_at":null,
    "invitation_accepted_at":null,
    "invitation_limit":null,
    "invited_by_id":null,
    "invited_by_type":null,
    "invitations_count":0
  },
  "@timestamp":"2015-12-11T13:35:50.070+00:00",
  "@version":"1",
  "severity":"INFO",
  "host":"app1-web1",
  "type":"apps"
}

We can see our event is in Logstash format with our user_deleted message and the contents of the @user instance variable structured as fields of a user hash. When a user is deleted this event would be passed to Logstash and could then be processed and stored. Once there you can see there are more than enough details to help us diagnose issues and track events.

This is a super simple example of how structured logging can make monitoring your applications so much easier. You can apply the basic principles articulated here in a variety of languages and frameworks.

Structured logging libraries

Just to get you started, here are some structured logging libraries and integrations for a variety of languages and frameworks. You should be able to find others by searching online.

Java

The Java community has the powerful and venerable Log4j. It’s a hugely configurable and flexible.

Go

Golang has Logrus, which extends the standard logger library with structured data.

Clojure

Clojure has a couple of good structured logging implementations. One from Puppet Labs and the other clj-log.

Ruby & Rails

We’ve already seen Lograge for Ruby and Rails. Other examples include Semantic Logger and ruby-cabin.

Python

Python has Structlog which augments the existing Logger methods with structured data.

Javascript & Node.JS

Javascript (and Node) has an implementation of .Net’s Serilog available called Structured Log. Another example is Bunyan.

.Net

The .Net framework has Serilog.