Add Rails timeout exception handling example

[zmillman]

I was recently bitten by an issue that occurred when rack-timeout raises Rack::Timeout::RequestTimeoutError during the middle of an ActiveRecord query. It interrupts the processing of the request but the query is still being processed by the database. Since Rails is running in production mode, ActiveRecord::Base's singleton connection isn't reset before the next web request.

Since the original request was cancelled and the results of the query are never read, the database eventually closes the connection, raising "Mysql2::Error: closed MySQL connection" during the middle of the next request.

I feel like this is probably a pretty common gotcha, and it's mentioned would be worth giving an example in the README to save other developers the same headaches.

This is what I'm doing:

# controllers/application_controller.rb
class ApplicationController < ActionController::Base

  rescue_from Rack::Timeout::RequestTimeoutError, :with => :handle_timeout
  #...
  protected

  def handle_timeout(exception)
    # Send exception report to service for tracking

    # If the timeout occurs during the middle of a MySQL query, we need to cancel the
    # query so that "Mysql2::Error: closed MySQL connection" isn't raised in the middle
    # of a subsequent request
    ActiveRecord::Base.connection.reset!

    # Render error page
    respond_with_error_status(503)
  end

[reconbot]

What web server are you using? Or would it matter?

[sslotnick]

@zmillman This error ("Mysql2::Error: closed MySQL connection") causes all queries to start failing until the server is restarted? You mention ActiveRecord::Base using a singleton connection, however, my understanding is that it uses a connection pool with multiple connections. I'm also curious what server you're using, because in my own testing I'm able to reproduce the "closed MySQL connection" error, but it does not affect any future requests to the same server (using Passenger Standalone running Ruby 1.9.3 and Rails 3.2).

I did recently encountered a similar problem where the request timed out mid-transaction and that did cause all queries to start failing until the app server was restarted. However, the error message was different:
Mysql2::Error: This connection is still waiting for a result, try again once you have the result: ROLLBACK

However, after witnessing that in a production environment, I was not able to reproduce it.

[zmillman]

To be honest, I haven't tried reproducing this recently. I still get the occasional closed connection error, but they're much less frequent now.

To clarify, this bug wasn't occurring on all requests following the timed-out one. Only one of the requests following Rack::Timeout::RequestTimeoutError was affected.

I'm using nginx, Rails 3.2.17, Ruby 1.9.3 and Unicorn 4.8.2 with configuration very similar to GitHub's example: https://gist.github.com/defunkt/206253#file-gistfile1-rb

[PikachuEXE]

I handle timeout exception this way:

#In `ApplicationController`
      rescue_from Rack::Timeout::RequestTimeoutError,
                  Rack::Timeout::RequestExpiryError,
                  with: :handle_request_timeout

private
   def handle_request_timeout(_)
      # If there is no accepted format declared by controller
      respond_to do |format|
        format.html do
          render file: Rails.root.join("public/503.html"),
            status: 503, layout: nil
        end
        format.all  { head 503 }
      end
    end

Problem is: I don't know how to handle it if the rack app hasn't reached the Rails app yet

[kch]

Sounds a bit like #39

[kch]

If the timeout raises outside of rails you have to handle it in rack.

An idea tho: what if after timing out anything, rack-timeout set a global (probably thread-local) flag on its module saying it has timed out.

A before_filter could check that flag and perform any necessary cleanup, then reset the flag.

Comments?

[PikachuEXE]

thread-local <- which thread?
Can't understand quite well without some example code

[sslotnick]

@kch, this does sound like #39. In that thread (pardon the overloaded term), you seemed to blame the problem on state being maintained between requests. I mostly agree, though reusing a shared DB connection pool between requests isn't unique to rails or rack. I'm not too familiar with the specifics of what Rails does to cleanup DB connections around requests and transactions, but my guess is that the problem stems from rack-timeout's timer_thread raising an exception inside app_thread (https://github.com/heroku/rack-timeout/blob/master/lib/rack/timeout.rb#L53) without any opportunity to cleanup. I'd love to know what specifically in the connection is getting into the bad state, but I haven't been able to chase it down that far. The more ominous problem IMO is that it potentially affects future requests.

Your idea to create a before_filter that resets the DB connection might work. You could also try to catch RequestTimeoutError somewhere or use the rack-timeout observers to do this.

[kch]

Yeah observers are a good idea.

[kch]

Supplanted by #49