If you read around about logging in the wonderful Sinatra framework you’ll tend to find something that suggests you just reopen STDOUT and STDERR in your config.ru file like this:

log = File.new("log/sinatra.log", "a+")
$stdout.reopen(log)
$stderr.reopen(log)

That worked fine and has served me well for quite a while. All that changed with more recent versions of the Passenger Gem which I tend to use in concert with Nginx to deploy my Ruby web applications. You see Passenger now seems to use STDOUT to do a lot of chatting to itself on and re-directing it in the above fashion just breaks things.

If you just leave Sinatra to do it’s thing then log messages end up in the Nginx error log. So I’ve been making do with that for a while now, but it’s not great - it can make tracing debugging hard and the log levels are not printed out. Well with my most recent deployment of Passenger I found it seems to be even more chatty in the logs, enough so that my log messages were getting lost in the noise. So time for a proper solution! What I really wanted was:

  • Nginx logging by itself as normal
  • Passenger logging somewhere by itself
  • Sinatra logging to it’s own application log file

So doing a bit of reading around and properly looking at the Rack documentation it would appear there are two rack variables that may be of use to us: rack.logger and rack.errors. Rack.logger says this:

A common object interface for logging messages. The object must implement:

  • info(message, &block)
  • debug(message, &block)
  • warn(message, &block)
  • error(message, &block)
  • fatal(message, &block)

Rack.errors says

The error stream must respond to puts, write and flush.

  • puts must be called with a single argument that responds to to_s.
  • write must be called with a single argument that is a String.
  • flush must be called without arguments and must be called in order to make the error appear for sure.
  • close must never be called on the error stream.

So I wondered could I set these variables for each request in my Sinatra application? The logical place to try was the before filter. So perhaps if we created two suitable objects we could do something like

before do
	env['rack.logger'] = $logger
	env['rack.errors'] = $error_logger
end

So the rack.logger can be a normal Logger, but it would seem that rack.errors would be better derived from the File class (Rack source for ShowExceptions class). So at the top of my Sinatra application I’ve added:

TEN_MB = 10490000

Logger.class_eval { alias :write :'<<' }
access_log = File.join( File.dirname(File.expand_path(__FILE__)), 'log', 'application.log' )
$logger    = Logger.new( access_log, 10, TEN_MB)	
$error_logger      = File.new( File.join(File.dirname(File.expand_path(__FILE__)), 'log', 'error.log'), 'a+' )
$error_logger.sync = true

So I’m creating my logs in the somewhat default Sinatra location based on the path of the application we’re running. My general access log is called application.log and this is where messages written with logger.info and friends will go. The error log file is called error.log and this is where exceptions should end up (we set the sync to true to make sure stuff is written to the logs and not buffered for a while - not much use if it is!). In my case I’m cycling the access log when it reaches 10MB in size and retaining ten log files, but you could do whatever suits. This is a decent guide to class_eval if you’re unfamilar with it.

I finally tell Sinatra about this by setting :logging to nil in a configure block

configure do
	set :logging, nil
end

So that seemed to work - I now have two log files that are used instead of the Nginx (STDOUT/STDERR) log so I can once again easily see my log messages (logger.error "msg" etc.). However there is no indication of the date and time of the log message or it’s severity. Being lazy I looked around for a solution and found a monkey patch to add such information to the log output, here is my slightly tweaked version which lives at the top of my Sinatra application.

class Logger::SimpleFormatter
  def call(severity, timestamp, progname, msg)
    msg = "#{String === msg ? msg : msg.inspect}"
    "[#{timestamp.to_s(:log)}] #{"[%5s]"% severity.upcase} #{msg}\n"
  end
end

So now I seem to have almost everything. I have my separate application logs with timestamps and severity for filtering, but Passenger is still logging to Nginx. That is however easy to solve the passenger_debug_log_file directive can be set in the Nginx configuration to define a file for Passenger to log to and the passenger_log_level can be tweaked to set the verbosity.

So finally a solution I’m happy with until perhaps the whole thing is fixed properly by someone with some time.