Sinatra with Puma gives twice the output in the terminal

Question

I have added Puma to my sinatra app, and now I get two lines of output for requests in the terminal. I've checked and it isn't actually calling the code twice, and I'm guessing that maybe Puma is outputting the request information along with Sinatra.

As a demonstration, I've created a simple app as follows:

Gemfile

source 'https://rubygems.org'
ruby '2.2.0'

gem 'sinatra'
gem 'puma'

config.ru

require 'sinatra'

get '/' do
  'Hello World'
end

run Sinatra::Application

Here is the command I run:

rackup -s puma

and here's the type of output I receive when I browse http://localhost:9292/

R5001755:test louis.sayers$ rackup -s puma
Puma 2.11.3 starting...
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://localhost:9292
::1 - - [03/Jul/2015:21:46:37 +1000] "GET / HTTP/1.1" 200 11 0.0074
::1 - - [03/Jul/2015:21:46:37 +1000] "GET / HTTP/1.1" 200 11 0.0222

I've uploaded the example project to github if you'd like to have a play

Any ideas as to what's going on? Thanks for your help!

Answer 1

This is caused by the CommonLogger middleware. It is added by both Rack (when using rackup) and by Sinatra (when logging is enabled), resulting in the duplicated output. Sinatra actually uses a custom subclass of this middleware to try and address this issue. In order for it to work it patches the original CommonLogger class.

The issue arises because Puma also defines its own version of CommonLogger which doesn’t include the changes introduced by Sinatra. When Puma is loaded after Sinatra the Puma version overwrites the patched version, and so the original behaviour (duplicated output lines) occurs.

There are a few ways to workaround this issue. You could disable logging in Sinatra to prevent the duplicate middleware from being added. The Sinatra logging setting applies to both the CommonLogger and the Logger middleware (which is what the logger helper uses), so you might want to add the Logger middleware yourself:

disable :logging
use Rack::Logger

You could also prevent rackup from adding the CommonLogger middleware by using the -q option to the rackup command:

$ rackup -q -s puma

Another option would be to ensure that Puma is loaded before Sinatra, so that when Sinatra patches CommonLogger it is patching the Puma version and the patch isn’t overwritten later. You can do this by using the -r option to rackup to force it to load Puma:

$ rackup -s puma -r puma