Merge pull request https://github.com/rails/rails/pull/28637 from st0012/fix-partial-cache-logging

actionview/lib/action_view/helpers/cache_helper.rb

@@ -214,8 +214,6 @@ def cache_fragment_name(name = {}, skip_digest: nil, virtual_path: nil)
         end
       end
 
-      attr_reader :cache_hit # :nodoc:
-
     private
 
       def fragment_name_with_digest(name, virtual_path)
@@ -235,13 +233,11 @@ def fragment_name_with_digest(name, virtual_path)
       end
 
       def fragment_for(name = {}, options = nil, &block)
-        # Some tests might using this helper without initialize actionview object
-        @cache_hit ||= {}
         if content = read_fragment_for(name, options)
-          @cache_hit[@virtual_path] = true
+          @view_renderer.cache_hits[@virtual_path] = :hit
           content
         else
-          @cache_hit[@virtual_path] = false
+          @view_renderer.cache_hits[@virtual_path] = :miss
           write_fragment_for(name, options, &block)
         end
       end

actionview/lib/action_view/log_subscriber.rb

@@ -25,7 +25,7 @@ def render_partial(event)
         message = "  Rendered #{from_rails_root(event.payload[:identifier])}"
         message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout]
         message << " (#{event.duration.round(1)}ms)"
-        message << " #{cache_message(event.payload)}" if event.payload.key?(:cache_hit)
+        message << " #{cache_message(event.payload)}" unless event.payload[:cache_hit].nil?
         message
       end
     end
@@ -73,9 +73,10 @@ def render_count(payload) # :doc:
     end
 
     def cache_message(payload) # :doc:
-      if payload[:cache_hit]
+      case payload[:cache_hit]
+      when :hit
         "[cache hit]"
-      else
+      when :miss
         "[cache miss]"
       end
     end

actionview/lib/action_view/renderer/partial_renderer.rb

@@ -344,7 +344,7 @@ def render_partial
           end
 
           content = layout.render(view, locals) { content } if layout
-          payload[:cache_hit] = !!view.cache_hit[@template.virtual_path]
+          payload[:cache_hit] = view.view_renderer.cache_hits[@template.virtual_path]
           content
         end
       end

actionview/lib/action_view/renderer/renderer.rb

@@ -46,5 +46,9 @@ def render_template(context, options) #:nodoc:
     def render_partial(context, options, &block) #:nodoc:
       PartialRenderer.new(@lookup_context).render(context, options, block)
     end
+
+    def cache_hits # :nodoc:
+      @cache_hits ||= {}
+    end
   end
 end

actionview/test/activerecord/relation_cache_test.rb

@@ -4,8 +4,11 @@ class RelationCacheTest < ActionView::TestCase
   tests ActionView::Helpers::CacheHelper
 
   def setup
-    @cache_hit = {}
-    @virtual_path = "path"
+    view_paths     = ActionController::Base.view_paths
+    lookup_context = ActionView::LookupContext.new(view_paths, {}, ["test"])
+    @view_renderer = ActionView::Renderer.new(lookup_context)
+    @virtual_path  = "path"
+
     controller.cache_store = ActiveSupport::Cache::MemoryStore.new
   end
 

actionview/test/template/log_subscriber_test.rb

@@ -8,11 +8,14 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
 
   def setup
     super
-    view_paths = ActionController::Base.view_paths
+
+    view_paths     = ActionController::Base.view_paths
     lookup_context = ActionView::LookupContext.new(view_paths, {}, ["test"])
-    renderer = ActionView::Renderer.new(lookup_context)
-    @view = ActionView::Base.new(renderer, {})
+    renderer       = ActionView::Renderer.new(lookup_context)
+    @view          = ActionView::Base.new(renderer, {})
+
     ActionView::LogSubscriber.attach_to :action_view
+
     unless Rails.respond_to?(:root)
       @defined_root = true
       def Rails.root; :defined_root; end # Minitest `stub` expects the method to be defined.
@@ -21,7 +24,9 @@ def Rails.root; :defined_root; end # Minitest `stub` expects the method to be de
 
   def teardown
     super
+
     ActiveSupport::LogSubscriber.log_subscribers.clear
+
     # We need to undef `root`, RenderTestCases don't want this to be defined
     Rails.instance_eval { undef :root } if @defined_root
   end
@@ -103,9 +108,9 @@ def test_render_partial_with_cache_hitted
       set_view_cache_dependencies
       set_cache_controller
 
-      @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") })
       # Second render should hit cache.
       @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") })
+      @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") })
       wait
 
       assert_equal 2, @logger.logged(:info).size
@@ -113,43 +118,43 @@ def test_render_partial_with_cache_hitted
     end
   end
 
-  def test_render_nested_partial_while_outter_partial_not_cached
+  def test_render_uncached_outer_partial_with_inner_cached_partial_wont_mix_cache_hits_or_misses
     Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do
       set_view_cache_dependencies
       set_cache_controller
 
       @view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
       wait
-      assert_match(/Rendered test\/_nested_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last)
-      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info)[-2])
+      *, cached_inner, uncached_outer = @logger.logged(:info)
+      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner)
+      assert_match(/Rendered test\/_nested_cached_customer\.erb \(.*?ms\)$/, uncached_outer)
 
+      # Second render hits the cache for the _cached_customer partial. Outer template's log shouldn't be affected.
       @view.render(partial: "test/nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
       wait
-      # Outter partial's log should not be affected by inner partial's result.
-      assert_match(/Rendered test\/_nested_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last)
-      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info)[-2])
+      *, cached_inner, uncached_outer = @logger.logged(:info)
+      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, cached_inner)
+      assert_match(/Rendered test\/_nested_cached_customer\.erb \(.*?ms\)$/, uncached_outer)
     end
   end
 
-  def test_render_nested_partial_while_outter_partial_cached
+  def test_render_cached_outer_partial_with_cached_inner_partial
     Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do
       set_view_cache_dependencies
       set_cache_controller
 
       @view.render(partial: "test/cached_nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
       wait
-      assert_match(/Rendered test\/_cached_nested_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last)
-      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info)[-2])
+      *, cached_inner, cached_outer = @logger.logged(:info)
+      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, cached_inner)
+      assert_match(/Rendered test\/_cached_nested_cached_customer\.erb (.*) \[cache miss\]/, cached_outer)
 
-      @view.render(partial: "test/cached_nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
-      wait
+      # One render: inner partial skipped, because the outer has been cached.
+      assert_difference -> { @logger.logged(:info).size }, +1 do
+        @view.render(partial: "test/cached_nested_cached_customer", locals: { cached_customer: Customer.new("Stan") })
+        wait
+      end
       assert_match(/Rendered test\/_cached_nested_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last)
-      # Should not generate log about cached_customer partial
-      assert_equal 3, @logger.logged(:info).size
-
-      @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("Stan") })
-      wait
-      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last)
     end
   end