Production Logging for Sinatra Applications

Logging for Sinatra applications can be a bit tricky. When in development mode, exceptions are helpfully shown in the browser, or in your terminal where you started the application. In production, however, it takes some additional configuration to properly log requests and errors.

Access Logging

The cited method for logging in Sinatra involves something like the following in your Rack configuration file (config.ru), or in the configuration block for the Sinatra application:

require 'logger'
Logger.class_eval { alias :write :'<<' }
logger = ::Logger.new(::File.new("log/app.log","a+")

configure do
    use Rack::CommonLogger, logger
end

This code creates an instance of Logger backed by a log file, and instructs the application to use the Rack CommonLogger middleware to log to this file. (It also creates a write method for the Logger class, as Rack expects to be able to call write on whatever logger it is provided.)

This works great for logging requests and responses at the Rack level: you get Apache-style logs with ip addresses, dates/times, HTTP command and status codes, etc.

127.0.0.1 - - [02/Nov/2013 23:25:37] "GET /nope HTTP/1.1" 200 6997 3.2593
127.0.0.1 - - [02/Nov/2013 23:40:31] "GET /yip HTTP/1.1" 200 6997 1.8096

Error Logging

Unfortunately, that is all. If your Sinatra application goes boom, you just find out that Rack returned a 500 error to the client:

127.0.0.1 - - [02/Nov/2013 23:52:07] "POST /radio HTTP/1.1" 500 5909 0.0204

This is not helpful at all in determining the nature of the error. All you find out is that the error occurred: no stack trace or anything particularly useful.

If you were being proactive and doing extensive exception handling, you might be able to properly catch and log some of the errors; but completely unexpected situations would leave you with a 500 error and no clues.

Fortunately, we can use the Rack env["rack.errors"] middleware to help us out.

We see here that Rack treats whatever is in env["rack.errors"] as an IO object. Several application servers (e.g. webrick) set env["rack.errors"] to STDERR when RACK_ENV is set to “development” so that messages are also printed to your terminal. However, this is a problem in production if the application server itself does not provide capture and logging of STDERR from processes (e.g. Puma).

For better log management, we can set env["rack.errors"] directly to control logging in production mode. We will use a File object (instead of Logger) since we need a subclass of IO.

error_log = ::File.new("log/error.log","a+")
env["rack.errors"] = error_log

Unfortunately, pre-setting env["rack.errors"] in the appropriate context proves to be difficult. Usually, it is defined when the application server loads up Rack — not when the application itself is being configured. By the time Sintra is loaded, it has already been set, and we can only access it from within the request chain (in the env hash).

Thus, we set env["rack.error"] before each request (or selectively for only certain requests):

error_log = ::File.new("log/error.log","a+")
before {
    env["rack.errors"] = error_log
}

Now, whenever an uncaught exception occurs, it is logged to the provided file. Of course, since Ruby buffers IO, log entries may not show up immediately. This behavior can be changed by setting the “sync mode” for the file to true so that Ruby immediately flushes the errors to disk:

error_log = ::File.new("log/error.log","a+")
error_log.sync = true
before {
    env["rack.errors"] = error_log
}

Putting it All Together

Now that we have all of the logging sorted out, a complete Sinatra application with exception logging may look something like:

require 'rubygems'
require 'sinatra/base'
require 'logger'

class SinatraLoggingExample < Sinatra::Base

  ::Logger.class_eval { alias :write :'<<' }
  access_log = ::File.join(::File.dirname(::File.expand_path(__FILE__)),'..','log','access.log')
  access_logger = ::Logger.new(access_log)
  error_logger = ::File.new(::File.join(::File.dirname(::File.expand_path(__FILE__)),'..','log','error.log'),"a+")
  error_logger.sync = true

  configure do
    use ::Rack::CommonLogger, access_logger
  end

  before {
    env["rack.errors"] =  error_logger
  }

  get "/nope" do
    "Nope, nope, nope."
  end

  get "/yip" do
    "Yip, yip, yip."
  end

  post "/radio" do
    radio = params[:radio]
    "Yip, yip, yip, yip #{radio.upcase}"
  end

  post "/book" do
    telephone = params[:book]
    "Nope, nope, nope, nope #{book.upcase}"
  end

end

This provides us a much better idea of what is causing exceptions than the simple request logging. While request logging is helpful, it certainly doesn’t cut it when debugging strange exceptions in a production Sinatra application.