56

I'm having trouble figuring out how to log messages with Sinatra. I'm not looking to log requests, but rather custom messages at certain points in my app. For example, when fetching a URL I would like to log "Fetching #{url}".

Here's what I'd like:

  • The ability to specify log levels (ex: logger.info("Fetching #{url}"))
  • In development and testing environments, the messages would be written to the console.
  • In production, only write out messages matching the current log level.

I'm guessing this can easily be done in config.ru, but I'm not 100% sure which setting I want to enable, and if I have to manually create a Logger object myself (and furthermore, which class of Logger to use: Logger, Rack::Logger, or Rack::CommonLogger).

(I know there are similar questions on StackOverflow, but none seem to directly answer my question. If you can point me to an existing question, I will mark this one as a duplicate).

the Tin Man
  • 158,662
  • 42
  • 215
  • 303
Kyle Fox
  • 3,133
  • 4
  • 23
  • 26

4 Answers4

47

Sinatra 1.3 will ship with such a logger object, exactly usable as above. You can use edge Sinatra as described in "The Bleeding Edge". Won't be that long until we'll release 1.3, I guess.

To use it with Sinatra 1.2, do something like this:

require 'sinatra'
use Rack::Logger

helpers do
  def logger
    request.logger
  end
end
the Tin Man
  • 158,662
  • 42
  • 215
  • 303
Konstantin Haase
  • 25,687
  • 2
  • 57
  • 59
  • 11
    This answer would be extra helpful if you included information on how to set the logger destination (file/STDOUT) and how to actually log (`logger.info "foo"`?) – Phrogz May 13 '11 at 19:51
  • 10
    Usage is described in the Sinatra README on github: `logger.info("foo")`. Destination is set by the Webserver (it uses the Rack error stream), you can basically set it by changing `env['rack.errors']`. – Konstantin Haase May 13 '11 at 21:18
  • 2
    because of using helpers, this appears to only work in request context. it does not work for things happening at earlier parts in the application (pre request, app setup etc) – random-forest-cat Mar 15 '16 at 15:08
  • worked for me , but i have to use the setting variable first, ie: settings.logger.info('blablabla') – gipsh Jun 05 '17 at 23:28
16

I personally log in Sinatra via:

require 'sinatra'
require 'sequel'
require 'logger'
class MyApp < Sinatra::Application
  configure :production do
    set :haml, { :ugly=>true }
    set :clean_trace, true

    Dir.mkdir('logs') unless File.exist?('logs')

    $logger = Logger.new('logs/common.log','weekly')
    $logger.level = Logger::WARN

    # Spit stdout and stderr to a file during production
    # in case something goes wrong
    $stdout.reopen("logs/output.log", "w")
    $stdout.sync = true
    $stderr.reopen($stdout)
  end

  configure :development do
    $logger = Logger.new(STDOUT)
  end
end

# Log all DB commands that take more than 0.2s
DB = Sequel.postgres 'mydb', user:'dbuser', password:'dbpass', host:'localhost'
DB << "SET CLIENT_ENCODING TO 'UTF8';"
DB.loggers << $logger if $logger
DB.log_warn_duration = 0.2
Phrogz
  • 296,393
  • 112
  • 651
  • 745
  • 8
    Why do you use a modular app on the one hand but a global variable for storing the logger? – Konstantin Haase May 13 '11 at 21:22
  • 1
    @Konstantin Good question. I do the former for simple config.ru MyApp.run, but I never run more than one app in the same process so the ugly global variable is just convenient laziness so far. – Phrogz May 13 '11 at 22:09
  • 1
    Reopening STDOUT can make Passenger to not start: https://github.com/phusion/passenger/wiki/Debugging-application-startup-problems – fguillen Dec 11 '13 at 19:30
7

If you are using something like unicorn logging or other middleware that tails IO streams, you can easily set up a logger to STDOUT or STDERR

# unicorn.rb
stderr_path "#{app_root}/shared/log/unicorn.stderr.log"
stdout_path "#{app_root}/shared/log/unicorn.stdout.log"

# sinatra_app.rb
set :logger, Logger.new(STDOUT) # STDOUT & STDERR is captured by unicorn
logger.info('some info') # also accessible as App.settings.logger

this allows you to intercept messages at application scope, rather than just having access to logger as request helper

random-forest-cat
  • 33,652
  • 11
  • 120
  • 99
3

Here's another solution:

module MySinatraAppLogger
  extend ActiveSupport::Concern

  class << self
    def logger_instance
      @logger_instance ||= ::Logger.new(log_file).tap do |logger|
        ::Logger.class_eval { alias :write :'<<' }
        logger.level = ::Logger::INFO
      end
    end

    def log_file
      @log_file ||= File.new("#{MySinatraApp.settings.root}/log/#{MySinatraApp.settings.environment}.log", 'a+').tap do |log_file|
        log_file.sync = true
      end
    end
  end

  included do
    configure do
      enable :logging
      use Rack::CommonLogger, MySinatraAppLogger.logger_instance
    end

    before { env["rack.errors"] = MySinatraAppLogger.log_file }
  end

  def logger
    MySinatraAppLogger.logger_instance
  end
end

class MySinatraApp < Sinatra::Base
  include MySinatraAppLogger
  get '/' do
    logger.info params.inspect
  end
end

Of course, you can do it without ActiveSupport::Concern by putting the configure and before blocks straight into MySinatraApp, but what I like about this approach is that it's very clean--all logging configuration is totally abstracted out of the main app class.

It's also very easy to spot where you can change it. For instance, the SO asked about making it log to console in development. It's pretty obvious here that all you need to do is a little if-then logic in the log_file method.

Isaac Betesh
  • 2,935
  • 28
  • 37
  • `Rack::Logger` streams to `env['rack.errors']`, it seems like a bad idea to override its contents in the before filter http://www.rubydoc.info/github/rack/rack/Rack/Loggerhttp://www.rubydoc.info/github/rack/rack/Rack/Logger – random-forest-cat Mar 15 '16 at 15:50
  • I'm not sure why that makes this a bad idea. Can you give some more details? – Isaac Betesh Mar 16 '16 at 15:41
  • fixed link: http://www.rubydoc.info/github/rack/rack/Rack/Logger my thoughts were that this key was reserved internally by rack logger to track request based errors – random-forest-cat Mar 16 '16 at 15:45
  • That's correct. If I understand correctly, that means that you're redirecting not only your own log statements, but Rack's as well. That's exactly what I intended for it to do, so that you can debug those request-based errors and see all your logs in one place. Assuming that's the goal, is there anything unsafe about this approach? It's worked well for me. – Isaac Betesh Mar 17 '16 at 19:27