Merge pull request rails#50008 from skipkayhil/hm-cache-key-normalization

Fix logged cache key normalization

Author: jonathanhefner

activesupport/CHANGELOG.md

@@ -1,3 +1,7 @@
+*   Fix logged cache keys not always matching actual key used by cache action.
+
+    *Hartley McGuire*
+
 *   Improve error messages of `assert_changes` and `assert_no_changes`
 
     `assert_changes` error messages now display objects with `.inspect` to make it easier

activesupport/lib/active_support/cache.rb

@@ -456,7 +456,7 @@ def fetch(name, options = nil, &block)
 
           entry = nil
           unless options[:force]
-            instrument(:read, name, options) do |payload|
+            instrument(:read, key, options) do |payload|
               cached_entry = read_entry(key, **options, event: payload)
               entry = handle_expired_entry(cached_entry, key, options)
               if entry
@@ -478,7 +478,7 @@ def fetch(name, options = nil, &block)
           if entry
             get_entry_value(entry, name, options)
           else
-            save_block_result_to_cache(name, options, &block)
+            save_block_result_to_cache(name, key, options, &block)
           end
         elsif options && options[:force]
           raise ArgumentError, "Missing block: Calling `Cache#fetch` with `force: true` requires a block."
@@ -508,7 +508,7 @@ def read(name, options = nil)
         key     = normalize_key(name, options)
         version = normalize_version(name, options)
 
-        instrument(:read, name, options) do |payload|
+        instrument(:read, key, options) do |payload|
           entry = read_entry(key, **options, event: payload)
 
           if entry
@@ -662,10 +662,11 @@ def fetch_multi(*names)
       # Other options will be handled by the specific cache store implementation.
       def write(name, value, options = nil)
         options = merged_options(options)
+        key = normalize_key(name, options)
 
-        instrument(:write, name, options) do
+        instrument(:write, key, options) do
           entry = Entry.new(value, **options.merge(version: normalize_version(name, options)))
-          write_entry(normalize_key(name, options), entry, **options)
+          write_entry(key, entry, **options)
         end
       end
 
@@ -675,9 +676,10 @@ def write(name, value, options = nil)
       # Options are passed to the underlying cache implementation.
       def delete(name, options = nil)
         options = merged_options(options)
+        key = normalize_key(name, options)
 
-        instrument(:delete, name) do
-          delete_entry(normalize_key(name, options), **options)
+        instrument(:delete, key) do
+          delete_entry(key, **options)
         end
       end
 
@@ -701,9 +703,10 @@ def delete_multi(names, options = nil)
       # Options are passed to the underlying cache implementation.
       def exist?(name, options = nil)
         options = merged_options(options)
+        key = normalize_key(name, options)
 
-        instrument(:exist?, name) do |payload|
-          entry = read_entry(normalize_key(name, options), **options, event: payload)
+        instrument(:exist?, key) do |payload|
+          entry = read_entry(key, **options, event: payload)
           (entry && !entry.expired? && !entry.mismatched?(normalize_version(name, options))) || false
         end
       end
@@ -1016,7 +1019,7 @@ def _instrument(operation, multi: false, options: nil, **payload, &block)
               if multi
                 ": #{payload[:key].size} key(s) specified"
               elsif payload[:key]
-                ": #{normalize_key(payload[:key], options)}"
+                ": #{payload[:key]}"
               end
 
             debug_options = " (#{options.inspect})" unless options.blank?
@@ -1052,10 +1055,10 @@ def get_entry_value(entry, name, options)
           entry.value
         end
 
-        def save_block_result_to_cache(name, options)
+        def save_block_result_to_cache(name, key, options)
           options = options.dup
 
-          result = instrument(:generate, name, options) do
+          result = instrument(:generate, key, options) do
             yield(name, WriteOptions.new(options))
           end
 

activesupport/lib/active_support/cache/file_store.rb

@@ -78,8 +78,9 @@ def decrement(name, amount = 1, options = nil)
 
       def delete_matched(matcher, options = nil)
         options = merged_options(options)
+        matcher = key_matcher(matcher, options)
+
         instrument(:delete_matched, matcher.inspect) do
-          matcher = key_matcher(matcher, options)
           search_dir(cache_path) do |path|
             key = file_path_key(path)
             delete_entry(path, **options) if key.match(matcher)

activesupport/lib/active_support/cache/mem_cache_store.rb

@@ -179,9 +179,11 @@ def inspect
       # <tt>raw: true</tt>, will fail and return +nil+.
       def increment(name, amount = 1, options = nil)
         options = merged_options(options)
-        instrument(:increment, name, amount: amount) do
+        key = normalize_key(name, options)
+
+        instrument(:increment, key, amount: amount) do
           rescue_error_with nil do
-            @data.with { |c| c.incr(normalize_key(name, options), amount, options[:expires_in], amount) }
+            @data.with { |c| c.incr(key, amount, options[:expires_in], amount) }
           end
         end
       end
@@ -203,9 +205,11 @@ def increment(name, amount = 1, options = nil)
       # <tt>raw: true</tt>, will fail and return +nil+.
       def decrement(name, amount = 1, options = nil)
         options = merged_options(options)
-        instrument(:decrement, name, amount: amount) do
+        key = normalize_key(name, options)
+
+        instrument(:decrement, key, amount: amount) do
           rescue_error_with nil do
-            @data.with { |c| c.decr(normalize_key(name, options), amount, options[:expires_in], 0) }
+            @data.with { |c| c.decr(key, amount, options[:expires_in], 0) }
           end
         end
       end

activesupport/lib/active_support/cache/memory_store.rb

@@ -168,8 +168,9 @@ def decrement(name, amount = 1, options = nil)
       # Deletes cache entries if the cache key matches a given pattern.
       def delete_matched(matcher, options = nil)
         options = merged_options(options)
+        matcher = key_matcher(matcher, options)
+
         instrument(:delete_matched, matcher.inspect) do
-          matcher = key_matcher(matcher, options)
           keys = synchronize { @data.keys }
           keys.each do |key|
             delete_entry(key, **options) if key.match(matcher)

activesupport/lib/active_support/cache/redis_cache_store.rb

@@ -192,12 +192,13 @@ def read_multi(*names)
       #
       # Failsafe: Raises errors.
       def delete_matched(matcher, options = nil)
-        instrument :delete_matched, matcher do
-          unless String === matcher
-            raise ArgumentError, "Only Redis glob strings are supported: #{matcher.inspect}"
-          end
+        unless String === matcher
+          raise ArgumentError, "Only Redis glob strings are supported: #{matcher.inspect}"
+        end
+        pattern = namespace_key(matcher, options)
+
+        instrument :delete_matched, pattern do
           redis.then do |c|
-            pattern = namespace_key(matcher, options)
             cursor = "0"
             # Fetch keys in batches using SCAN to avoid blocking the Redis server.
             nodes = c.respond_to?(:nodes) ? c.nodes : [c]
@@ -230,10 +231,11 @@ def delete_matched(matcher, options = nil)
       #
       # Failsafe: Raises errors.
       def increment(name, amount = 1, options = nil)
-        instrument :increment, name, amount: amount do
+        options = merged_options(options)
+        key = normalize_key(name, options)
+
+        instrument :increment, key, amount: amount do
           failsafe :increment do
-            options = merged_options(options)
-            key = normalize_key(name, options)
             change_counter(key, amount, options)
           end
         end
@@ -256,10 +258,11 @@ def increment(name, amount = 1, options = nil)
       #
       # Failsafe: Raises errors.
       def decrement(name, amount = 1, options = nil)
-        instrument :decrement, name, amount: amount do
+        options = merged_options(options)
+        key = normalize_key(name, options)
+
+        instrument :decrement, key, amount: amount do
           failsafe :decrement do
-            options = merged_options(options)
-            key = normalize_key(name, options)
             change_counter(key, -amount, options)
           end
         end

activesupport/test/cache/behaviors/cache_logging_behavior.rb

@@ -3,6 +3,56 @@
 require "active_support/core_ext/object/with"
 
 module CacheLoggingBehavior
+  def test_fetch_logging
+    assert_logs(/Cache read: #{key_pattern("foo")}/) do
+      @cache.fetch("foo")
+    end
+
+    assert_logs(/Cache read: #{key_pattern("foo", namespace: "bar")}/) do
+      @cache.fetch("foo", namespace: "bar")
+    end
+  end
+
+  def test_read_logging
+    assert_logs(/Cache read: #{key_pattern("foo")}/) do
+      @cache.read("foo")
+    end
+
+    assert_logs(/Cache read: #{key_pattern("foo", namespace: "bar")}/) do
+      @cache.read("foo", namespace: "bar")
+    end
+  end
+
+  def test_write_logging
+    assert_logs(/Cache write: #{key_pattern("foo")}/) do
+      @cache.write("foo", "qux")
+    end
+
+    assert_logs(/Cache write: #{key_pattern("foo", namespace: "bar")}/) do
+      @cache.write("foo", "qux", namespace: "bar")
+    end
+  end
+
+  def test_delete_logging
+    assert_logs(/Cache delete: #{key_pattern("foo")}/) do
+      @cache.delete("foo")
+    end
+
+    assert_logs(/Cache delete: #{key_pattern("foo", namespace: "bar")}/) do
+      @cache.delete("foo", namespace: "bar")
+    end
+  end
+
+  def test_exist_logging
+    assert_logs(/Cache exist\?: #{key_pattern("foo")}/) do
+      @cache.exist?("foo")
+    end
+
+    assert_logs(/Cache exist\?: #{key_pattern("foo", namespace: "bar")}/) do
+      @cache.exist?("foo", namespace: "bar")
+    end
+  end
+
   def test_read_multi_logging
     assert_logs("Cache read_multi: 1 key(s)") { @cache.read_multi("foo") }
     assert_logs("Cache read_multi: 2 key(s)") { @cache.read_multi("foo", "bar") }
@@ -26,4 +76,8 @@ def assert_logs(pattern, &block)
       ActiveSupport::Cache::Store.with(logger: Logger.new(io, level: :debug), &block)
       assert_match pattern, io.string
     end
+
+    def key_pattern(key, namespace: @namespace)
+      /#{Regexp.escape namespace.to_s}#{":" if namespace}#{Regexp.escape key}/
+    end
 end

activesupport/test/cache/stores/file_store_test.rb

@@ -158,4 +158,9 @@ def test_write_with_unless_exist
     @cache.write(1, nil)
     assert_equal false, @cache.write(1, "aaaaaaaaaa", unless_exist: true)
   end
+
+  private
+    def key_pattern(key, namespace: nil)
+      /.+\/#{Regexp.escape namespace.to_s}#{/%3A/i if namespace}#{Regexp.escape key}/
+    end
 end