Sinatra is not logging when calling another route

I'm trying to trigger a route every 5s, using Rufus Scheduler within a Sinatra application; with the solution provided here (Calling Sinatra from within Sinatra).

Everything is working fine, except that the Logger doesn’t log anything when the route is called by the scheduler.

require 'sinatra/base'
require 'rufus/scheduler'

class App < Sinatra::Base
    configure do
        enable :logging
    end

    Rufus::Scheduler.new.every("5s") do
        call(
            'REQUEST_METHOD' => 'GET',
            'PATH_INFO' => '/test',
            'rack.input' => StringIO.new,
        )
    end

    get '/test' do
        puts env["rack.logger"].inspect
        logger.info "This is a logger test."
    end
    run!
end

Here is the output when called by Curl without the scheduler:

#<Logger:0x0000000249a9d8 @progname=nil, @level=1, @default_formatter=#<Logger::Formatter:0x0000000249a9b0 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x0000000249a8c0 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDERR>>, @mutex=#<Logger::LogDevice::LogDeviceMutex:0x0000000249a870 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x0000000249a7d0>>>>
I, [2015-01-15T20:49:36.365062 #15803]  INFO -- : This is a logger test.
127.0.0.1 - - [15/Jan/2015 20:49:36] "GET /test HTTP/1.1" 200 - 0.0011

And when called by the call() method :

#<Logger:0x000000024b8a78 @progname=nil, @level=1, @default_formatter=#<Logger::Formatter:0x000000024b89b0 @datetime_format=nil>, @formatter=nil, @logdev=nil>

Is seems that the logging device in the Logger object is empty.

Any ideas, or other way to achieve this ?

Thanks,

Solution

When Sinatra sets up logging for a request, it uses the IO object in env['rack.errors'] (Sinatra uses a subclass of Rack::Logger) as the destination for the messages. This is set by the server as it processes the request before it hands it over to your app.

When you use call directly you bypass the work the server does setting this up, so env['rack.errors'] remain unset, so it evaluates t nil. This ends up creating a logger that simply ignores any requests.

You can get this working by adding an IO object to the hash you pass to call under the rack.errors key. For example to log to standard out:

call(
  'REQUEST_METHOD' => 'GET',
  'PATH_INFO' => '/test',
  'rack.input' => StringIO.new,
  'rack.errors' => $stdout
)

You might need to check your server if you want the logs going to the same place, it might be logging to standard error