Log Weasel released into the wild

Alon Salant ·

Log Weasel makes it easy to trace execution of a unit of work across applications and application instances by instrumenting Rails and Resque logs to show a single transaction ID for every log entry from that unit of work.

These days, many of our larger Rails applications at Carbon Five are often actually a federated collection of multiple Rails applications and Resque workers all collaborating to get work done. When something goes awry, it can be hard to trace through all these systems to find what went wrong and where. Log Weasel makes it easy to correlate log entries across these system. This is particularly handy if you’re using a system like Splunk to manage your log files across many applications and application instances.

The most up to date usage details will always be at http://github.com/carbonfive/log_weasel.

Installation

Add log_weasel to your Gemfile:

gem 'log_weasel'

Use bundler to install it:

bundle install

Rack

Log Weasel provides Rack middleware to create and destroy a transaction ID for every HTTP request. You can use it in a any web framework that supports Rack (Rails, Sinatra,…)

Rails 3

To see Log Weasel transaction IDs in your Rails logs, you need to add the Rack middleware and either use the BufferedLogger provided or customize the formatting of your logger to include
LogWeasel::Transaction.id.

YourApp::Application.configure do
  logger = LogWeasel::BufferedLogger.new "#{Rails.root}/log/#{Rails.env}.log"
  config.logger                   = logger
  config.action_controller.logger = logger
  config.active_record.logger     = logger

  config.middleware.insert_before Rails::Rack::Logger,
                                  LogWeasel::Middleware, :key => 'YOUR_APP'
end

:key is an optional parameter used to name the transaction ID that is useful in an environment where a unit of work may span multiple applications.

Resque

To see Log Weasel transaction IDs in your Resque logs, you need to need to initialize Log Weasel when you configure Resque, for example in a Rails initializer.

LogWeasel::Resque.initialize! :key => 'YOUR_APP'

Start your Resque worker with VERBOSE=1 and you’ll see transaction IDs in your Resque logs.

Hoptoad

If you are using Hoptoad, Log Weasel will add the parameter log_weasel_id to Hoptoad errors so that you can track execution through your application stack that resulted in the error. No additional configuration required.

Example

In this example we have a Rails app pushing jobs to Resque and a Resque worker that run with the Rails environment loaded.

HelloController

class HelloController < ApplicationController

  def index
    Resque.enqueue EchoJob, 'hello from HelloController'
    Rails.logger.info("HelloController#index: pushed EchoJob")
  end

end

EchoJob

class EchoJob
  @queue = :default_queue

  def self.perform(args)
    Rails.logger.info("EchoJob.perform: #{args.inspect}")
  end
end

Start Resque with:

QUEUE=default_queue rake resque:work VERBOSE=1

Requesting http://localhost:3030/hello/index, our development log shows:

[2011-02-14 14:37:42] YOUR_APP-WEB-192587b585fa66b19638 48353 INFO

Started GET "/hello/index" for 127.0.0.1 at 2011-02-14 14:37:42 -0800
[2011-02-14 14:37:42] YOUR_APP-WEB-192587b585fa66b19638 48353 INFO   Processing by HelloController#index as HTML
[2011-02-14 14:37:42] YOUR_APP-WEB-192587b585fa66b19638 48353 INFO HelloController#index: pushed EchoJob
[2011-02-14 14:37:42] YOUR_APP-WEB-192587b585fa66b19638 48353 INFO Rendered hello/index.html.erb within layouts/application (1.8ms)
[2011-02-14 14:37:42] YOUR_APP-WEB-192587b585fa66b19638 48353 INFO Completed 200 OK in 14ms (Views: 6.4ms | ActiveRecord: 0.0ms)
[2011-02-14 14:37:45] YOUR_APP-WEB-192587b585fa66b19638 48461 INFO EchoJob.perform: "hello from HelloController"

Fire up a Rails console and push a job directly with:

> Resque.enqueue EchoJob, 'hi from Rails console'

and our development log shows:

[2011-02-14 14:37:10] YOUR_APP-RESQUE-a8e54bfb76718d09f8ed 48453 INFO EchoJob.perform: "hi from Rails console"

Units of work initiated from Resque, for example if using a scheduler like resque-scheduler, will include ‘RESQUE’ in the transaction ID to indicate that the work started in Resque.