(W)rapping About Exceptional Behavior in Rails

Exceptional Behavior in Rails 🔗

(W)rapping About Exceptional Behavior In Rails
Wrapping Up Rails Exceptional Behavior

Reset 🔗

Pop Quiz 🔗

Consider the following controller:

class FoosController < ActionController::API
  rescue_from ActiveRecord::RecordNotFound, with: :raise_not_found

  def create
    raise ActiveRecord::RecordNotFound
    head :ok
  end

  def raise_not_found
    raise "What status code?"
  end
end

Here we have an endpoint that that always raises ActiveRecord::RecordNotFound. However, we’re using rescue_from to handle this exception, and raise a new RuntimeError.

When you hit this controller endpoint, what status code do you expect to receive?

It Depends 🔗

In Rails 6, we get a 500.

> curl -I -X POST localhost:3000/foos
HTTP/1.1 500 Internal Server Error

However, in Rails 5, we get a 404.

> curl -I -X POST localhost:3000/foos
HTTP/1.1 404 Not Found

Why does this difference exist? Let’s dig into how to investigate.

Research 🔗

If you’ve ever hit the #show route for a resource, passing it an ID that doesn’t exist, you may have noticed that Rails responds with a 404 Not Found HTTP status code. Rails is intercepting the exception that’s raised from calling find (ActiveRecord::RecordNotFound) and, rather than returning a 500, it knows to return a 404 instead.

Start With What You Know 🔗

To give us some grounding, let’s begin by explicitly stating what we believe to be true:

Rails has some special handling of certain exceptions to respond with a different HTTP status code.
If we rescue_from one of those exceptions in Rails 5 and re-raise a new exception, we’ll still see that special handling behavior.
In Rails 6, with the same implementation, the server now responds with a 500, no longer considering it a special case.

Go Explore 🔗

The exception that we know exhibits this behavior is ActiveRecord::RecordNotFound. We also know that Rails returns a 404 Not Found status code. If we search through the Rails codebase for RecordNotFound or not_found (which is the symbol representation of the status code), we get a number of results - but there are fewer for not_found, so let’s look through that.

Towards the bottom of the first page of results (as of this writing), we see the ExceptionWrapper class, which includes this:

  cattr_accessor :rescue_responses, default: Hash.new(:internal_server_error).merge!(
      "ActionController::RoutingError"                     => :not_found,
      "AbstractController::ActionNotFound"                 => :not_found,
      "ActionController::MethodNotAllowed"                 => :method_not_allowed,
      "ActionController::UnknownHttpMethod"                => :method_not_allowed,
      "ActionController::NotImplemented"                   => :not_implemented,
      "ActionController::UnknownFormat"                    => :not_acceptable,
      "ActionDispatch::Http::MimeNegotiation::InvalidType" => :not_acceptable,
      "ActionController::MissingExactTemplate"             => :not_acceptable,
      "ActionController::InvalidAuthenticityToken"         => :unprocessable_entity,
      "ActionController::InvalidCrossOriginRequest"        => :unprocessable_entity,
      "ActionDispatch::Http::Parameters::ParseError"       => :bad_request,
      "ActionController::BadRequest"                       => :bad_request,
      "ActionController::ParameterMissing"                 => :bad_request,
      "Rack::QueryParser::ParameterTypeError"              => :bad_request,
      "Rack::QueryParser::InvalidParameterError"           => :bad_request
    )

This looks like a big list of exceptions that are mapped to HTTP status codes. This seems promising - but ActiveRecord::RecordNotFound isn’t in this hash!

If we search further, we will eventually run into ActiveRecord’s railtie, which includes:

config.action_dispatch.rescue_responses.merge!(
  "ActiveRecord::RecordNotFound"   => :not_found,
  "ActiveRecord::StaleObjectError" => :conflict,
  "ActiveRecord::RecordInvalid"    => :unprocessable_entity,
  "ActiveRecord::RecordNotSaved"   => :unprocessable_entity
)

This is adding ActiveRecord exceptions to that same hash we saw above in ActionDispatch. We’ve found where the special handling of mapping exceptions to status codes occurs!

Pull Out Some Tools 🔗

Returning to the ExceptionWrapper class, we see the status_code_for_exception method, which looks to take in an exception class and convert it to a status code, based on the @@rescue_responses hash.

def self.status_code_for_exception(class_name)
  Rack::Utils.status_code(@@rescue_responses[class_name])
end

Maybe if we could see what class name is getting passed into that, we could see if the exception is somehow getting transformed before or after that point. But, we need a way to get into the rails source code on our running rails app - that’s not our code; how can we do that?

`Open`ing A World of Possibilities 🔗

Rails 5 appears to be showing confusing results - we’re explicitly raising a RuntimeError, but it’s returning a 404. As such, let’s look in Rails 5.

You can access the source of any dependency using bundler’s open command. Rails itself is a series of gems, and we can see that this ExceptionWrapper is part of actionpack, so let’s open that up:

bundle open actionpack

This will open up the source code for the actionpack gem in the editor you have defined. We open the ExceptionWrapper class, and we know we want to find out what value is passed to it, but we’re not sure what else we might want to see while we’re there. Using Ruby’s binding.irb, we can start a console when we hit that method.

def self.status_code_for_exception(class_name)
  binding.irb
  Rack::Utils.status_code(@@rescue_responses[class_name])
end

After starting a rails server, and issuing a request to our endpoint via curl, we eventually hit our breakpoint:

From: /ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/exception_wrapper.rb @ line 86 :

    81:         "Full Trace" => full_trace_with_ids
    82:       }
    83:     end
    84:
    85:     def self.status_code_for_exception(class_name)
 => 86:       binding.irb
    87:       Rack::Utils.status_code(@@rescue_responses[class_name])
    88:     end
    89:
    90:     def source_extracts
    91:       backtrace.map do |trace|

irb(ActionDispatch::ExceptionWrapper):001:0>  class_name
=> "RuntimeError"

This isn’t surprising that we’re getting the RuntimeError, but doesn’t help explain how we’re getting a 404 returned. Let’s exit and regroup on a new strategy.

irb(ActionDispatch::ExceptionWrapper):002:0> exit
Completed 500 Internal Server Error in 2ms (ActiveRecord: 0.0ms)



From: /ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/exception_wrapper.rb @ line 86 :

    81:         "Full Trace" => full_trace_with_ids
    82:       }
    83:     end
    84:
    85:     def self.status_code_for_exception(class_name)
 => 86:       binding.irb
    87:       Rack::Utils.status_code(@@rescue_responses[class_name])
    88:     end
    89:
    90:     def source_extracts
    91:       backtrace.map do |trace|

irb(ActionDispatch::ExceptionWrapper):001:0>

Wait! This method is called a second time. And that time, the class name is still "RuntimeError". It gets called a third time, and that time, we see:

irb(ActionDispatch::ExceptionWrapper):001:0> class_name
=> "ActiveRecord::RecordNotFound"

We’ve found our NotFound! But - what do we do now?

`Call`ing In A Favor 🔗

We’re still in our console session, and we’ve executed the status_code_for_exception for the third time when processing a single HTTP request. What’s calling this method? Ruby will tell us its caller:

irb(ActionDispatch::ExceptionWrapper):002:0> caller
=> ["/ruby/2.6.6/lib/ruby/2.6.0/irb/workspace.rb:85:in `eval'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/workspace.rb:85:in `evaluate'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/context.rb:385:in `evaluate'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:493:in `block (2 levels) in eval_input'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:647:in `signal_status'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:490:in `block in eval_input'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/ruby-lex.rb:246:in `block (2 levels) in each_top_level_statement'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/ruby-lex.rb:232:in `loop'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/ruby-lex.rb:232:in `block in each_top_level_statement'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/ruby-lex.rb:231:in `catch'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb/ruby-lex.rb:231:in `each_top_level_statement'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:489:in `eval_input'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:428:in `block in run'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:427:in `catch'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:427:in `run'",
"/ruby/2.6.6/lib/ruby/2.6.0/irb.rb:796:in `irb'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/exception_wrapper.rb:86:in `status_code_for_exception'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/exception_wrapper.rb:46:in `status_code'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:105:in `render_for_browser_request'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:87:in `render_exception'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/web-console-3.7.0/lib/web_console/extensions.rb:28:in `render_exception_with_web_console'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:71:in `rescue in call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/web-console-3.7.0/lib/web_console/middleware.rb:135:in `call_app'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/web-console-3.7.0/lib/web_console/middleware.rb:30:in `block in call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/web-console-3.7.0/lib/web_console/middleware.rb:20:in `catch'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/web-console-3.7.0/lib/web_console/middleware.rb:20:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:38:in `call_app'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `block in call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `block in tagged'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:28:in `tagged'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `tagged'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/sprockets-rails-3.2.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/executor.rb:14:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/static.rb:127:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-5.2.4.5/lib/rails/engine.rb:524:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'",
"/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'"
]

Starting from the bottom, we can see the full path that leads us to executing status_code_for_exception. Tracing our way backwards from status_code_for_exception, we eventually find where the ExceptionWrapper is created:

def render_exception(request, exception)
  backtrace_cleaner = request.get_header("action_dispatch.backtrace_cleaner")
  wrapper = ExceptionWrapper.new(backtrace_cleaner, exception)
  ...

We drop a binding.irb in here, and it looks like the exception is always our RuntimeError. It looks like something inside of ExceptionWrapper is doing something to change this to an ActiveRecord::RecordNotFound exception.

Walk Away 🔗

We’ve been at this for a while, and we’ve got a lead to track down, but at this point, let’s take a break. We should clean up our mess by restoring actionpack back to how it was before.

bundle pristine

Let’s take stock in what we’ve done:

Identified that Rails has a list of exceptions that it maps to specific HTTP status codes.
Used bundle open to manipulate the source code of our dependency.
Inserted a binding.irb to play around in a method that we think is interesting, and asked where it’s being invoked with caller.
Confirmed that what’s calling our class in question is always passing it a RuntimeError.

We still don’t know where the ActiveRecord::RecordNotFound exception is coming from.

We’ll take another look at this with fresh eyes in our next post.

This post originally published on The Gnar Company blog.