🌲 Timber - Simple Ruby Structured Logging

ISC License Build Status Build Status Code Climate View docs

Overview

Timber solves ruby structured logging so you don't have to. Go from raw text logs to rich structured events in seconds. Spend more time focusing on your app and less time focusing on logging.

  1. Easy setup. - bundle exec timber install, get setup in seconds.

  2. Automatically structures yours logs. - Third-party and in-app logs are all structured in a consistent format. See how it works below.

  3. Seamlessly integrates with popular libraries and frameworks. - Rails, Rack, Devise, Omniauth, etc. Automatically captures user context, HTTP context, and event data.

  4. Pairs with a modern structured-logging console. - Designed specifically for structured data, hosted, instantly usable, tail users, trace requests. Checkout the docs.

Installation

  1. In Gemfile, add the timber gem:

    gem 'timber', '~> 2.0'
    
  2. In your shell, run bundle install

  3. In your shell, run bundle exec timber install

How it works

Let's start with an example. Timber turns this production log line:

I, [2017-06-04T18:04:53.653812 #42348]  INFO -- : [my.host.com] [df88dbaa-50fd-4178-85d7-d66279ea33b6] [192.32.23.12] [bfa8242cd9733bf0211e334be203f0d0] Sent 200 in 45.2ms

Into a structured http_server_response event.

Sent 200 in 45.2ms  {"dt": "2017-02-02T01:33:21.154345Z", "level": "info", "context": {"http": {"method": "GET", "path": "/path", "remote_addr": "192.32.23.12", "request_id": "df88dbaa-50fd-4178-85d7-d66279ea33b6"}, "session": {"id": "bfa8242cd9733bf0211e334be203f0d0"}, "system": {"hostname": "my.host.com", "pid": "254354"}, "user": {"id": 1, "name": "Ben Johnson", "email": "bens@email.com"}}, "event": {"http_server_response": {"status": 200, "time_ms": 45.2}}}

Notice that instead of completely replacing your log messages, Timber augments your logs with structured metadata. Turning them into rich events with context without sacrificing readability. And you have complete control over which data is captured.

This is all accomplished by using the Timber::Logger:

logger = Timber::Logger.new(STDOUT)
logger.info("Sent 200 in 45.2ms")

Here's a better look at the metadata:

{
  "dt": "2017-02-02T01:33:21.154345Z",
  "level": "info",
  "context": {
    "http": {
      "method": "GET",
      "path": "/path",
      "remote_addr": "192.32.23.12",
      "request_id": "abcd1234"
    },
    "session": {
      "id": "bfa8242cd9733bf0211e334be203f0d0"
    },
    "system": {
      "hostname": "1.server.com",
      "pid": "254354"
    },
    "user": { // user identifiable logs :O
      "id": 1,
      "name": "Ben Johnson",
      "email": "bens@email.com"
    },
  },
  "event": {
    "http_server_response": {
      "status": 200,
      "time_ms": 45.2
    }
  }
}

This structure isn't arbitrary either, it follows the simple log event JSON schema, which formalizes the data structure, creates a contract with downstream consumers, and improves stability.

So what can you do with this data?

  1. Tail a user - user.id:1
  2. Trace a request - http.request_id:abcd1234
  3. Narrow by host - system.hostname:1.server.com
  4. View slow responses - http_server_response.time_ms:>=1000
  5. Filter by log level - level:error
  6. Quickly find exceptions - is:exception

For a complete overview, see the Timber for Ruby docs.

Third-party integrations

  1. Rails: Structures (HTTP requests, HTTP respones, controller calls, template renders, and sql queries).
  2. Rack: Structures exceptions, captures HTTP context, captures user context, captures session context.
  3. Devise, Omniauth, Clearance: captures user context
  4. Heroku: Captures release context via Heroku dyno metadata.

...and more. Timber will continue to evolve and support more libraries.

Usage

Basic logging

Use the Timber::Logger just like you would ::Logger:

logger = Timber::Logger.new(STDOUT)
logger.info("My log message") # use warn, error, debug, etc.

# => My log message @metadata {"level": "info", "context": {...}}

Custom events

Custom events allow you to extend beyond events already defined in the Timber::Events namespace.

logger = Timber::Logger.new(STDOUT)
logger.warn "Payment rejected", payment_rejected: {customer_id: "abcd1234", amount: 100, reason: "Card expired"}

# => Payment rejected @metadata {"level": "warn", "event": {"payment_rejected": {"customer_id": "abcd1234", "amount": 100, "reason": "Card expired"}}, "context": {...}}
  • Notice the :payment_rejected root key. Timber will classify this event as such.
  • In the Timber console use the query: type:payment_rejected or payment_rejected.amount:>100.
  • See more details on our custom events docs page

Custom contexts

Context is additional data shared across log lines. Think of it like log join data. This is how a query like context.user.id:1 can show you all logs generated by that user. Custom contexts allow you to extend beyond contexts already defined in the Timber::Contexts namespace.

logger = Timber::Logger.new(STDOUT)
logger.with_context(build: {version: "1.0.0"}) do
  logger.info("My log message")
end

# => My log message @metadata {"level": "info", "context": {"build": {"version": "1.0.0"}}}

Metrics & Timings

Aggregates destroy details, and with Timber capturing metrics and timings is just logging events. Timber is built on modern big-data principles, it can calculate aggregates across terrabytes of data in seconds. Don't reduce the quality of your log data to accomodate a restrive logging system.

Here's a timing example. Notice how Timber automatically calculates the time and adds the timing to the message.

logger = Timber::Logger.new(STDOUT)
timer = Timber::Timer.start
# ... code to time ...
logger.info("Processed background job", background_job: {time_ms: timer})

# => Processed background job in 54.2ms @metadata {"level": "info", "event": {"background_job": {"time_ms": 54.2}}}

And of course, time_ms can also take a Float or Fixnum:

logger.info("Processed background job", background_job: {time_ms: 45.6})

Lastly, metrics aren't limited to timings. You can capture any metric you want:

logger = Timber::Logger.new(STDOUT)
logger.info("Credit card charged", credit_card_charge: {amount: 123.23})

# => Credit card charged @metadata {"level": "info", "event": {"credit_card_charge": {"amount": 123.23}}}

In Timber you can easily sum, average, min, and max the amount attribute across any interval you desire.

Configuration

Below are a few popular configuration options, for a comprehensive list, see Timber::Config.

Logrageify. Silence noisy logs (sql query, template renders)

Timber allows you to silence noisy logs that aren't of value to you, just like lograge. In fact, we've provided a convenience method for anyone transitioning from lograge:

# config/initializers/timber.rb

config = Timber::Config.instance
config.logrageify!()

It turns this:

Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
  Rendered text template within layouts/application (0.0ms)
  Rendered layouts/_assets.html.erb (2.0ms)
  Rendered layouts/_top.html.erb (2.6ms)
  Rendered layouts/_about.html.erb (0.3ms)
  Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)

Into this:

Get "/" sent 200 OK in 79ms  {...}

Internally this is equivalent to:

# config/initializers/timber.rb

config = Timber::Config.instance
config.integrations.action_controller.silence = true
config.integrations.action_view.silence = true
config.integrations.active_record.silence = true
config.integrations.rack.http_events.collapse_into_single_event = true

Feel free to deviate and customize which logs you silence. We recommend a slight deviation from lograge with the following settings:

# config/initializers/timber.rb

config = Timber::Config.instance
config.integrations.action_view.silence = true
config.integrations.active_record.silence = true
config.integrations.rack.http_events.collapse_into_single_event = true

This does not silence the controller call log event. This is because Timber captures the parameters passed to the controller, which are generally valuable when debugging.

For a full list of integration settings, see Timber::Config::Integrations


Silence specific requests (LB health checks, etc)

The following will silence all [GET] /_health requests:

# config/initializers/timber.rb

config = Timber::Config.instance
config.integrations.rack.http_events.silence_request = lambda do |rack_env, rack_request|
  rack_request.path == "/_health"
end

We require a block because it gives you complete control over how you want to silence requests. The first parameter being the traditional Rack env hash, the second being a Rack Request object.


Change log formats

Simply set the formatter like you would with any other logger:

# This is set in your various environment files
logger = Timber::Logger.new(STDOUT)
logger.formatter = Timber::Logger::JSONFormatter.new

Your options are:

  1. Timber::Logger::AugmentedFormatter - (default) A human readable format that appends metadata to the original log line. The Timber service can parse this data appropriately. Ex: My log message @metadata {"level":"info","dt":"2017-01-01T01:02:23.234321Z"}

  2. Timber::Logger::JSONFormatter - Ex: {"level":"info","message":"My log message","dt":"2017-01-01T01:02:23.234321Z"}

  3. Timber::Logger::MessageOnlyFormatter - For use in development / test. Prints logs as strings with no metadata attached. Ex: My log message


Capture custom user context

By default Timber automatically captures user context for most of the popular authentication libraries (Devise, Omniauth, and Clearance). See Timber::Integrations::Rack::UserContext for a complete list.

In cases where you Timber doesn't support your strategy, or you want to customize it further, you can do so like:

# config/initializers/timber.rb

config = Timber::Config.instance
config.integrations.rack.user_context.custom_user_hash = lambda do |rack_env|
  user = rack_env['warden'].user
  if user
    {
      id: user.id, # unique identifier for the user, can be an integer or string,
      name: user.name, # identifiable name for the user,
      email: user.email, # user's email address
    }
  else
    nil
  end
end

All of the user hash keys are optional, but you must provide at least one.


Capture release / deploy context

Timber::Contexts::Release tracks the current application release and version. If you're on Heroku, simply enable the dyno metadata feature. If you are not, set the following environment variables and this context will be added automatically:

  1. RELEASE_COMMIT - Ex: 2c3a0b24069af49b3de35b8e8c26765c1dba9ff0
  2. RELEASE_CREATED_AT - Ex: 2015-04-02T18:00:42Z
  3. RELEASE_VERSION - Ex: v2.3.1

All variables are optional, but at least one must be present.


Jibber-Jabber

Which events and contexts does Timber capture for me?

Out of the box you get everything in the Timber::Events namespace.

We also add context to every log, everything in the Timber::Contexts namespace. Context is structured data representing the current environment when the log line was written. It is included in every log line. Think of it like join data for your logs. It's how Timber is able to accomplished tailing users (context.user.id:1).

Lastly, you can checkout how we capture these events in Timber::Integrations.


Won't this increase the size of my log data?

Yes, but it's no different than adding any other useful data to your logs, such as tags. A few of things to note:

  1. Timber generally reduces the amount of logs your app generates, trading quality for quantity. It does so by providing options to consolidate request / response logs, template logs, and even silence logs that are not of value to you. (see configuration for examples).
  2. Timber lets you pick exactly which events and contexts you want. (see configuration for examples)
  3. Your logging provider should be compressing your data and charging you accordingly. Log data is notoriously repetitive, and the context Timber generates is repetitive. Because of compression we've seen somes apps only incur a ~15% increase in data size.

Finally, log what is useful to you. Quality over quantity certainly applies to logging.


What about my current log statements?

They'll continue to work as expected. Timber adheres to the default ::Logger interface. Your previous logger calls will work as they always do. Just swap in Timber::Logger and you're good to go.

In fact, traditional log statements for non-meaningful events, debug statements, etc, are encouraged. In cases where the data is meaningful, consider logging a custom event.