Rails error reporter doesn't report exceptions in production

[fractaledmind]

In production, an exception that occurs in the HTTP request lifecycle is rendered and not raised. The Executor middleware reports only raised exceptions. This severely neuters, IMHO, the value of the new error reporter.

Expected behavior

Exceptions that occur within the HTTP request lifecycle in production, while still being rendered, are also reported to the error reporter.

Actual behavior

Exceptions that occur within the HTTP request lifecycle in production are not reported to the error reporter.

System configuration

Rails version: >7.0

[fractaledmind]

This change to the Executor middleware produces the effect that I want:

module ActionDispatch
  class Executor
    def initialize(app, executor)
      @app, @executor = app, executor
    end

    def call(env)
      state = @executor.run!(reset: true)
      begin
        response = @app.call(env)
        returned = response << ::Rack::BodyProxy.new(response.pop) { state.complete! }
        if (exception = env['action_dispatch.exception'])
          @executor.error_reporter.report(exception, handled: false, source: "application.action_dispatch")
        end
        returned
      rescue => error
        @executor.error_reporter.report(error, handled: false, source: "application.action_dispatch")
        raise
      ensure
        state.complete! unless returned
      end
    end
  end
end

[fractaledmind]

I stumbled across this issue by publishing the SolidErrors gem, which plugs into the error reporter to store errors and their occurrences in the database to drive a simple, in-app error monitoring dashboard. It was reported by a user that errors weren't being reported in production, and I was then able to confirm with my production applications. A Twitter follower then also confirmed that they were seeing the same behavior.

To my mind, this feels like a bug. A default Rails application should report exceptions to the error reporter, especially in the production context, even if the error is swallowed and converted into an valid HTTP response.

[fractaledmind]

I have dug in more, and I have a clearer picture of what is going on. The top-level point is that it is mostly a happy coincidence that errors are reported in development. But, let me explain.

Errors are reported via the ActionDispatch::Executor middleware:

rails/actionpack/lib/action_dispatch/middleware/executor.rb

Lines 11 to 21 in 3b8222c

	def call(env)
	state = @executor.run!(reset: true)
	begin
	response = @app.call(env)
	returned = response << ::Rack::BodyProxy.new(response.pop) { state.complete! }
	rescue => error
	@executor.error_reporter.report(error, handled: false, source: "application.action_dispatch")
	raise
	ensure
	state.complete! unless returned
	end

You will notice that only raised errors are reported, as we are inside of a rescue block. The issue is that, by default, errors are not raised, they are rendered. This is what happens in the ActionDispatch::ShowExceptions middleware:

rails/actionpack/lib/action_dispatch/middleware/show_exceptions.rb

Lines 30 to 41 in 3b8222c

	def call(env)
	@app.call(env)
	rescue Exception => exception
	request = ActionDispatch::Request.new env
	backtrace_cleaner = request.get_header("action_dispatch.backtrace_cleaner")
	wrapper = ExceptionWrapper.new(backtrace_cleaner, exception)
	if wrapper.show?(request)
	render_exception(request, wrapper)
	else
	raise exception
	end
	end

Inside of this middleware, inside of a rescue block, we see a condition—the error is either rendered or raised. The determinant is the result of ActionDispatch::ExceptionWrapper#show?:

rails/actionpack/lib/action_dispatch/middleware/exception_wrapper.rb

Lines 177 to 191 in 3b8222c

	def show?(request)
	# We're treating `nil` as "unset", and we want the default setting to be
	# `:all`. This logic should be extracted to `env_config` and calculated
	# once.
	config = request.get_header("action_dispatch.show_exceptions")
	case config
	when :none
	false
	when :rescuable
	rescue_response?
	else
	true
	end
	end

You can inspect the config variable, but you will find (as I did) that by default, for both development and production is :all. Thus, the else condition is hit and true is returned. This is the first major detail: in both development and production environments, errors are rendered by the ShowExceptions middleware.

So, the question becomes, how are errors reported in development? The short answer is because development includes the ActionDispatch::Reloader middleware and production does not. But, for those looking to understand what is occurring with more detail, let me elaborate.

In a standard, default Rails application, you will find the following middleware stack in development:

irb(main):001> Rails.application.middleware
=>
#<ActionDispatch::MiddlewareStack:0x0000000105ce77e0
 @middlewares=
  [ActionDispatch::HostAuthorization,
   Rack::Sendfile,
   ActionDispatch::Static,
   ActionDispatch::Executor,
   ActionDispatch::ServerTiming,
   ActiveSupport::Cache::Strategy::LocalCache::Middleware,
   Rack::Runtime,
   Rack::MethodOverride,
   ActionDispatch::RequestId,
   ActionDispatch::RemoteIp,
   Rails::Rack::Logger,
   ActionDispatch::ShowExceptions,
   WebConsole::Middleware,
   ActionDispatch::DebugExceptions,
   ActionDispatch::ActionableExceptions,
   ActionDispatch::Reloader,
   ActionDispatch::Callbacks,
   ActiveRecord::Migration::CheckPending,
   ActionDispatch::Cookies,
   ActionDispatch::Session::CookieStore,
   ActionDispatch::Flash,
   ActionDispatch::ContentSecurityPolicy::Middleware,
   ActionDispatch::PermissionsPolicy::Middleware,
   Rack::Head,
   Rack::ConditionalGet,
   Rack::ETag,
   Rack::TempfileReaper]>

In comparison, you will see this middleware stack in production:

irb(main):001> Rails.application.middleware
=>
#<ActionDispatch::MiddlewareStack:0x000000010943fc60
 @middlewares=
  [Rack::Sendfile,
   ActionDispatch::Static,
   ActionDispatch::Executor,
   Rack::Runtime,
   Rack::MethodOverride,
   ActionDispatch::RequestId,
   ActionDispatch::RemoteIp,
   Rails::Rack::Logger,
   ActionDispatch::ShowExceptions,
   ActionDispatch::DebugExceptions,
   ActionDispatch::Callbacks,
   ActionDispatch::Cookies,
   ActionDispatch::Session::CookieStore,
   ActionDispatch::Flash,
   ActionDispatch::ContentSecurityPolicy::Middleware,
   ActionDispatch::PermissionsPolicy::Middleware,
   Rack::Head,
   Rack::ConditionalGet,
   Rack::ETag,
   Rack::TempfileReaper]>

Diffing these two arrays (dev.map(&:inspect) - prod.map(&:inspect)), we see that development includes these additional middlewares:

["ActionDispatch::HostAuthorization",
 "ActionDispatch::ServerTiming",
 "ActiveSupport::Cache::Strategy::LocalCache::Middleware",
 "WebConsole::Middleware",
 "ActionDispatch::ActionableExceptions",
 "ActionDispatch::Reloader",
 "ActiveRecord::Migration::CheckPending"]

One of these middlewares allows errors to be reported. When adding additional logging to the middlewares, it became clear that errors were reported in development because 2 instances of ActionDispatch::Executor are in the middleware stack. The inner instance sees the raised exception before the ShowExceptions middleware swallows it to render an error HTTP response. This second, inner instance of the Executor is, in fact, the ActionDispatch::Reloader middleware:

rails/actionpack/lib/action_dispatch/middleware/reloader.rb

Lines 3 to 14 in 3b8222c

	module ActionDispatch
	# = Action Dispatch \Reloader
	#
	# ActionDispatch::Reloader wraps the request with callbacks provided by
	# ActiveSupport::Reloader, intended to assist with code reloading during
	# development.
	#
	# ActionDispatch::Reloader is included in the middleware stack only if
	# reloading is enabled, which it is by the default in +development+ mode.
	class Reloader < Executor
	end
	end

It inherits from the Executor and does nothing else. I confess that I don't presently understand how a second instance of the Executor middleware "wraps the request with callbacks provided by ActiveSupport::Reloader", but that is immaterial to our investigation. The essential details is that:

Important

Errors that occur within the HTTP request->response lifecycle are only reported in development if config.enable_reloading is set to true. If set to false, you will observe in that the error reporter is not called.

[fractaledmind]

I have a simple repo ready for experimentation and exploration here: https://github.com/fractaledmind/rails-error-reporter-demo

[byroot]

cc @casperisfine for Monday.