- (W)rapping About Exceptional Behavior In Rails
- Wrapping Up Rails Exceptional Behavior
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
However, we're using
rescue_from to handle this exception, and raise a new
When you hit this controller endpoint, what status code do you expect to receive?
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.
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
ActiveRecord::RecordNotFound) and, rather than returning a 500, it knows to
return a 404 instead.
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_fromone 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.
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!
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
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?
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.
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-18.104.22.168/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
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-22.214.171.124/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
"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?
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-126.96.36.199/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-188.8.131.52/lib/action_dispatch/middleware/exception_wrapper.rb:46:in `status_code'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-184.108.40.206/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-220.127.116.11/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-18.104.22.168/lib/action_dispatch/middleware/debug_exceptions.rb:71:in `rescue in call'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-22.214.171.124/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-126.96.36.199/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-188.8.131.52/lib/rails/rack/logger.rb:38:in `call_app'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-184.108.40.206/lib/rails/rack/logger.rb:26:in `block in call'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-220.127.116.11/lib/active_support/tagged_logging.rb:71:in `block in tagged'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-18.104.22.168/lib/active_support/tagged_logging.rb:28:in `tagged'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-22.214.171.124/lib/active_support/tagged_logging.rb:71:in `tagged'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/railties-126.96.36.199/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-188.8.131.52/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-184.108.40.206/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-220.127.116.11/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-18.104.22.168/lib/action_dispatch/middleware/executor.rb:14:in `call'", "/ruby/2.6.6/lib/ruby/gems/2.6.0/gems/actionpack-22.214.171.124/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-126.96.36.199/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
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
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.
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.
bundle opento manipulate the source code of our dependency.
- Inserted a
binding.irbto play around in a method that we think is interesting, and asked where it's being invoked with
- Confirmed that what's calling our class in question is always passing it a
We still don't know where the
ActiveRecord::RecordNotFound exception is coming
We'll take another look at this with fresh eyes in our next post.