Simultaneous requests cause ActionDispatch::IllegalStateError (header already sent)

[harigopal]

It appears that there's something wrong with the way the header is being set by this gem. I'm getting ActionDispatch::IllegalStateError when a second request is sent to the server before it is done processing a previous one. This causes tests to fail, and is pretty annoying in the dev environment when working with slow requests. I haven't noticed this in production.

Demo of the bug: https://github.com/harigopal/rst_headers_sent_bug_demo

Relevant portion of the backtrace:

/Users/hari/.rbenv/versions/2.4.2/lib/ruby/2.4.0/delegate.rb:85:in `call'
/Users/hari/.rbenv/versions/2.4.2/lib/ruby/2.4.0/delegate.rb:85:in `method_missing'
actionpack (5.1.4) lib/action_dispatch/http/response.rb:44:in `[]='
rails_server_timings (1.0.7) lib/rails_server_timings/controller_runtime.rb:17:in `block in process_action'
activesupport (5.1.4) lib/active_support/notifications/fanout.rb:127:in `finish'
activesupport (5.1.4) lib/active_support/notifications/fanout.rb:46:in `block in finish'
activesupport (5.1.4) lib/active_support/notifications/fanout.rb:46:in `each'
activesupport (5.1.4) lib/active_support/notifications/fanout.rb:46:in `finish'
activesupport (5.1.4) lib/active_support/notifications/instrumenter.rb:42:in `finish_with_state'
activesupport (5.1.4) lib/active_support/notifications/instrumenter.rb:27:in `instrument'
activesupport (5.1.4) lib/active_support/notifications.rb:166:in `instrument'
actionpack (5.1.4) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
actionpack (5.1.4) lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
activerecord (5.1.4) lib/active_record/railties/controller_runtime.rb:22:in `process_action'
rails_server_timings (1.0.7) lib/rails_server_timings/controller_runtime.rb:22:in `block in process_action'
activesupport (5.1.4) lib/active_support/notifications.rb:178:in `subscribed'
rails_server_timings (1.0.7) lib/rails_server_timings/controller_runtime.rb:21:in `process_action'
actionpack (5.1.4) lib/abstract_controller/base.rb:124:in `process'

It appears that the gem is attempting to set the header when, in action_dispatch/http/response.rb, the response is either sending, or has already been sent. 🤷‍♂️

def []=(k, v)
  if @response.sending? || @response.sent?
    raise ActionDispatch::IllegalStateError, "header already sent"
  end

  ...

full_backtrace.txt

[dpogue]

I've been trying to track this down for a while, and I think I've figured out what causes it, but I'm still not sure how to fix it.

It happens when simultaneous requests occur while using Puma as a Rails server.

What's actually happening is that the rails_server_timings's process_action block is getting called for both actions, for each request. So the first request comes in and runs and adds its header, and then the second request comes in and our block gets called again with the data from the second request but the context of the first request. That causes the IllegalStateError because we've already sent the first request.

My guess is that this is due somehow to the way Puma does threading, and we might be able to avoid it by storing the current request ID in a thread-local variable, and only adding the header to the matching request. I haven't had a chance to verify that suspicion though.

Another option would be to turn the header-adding part into a Rack middleware, à la server_timing_middleware