rails / actionpack-action_caching

Action caching for Action Pack (removed from core in Rails 4.0)
MIT License
260 stars 95 forks source link

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

Open tom-kuca opened 2 years ago

tom-kuca commented 2 years ago

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.

https://github.com/rails/actionpack-action_caching/blob/05c821ec84eb79760e95b0a57ae72919eefb0257/lib/action_controller/caching/actions.rb#L171

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

hakunin commented 1 month ago

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 commented 1 month ago

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

-    include ActiveStorage::Streaming
+    include ActionController::DataStreaming
hakunin commented 1 month ago

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