Merge pull request #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,53 +108,53 @@ 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
      assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last)
    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