"header already sent" on cache miss when ActionController::Live is included

[tom-kuca]

Given a controller

class ArticlesController < ApplicationController
  include ActionController::Live
  ...
  caches_action :index
  ...
end

calling/articles with an empty cache triggers the error below. The page is rendered and cached correctly despite the error in the log.

Started GET "/articles" for 127.0.0.1 at 2022-09-24 02:55:47 +0200
   (0.3ms)  SELECT sqlite_version(*)
  ActiveRecord::SchemaMigration Pluck (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by ArticlesController#index as HTML
Read fragment views/localhost:3000/articles (0.1ms)
  Rendering layout layouts/application.html.erb
  Rendering articles/index.html.erb within layouts/application
   (0.1ms)  SELECT sqlite_version(*)
  ↳ app/views/articles/index.html.erb:6
  Article Load (0.1ms)  SELECT "articles".* FROM "articles"
  ↳ app/views/articles/index.html.erb:6
  Rendered articles/index.html.erb within layouts/application (Duration: 4.7ms | Allocations: 1751)
  Rendered layout layouts/application.html.erb (Duration: 37.4ms | Allocations: 36077)
Write fragment views/localhost:3000/articles (0.1ms)
Completed 500 Internal Server Error in 45ms (Views: 38.8ms | ActiveRecord: 0.5ms | Allocations: 42557)



IOError (closed stream):
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_dispatch/http/response.rb:115:in `write'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:157:in `write'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:271:in `rescue in block (2 levels) in process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:268:in `block (2 levels) in process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/concurrency/share_lock.rb:162:in `sharing'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/dependencies/interlock.rb:37:in `running'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:258:in `block in process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:344:in `block in new_controller_thread'



ActionDispatch::IllegalStateError (header already sent):
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/2.7.0/delegate.rb:85:in `bind_call'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/2.7.0/delegate.rb:85:in `method_missing'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_dispatch/http/response.rb:46:in `[]='
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_dispatch/http/response.rb:181:in `set_header'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_dispatch/http/response.rb:436:in `set_content_type'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_dispatch/http/response.rb:240:in `content_type='
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal.rb:147:in `content_type='
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-action_caching-1.2.2/lib/action_controller/caching/actions.rb:171:in `around'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actiontext-7.0.3.1/lib/action_text/rendering.rb:20:in `with_renderer'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actiontext-7.0.3.1/lib/action_text/engine.rb:69:in `block (4 levels) in <class:Engine>'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:127:in `instance_exec'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:138:in `run_callbacks'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/abstract_controller/callbacks.rb:233:in `process_action'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/notifications.rb:206:in `block in instrument'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/notifications.rb:206:in `instrument'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/instrumentation.rb:66:in `process_action'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activerecord-7.0.3.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/abstract_controller/base.rb:151:in `process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionview-7.0.3.1/lib/action_view/rendering.rb:39:in `process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:267:in `block (2 levels) in process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/concurrency/share_lock.rb:162:in `sharing'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/activesupport-7.0.3.1/lib/active_support/dependencies/interlock.rb:37:in `running'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:258:in `block in process'
  /home/tomas/.rbenv/versions/2.7.4/lib/ruby/gems/2.7.0/gems/actionpack-7.0.3.1/lib/action_controller/metal/live.rb:344:in `block in new_controller_thread'

Expected behavior

The page should be rendered and cached correctly (as it is) and there should not be any error in the log.

Notes

In my case, ActionController::Live was included transitively by include ActiveStorage::Streaming.

The problem is caused by setting content type at the end of around filter. At that point, the response is already commited if ActionController::Live is included.

actionpack-action_caching/lib/action_controller/caching/actions.rb

Line 171 in 05c821e

controller.content_type = Mime[cache_path.extension || :html]

The page is still rendered and cached correctly, because it was already submitted before the error is triggered. The error is not present in following requests which hit the cache.

I was able to reproduced it in a blank rails application, with a single controller generated by scaffolding.

Versions

• ruby 2.7.4p191
• rails (7.0.3.1)
• actionpack-action_caching (1.2.2)

[hakunin]

Ran into this myself, same line causing the issue with Rails 6.1.
include ActionController::Live also present.

Did you find a workaround?

[tom-kuca]

I didn't need most of ActiveStorage::Streaming, I replaced it with ActionController::DataStreaming.

-    include ActiveStorage::Streaming
+    include ActionController::DataStreaming

[hakunin]

I ended up doing this:

require 'action_controller/caching/actions'

# Workaround for known issue
# https://github.com/rails/actionpack-action_caching/issues/83
module ActionController
  module Caching
    module Actions
      class ActionCacheFilter

        alias_method :original_around, :around

        def around(controller)
          original_around(controller) { yield }
        rescue ActionDispatch::IllegalStateError => e
          Rails.logger.error(
            "Silenced ActionPack / IllegalStateError: #{e.message}"
          )
        end
      end
    end
  end
end