When I was working on integrating Rodauth with OmniAuth authentication, I noticed an error warning after upgrading to Rails 6.1, when Rodauth was redirecting inside a Rails controller action:
class RodauthController < ApplicationController
def omniauth
# ...
rodauth.login("omniauth") # logs the session in and redirects
end
end
Could not log "process_action.action_controller" event.
/path/to/actionpack-6.1.1/lib/action_controller/log_subscriber.rb:26:in `block in process_action': undefined method `first' for nil:NilClass (NoMethodError)
Since I want the integration between Rodauth and Rails to be as smooth as possible, I decided to investigate.
Diving in
Let's see the ActionController::LogSubscriber
source code where the error happens:
# lib/action_controller/log_subscriber.rb
module ActionController
class LogSubscriber < ActiveSupport::LogSubscriber
# ...
def process_action(event)
# ...
status = payload[:status]
if status.nil? && (exception_class_name = payload[:exception].first) # <==== the exception happens here
status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
end
# ...
end
# ...
end
end
We can see that the issue happens because :exception
data is missing from the instrumentation event payload. Let's look at ActionController::Instrumentation
next, which is in charge of instrumenting controller actions:
# lib/action_controller/metal/instrumentation.rb
class ActionController
module Instrumentation
def process_action(*)
# ...
ActiveSupport::Notifications.instrument("process_action.action_controller", raw_payload) do |payload|
result = super # <=== this calls our controller action
payload[:response] = response
payload[:status] = response.status
# ...
end
end
end
end
We can see that, if our controller action raises an exception, the :status
data will never be set. This ties to the status.nil?
check we've seen in the ActionController::LogSubscriber
.
The remaining part is to find where :exception
is being set. Knowing that instrumentation is implemented in Active Support, I quickly found ActiveSupport::Notifications::Instrumenter
:
# lib/active_support/notifications/instrumenter.rb
module ActiveSupport
module Notifications
class Instrumenter
# ...
def instrument(name, payload = {})
# ...
begin
yield payload if block_given?
rescue Exception => e
payload[:exception] = [e.class.name, e.message] # <==== the exception is set here
payload[:exception_object] = e
raise e
ensure
finish_with_state listeners_state, name, payload
end
end
end
end
end
The problem
When Rodauth redirects, what is actually doing is throwing :halt
with the rack response. This is how Roda implements redirection, and it's common practice in non-Rails web frameworks (Sinatra and Cuba do it too). In our case, throwing exits from controller action and is caught by the Roda middleware.
Does throwing act the same way as raising an exception does? Initially it would appear so:
begin
throw :halt
rescue Exception => exception
puts "rescue: #{exception.inspect}"
raise
ensure
puts "ensure"
end
rescue: #<UncaughtThrowError: uncaught throw :halt>
ensure
~> uncaught throw :halt (UncaughtThrowError)
This makes sense to me, because uncaught throw is an exception. But then why wasn't the rescue
block that was supposed to set the :exception
in the event payload being executed?
The picture starts getting clearer when we wrap the code with a catch
block:
catch(:halt) do
begin
throw :halt
rescue Exception => exception
puts "rescue: #{exception.inspect}"
raise
ensure
puts "ensure"
end
end
ensure
We see that in this case the rescue
block isn't being executed, and this is precisely our scenario. This actually makes sense when you think about it, because a throw
with a matching catch
is not anything erroneous, it's just a way to do an early return.
The solution
Now we know where the issue is, which is that Rails just wasn't correctly handling a throw
/catch
scenario when processing controller actions. Fixing it was the easy part.
throw
/catch
is probably something you'll rarely use, but it does have its use cases. I hope this article taught you a bit more about this lesser known Ruby feature.
Top comments (0)