A compact log format for humans and machines

If you have run an app on Heroku, you have likely seen the router’s log messages: dense, key/value lines that stand apart from JSON-style structured logging. Internally, that style is called “logfmt,” and it has been adopted as a standard for log emission across components.

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

Logfmt is easy to read with a bit of practice—especially when colorized—and easy to parse with a machine. It strikes a practical balance between human readability and machine searchability, even if it is not optimal for either. Splunk’s logging best practices recommend the same format, which makes it viable for long-term log analysis.

Designing log lines without guesswork

A traditional log line forces a developer to make a series of micro-decisions about formatting: where to put square brackets, parentheses, or other metadata. Consider a line like:

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

A developer must decide where to place the manager identifier, where the module name goes, and whether additional data such as the number of open fetchers belongs on the same line or in a separate one. Logfmt removes that friction. The equivalent line is simply:

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

Readability is preserved, and adding information is just a matter of appending another key/value pair, such as num_open_fetchers=3. This also enables ad hoc queries against the data:

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

Making logfmt friendlier for humans

Logfmt is more scannable than JSON, but it can still be dense. To improve human readability, include a human-readable message with every log line, following the pattern used by logrus:

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

In development, a log formatter can give the msg field special treatment—along with fields like level—so the output is presented in a way that suits human scanning:

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

For machine searchability, it helps to assign a distinct tag to each log line:

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

Accumulating context across a request

Logfmt is well-suited to building a context object that travels with a request. As new information becomes available, it is appended to a request-specific context and included in every log line the application emits. This is especially useful during production debugging: one log line can convey the state of a whole operation.

For example, a 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 final log line carries a useful set of contextual details:

msg="Request finished" tag=request_finish status=200 
  [email protected] user_id=1234 app=mutelight app_id=1234

The benefit becomes clear on an error path. The resulting log line automatically includes key debugging information, and in practice a stack trace would also be attached:

msg="Request errored" tag=request_error error_class=NoMethodError
  error_message="undefined method `serialize' for nil:NilClass"
  [email protected] user_id=1234 app=mutelight app_id=1234

Several libraries exist for parsing logfmt: