Skip to main content
Published in Engineering Insights

(W)rapping About Exceptional Behavior In Rails

Mike StoneCo-Founder, The Gnar CompanyUpdated
(W)rapping About Exceptional Behavior In Rails
Table of contents
  1. Exceptional Behavior in Rails
  2. Pop Quiz
  3. It Depends
  4. Research
    1. Start With What You Know
    2. Go Explore
    3. Pull Out Some Tools
    4. Calling In A Favor
    5. Walk Away

Exceptional Behavior in Rails#

  1. (W)rapping About Exceptional Behavior In Rails
  2. Wrapping Up Rails Exceptional Behavior

Pop Quiz#

Consider the following controller:

Ruby
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.

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

However, in Rails 5, we get a 404.

Shell
> 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:

Ruby
 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:

Ruby
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.

Ruby
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?

Opening 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:

Shell
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.

Ruby
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:

Ruby
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.

Ruby
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:

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

We've found our NotFound! But, what do we do now?

Calling 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:

Ruby
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:

Ruby
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 thispoint, let's take a break. We should clean up our mess by restoring actionpack back to how it was before.

Shell
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.

Frequently asked questions

How can I open the dependency's source code?

Use bundle open actionpack to open the gem in your configured editor.

What does binding.irb help inspect?

It starts a console when execution reaches the method. The investigation uses it to inspect the exception class passed to status_code_for_exception.

What did the repeated method calls reveal?

The first two calls received RuntimeError. The third received ActiveRecord::RecordNotFound.

Did the investigation resolve the cause?

No. It found that the caller passed RuntimeError into ExceptionWrapper, but did not yet establish where ActiveRecord::RecordNotFound came from.

How does the post restore the edited dependency?

It runs bundle pristine to restore the dependency after the investigation.

Related Insights

Engineering Insights

Everyone Has a License. That's Not AI Adoption.

Product Insights

How to Choose an AI Automation Consulting Partner

Stay In The Loop

Never miss an update. Get the latest blogs, webinars, and expert insights straight to your inbox from The Gnar.