brandur.org

logfmt

If you’ve ever run an app on Heroku, you may have come across log messages produced by the Heroku router and wondered about their unusual formatting. Each line consists of a single level of key/value pairs which are densely packed together compared to other well-known structured formats like JSON. For example:

at=info method=GET path=/ host=mutelight.org fwd="124.133.52.161"
  dyno=web.2 connect=4ms service=8ms status=200 bytes=1653

Internally we’ve taken to calling this style of structured logging “logfmt”, and adopted it as a standard for log emission across internal components. I’ve never been able to find any good posts providing any context or background for logfmt, so I’ve written this one.

Especially with a bit of practice (and ideally, colorized output), it’s pretty easy for a human being to read logfmt – an important property for any good logging format. Building a machine parser for the format is also pretty approachable. Logfmt therefore achieves pretty good readability for both human and computer, even while not being optimal for either.

Splunk also recommends the same format under their best practices so we can be sure that it can be used to search and analyze all our logs in the long term.

A major advantage provided by logfmt is that it helps to eliminate any guesswork that a developer would have to make while deciding what to log. Consider this log line in a more traditional format:

INFO [ConsumerFetcherManager-1382721708341] Stopping all fetchers
  (kafka.consumer.ConsumerFetcherManager)

While writing this code, a developer would’ve had to decide how to format the log line like placing the manager’s identifier in square brackets at the beginning, the module name in parenthesis at the end, with some general information in the middle. Convention can help a lot here, but it’s still a series of micro-decisions that have to be made for every log line. Furthermore, what if they want to add another piece of data like number of open fetchers? Does that belong on a new line, or in another set of brackets somewhere?

An equivalent logfmt line might look this:

level=info tag=stopping_fetchers id=ConsumerFetcherManager-1382721708341
  module=kafka.consumer.ConsumerFetcherManager

Readability isn’t compromised too much, and all the developer has to do is dump any information that they think is important. Adding more data is trivial – just append num_open_fetchers=3 to the end. The developer also knows that if for any reason they need to generate a statistic on-the-fly, like the average number of fetchers still open, they’ll easily be able to do that with a simple Splunk (or equivalent) query:

tag=stopping_fetchers | stats p50(num_open_fetchers) p95(num_open_fetchers)
  p99(num_open_fetchers)

Update (March 30, 2016): This section was added after original publication to reflect changes to the recommended best practices.

Logfmt may be more readable than something like JSON, but it’s still difficult to scan quickly for humans. To improve that, I’d recommend using the approach seen in logrus and including a human readable message with every log line:

level=info msg="Stopping all fetchers"
  tag=stopping_fetchers id=ConsumerFetcherManager-1382721708341
  module=kafka.consumer.ConsumerFetcherManager

In development, a log output formatter can then give the msg field special treatment by displaying it in way that a human can easily read (along with other special fields like level):

info | Stopping all fetchers          module=kafka.consumer.ConsumerFetcherManager
info | Performing log compaction      module=kafka.compacter.LogCompactionManager
info | Performing garbage collection  module=kafka.cleaner.GarbageCollectionManager
info | Starting all fetchers          module=kafka.consumer.ConsumerFetcherManager

Assigning a machine-friendly “tag” to each log line can make them more easily machine searchable:

info | Stopping all fetchers          tag=stopping_fetchers module=kafka.consumer.ConsumerFetcherManager
info | Performing log compaction      tag=log_compaction module=kafka.compacter.LogCompactionManager
info | Performing garbage collection  tag=garbage_collection module=kafka.cleaner.GarbageCollectionManager
info | Starting all fetchers          tag=starting_fetchers module=kafka.consumer.ConsumerFetcherManager

Update (July 30, 2019): These days I’d recommend using a canonical log line instead of the practice described in this section.

Logfmt also lends itself well to building context around operations. Inside a request for example, as important information becomes available, it can be added to a request-specific context and included with every log line published by the app. This may not seem immediately useful, but it can be very helpful while debugging in production later, as only a single log line need be found to get a good idea of what’s going on.

For instance, consider this simple Sinatra app:

def authenticate!
  @user = User.authenticate!(env["HTTP_AUTHORIZATION"]) || throw(401)
  log_context.merge! user: @user.email, user_id: @user.id
end

def find_app
  @app = App.find!(params[:id])
  log_context.merge! app: @app.name, app_id: @app.id
end

before do
  log "Starting request", tag: "request_start"
end

get "/:id" do
  authenticate!
  find_app!
end

after do
  log "Finished request", tag: "request_finish", status: response.status
end

error do
  e = env["sinatra.error"]
  log "Request errored", tag: "request_error",
    error_class: e.class.name, error_message: e.message
end

By the end of a request, the last log line has picked up a lot of contextual informational that’s helpful for quick debugging:

msg="Request finished" tag=request_finish status=200 
  user=brandur@mutelight.org user_id=1234 app=mutelight app_id=1234

The value becomes even more apparent when we consider what would be logged on an error, which automatically contains some key information to help with debugging (note that in real life, we’d include a stack trace as well):

msg="Request errored" tag=request_error error_class=NoMethodError
  error_message="undefined method `serialize' for nil:NilClass"
  user=brandur@mutelight.org user_id=1234 app=mutelight app_id=1234

A few projects from already exist to help parse logfmt in various languages:

Did I make a mistake? Please consider sending a pull request.