Recently, we have been experiencing “stalls” in the Puma web server in development, this means that quite often during our dev cycle we would hit CTRL-C and be stuck waiting many many seconds for Puma to stop. Sometimes needing to fallback to kill -9 on the Puma process.

We definitely want this Puma issue fixed, however our “web application server of choice” is Unicorn not Puma. It makes little sense for us to run Puma in development. Our Unicorn configuration is very mature and handles all sorts of magic including automatic forking of our Sidekiq job scheduler which is awesome in dev.

A major problem though is that when we run Puma in dev our console is pristine, run Unicorn in dev and it is noise central.

127.0.0.1 - - [07/Aug/2018:15:38:59 +1000] "GET /assets/pretty-text-bundle.js?1533620338.6222095 HTTP/1.1" 200 112048 0.0481
127.0.0.1 - - [07/Aug/2018:15:38:59 +1000] "GET /assets/plugin.js?1533620338.6222444 HTTP/1.1" 200 146176 0.0726
127.0.0.1 - - [07/Aug/2018:15:38:59 +1000] "GET /assets/plugin-third-party.js?1533620338.6222594 HTTP/1.1" 200 3364 0.0569
127.0.0.1 - - [07/Aug/2018:15:38:59 +1000] "GET /assets/application.js?1533620338.6222193 HTTP/1.1" 200 3039095 0.2049
127.0.0.1 - - [07/Aug/2018:15:38:59 +1000] "GET /assets/fontawesome-webfont.woff2?http://l.discourse&2&v=4.7.0 HTTP/1.1" 304 - 0.0016

I am a puts debugger and being barred from being a puts debugger in development is a blocking feature for me.

So, how do we find where these messages are coming from?

Before we start the little tip here first… if you have not yet… take a break and read _why’s classic seeing metaclasses clearly.

Now that you know about metaclasses, time to have some fun, let’s reopen STDERR and glue a little debug method to it that will output caller locations when we invoke write on STDERR (note this will work on STDOUT as well if you want):

class << STDERR
  alias_method :orig_write, :write
  def write(x)
    orig_write(caller[0..3].join("\n"))
    orig_write(x)
  end
end

/home/sam/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/common_logger.rb:61:in `log'
/home/sam/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/common_logger.rb:35:in `block in call'
/home/sam/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/body_proxy.rb:23:in `close'
/home/sam/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rack-2.0.5/lib/rack/chunked.rb:34:in `close'
127.0.0.1 - - [07/Aug/2018:15:44:57 +1000] "POST /mini-profiler-resources/results HTTP/1.1" 200 - 0.0109

So, there you have it this line is coming from CommonLogger.

However… Discourse does not use the Rack::CommonLogger middleware… a little bit more hunting we can find out that unicorn will always load Rack::CommonLogger, Rack::ShowExceptions, and Rack::Lint middleware in development and it has a little command line option of -N or --no-default-middleware to disable this behavior.

This tip is handy for a large number of issues you can encounter, be it stray messages in your test suite or leftover puts in some gem you upgraded. And as always, enjoy.