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

1 files changed, 26 insertions, 21 deletions

diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb
index 94d2c35635..4c9f84f277 100644
--- a/actionview/test/template/log_subscriber_test.rb
+++ b/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 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
 
   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 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       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 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
     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