Fix logged cache key normalization #50008

skipkayhil · 2023-11-10T18:17:18Z

Motivation / Background

Previously, the Cache::Store instrumentation would call normalize_key when adding a key to the log. However, this resulted in the logged key not always matching the actual key written/read from the cache:

irb(main):004> cache.write("foo", "bar", namespace: "baz")
D, [2023-11-10T12:44:59.286362 #169586] DEBUG -- : Cache write: baz:foo ({:compress=>false, :compress_threshold=>1024, :namespace=>"baz"})
=> true
irb(main):005> cache.delete("foo", namespace: "baz")
D, [2023-11-10T12:45:03.071300 #169586] DEBUG -- : Cache delete: foo
=> true

In this example, #write would correctly log that the key written to was baz:foo because the namespace option would be passed to the instrument method. However, other methods like #delete would log that the foo key was deleted because the namespace option was not passed to instrument.

Detail

This commit fixes the issue by making the caller responsible for passing the correct key to #instrument. This allows normalize_key to be removed from the log generation which both prevents the key from being normalized a second time and removes the need to pass the full options hash into #instrument.

Checklist

Before submitting the PR make sure the following are checked:

This Pull Request is related to one change. Changes that are unrelated should be opened in separate PRs.
Commit message has a detailed description of what changed and why. If this PR fixes a related issue include it in the commit message. Ex: [Fix #issue-number]
Tests are added or updated if you fix a bug or add a feature.
CHANGELOG files are updated for the changed libraries if there is a behavior change or additional feature. Minor bug fixes and documentation changes should not be included.

skipkayhil · 2023-11-10T18:19:03Z

activesupport/lib/active_support/cache.rb

+            options = options.dup
+
+            result = instrument(:generate, key, options) do
+              yield(name, WriteOptions.new(options))
+            end
+
+            write(name, result, options) unless result.nil? && options[:skip_nil]
+            result


I inlined this method so that key could be passed to instrument, but I wasn't sure if the method was something that should be kept.

The fetch method is already rather long. My inclination would be to keep save_block_result_to_cache and either add an extra param or just recompute key = normalize_key(name, options) inside it (depending on the overhead).

The subsequent write will recompute the normalized key too. I wonder if there's some elegant way to avoid that? 🤔

Yeah I had the same thought, maybe we should extract a private _write that both fetch and write can call with an already normalized key and merged options? Anyways, I'll put the method back with an extra parameter in the meantime.

jonathanhefner · 2023-11-10T20:34:26Z

activesupport/lib/active_support/cache.rb

+            options = options.dup
+
+            result = instrument(:generate, key, options) do
+              yield(name, WriteOptions.new(options))
+            end
+
+            write(name, result, options) unless result.nil? && options[:skip_nil]
+            result


The fetch method is already rather long. My inclination would be to keep save_block_result_to_cache and either add an extra param or just recompute key = normalize_key(name, options) inside it (depending on the overhead).

The subsequent write will recompute the normalized key too. I wonder if there's some elegant way to avoid that? 🤔

jonathanhefner · 2023-11-10T20:35:31Z

activesupport/test/cache/stores/memory_store_test.rb

+  def test_fetch_logging
+    assert_logs("Cache read: foo") { @cache.fetch("foo") }
+    assert_logs("Cache read: bar:foo") { @cache.fetch("foo", namespace: "bar") }
+  end
+
+  def test_read_logging
+    assert_logs("Cache read: foo") { @cache.read("foo") }
+    assert_logs("Cache read: bar:foo") { @cache.read("foo", namespace: "bar") }
+  end
+
+  def test_write_logging
+    assert_logs("Cache write: foo") { @cache.write("foo", "bar") }
+    assert_logs("Cache write: baz:foo") { @cache.write("foo", "bar", namespace: "baz") }
+  end
+
+  def test_delete_logging
+    assert_logs("Cache delete: foo") { @cache.delete("foo") }
+    assert_logs("Cache delete: bar:foo") { @cache.delete("foo", namespace: "bar") }
+  end
+
+  def test_exist_logging
+    assert_logs("Cache exist?: foo") { @cache.exist?("foo") }
+    assert_logs("Cache exist?: bar:foo") { @cache.exist?("foo", namespace: "bar") }
+  end


Should these tests go in activesupport/test/cache/behaviors/cache_logging_behavior.rb?

I started with that but it got complicated because MemCacheStore has a default random namespace, and FileStore keys end up being a path, so it ends up being harder to make concrete assertions. I'll see if I can figure something out with regex or special casing the problematic stores.

Done. The regular expressions are a little cursed but the tests themselves don't look too bad 😅

I pushed a commit that attempts to simplify the patterns. After factoring out the key_pattern helper, I felt like the assert_logs_key helper wasn't really worth the extra indirection, but I could go either way. Let me know what you think.

Looks great! Keeping the complexity inside FileStoreTest is really nice

jonathanhefner · 2023-11-10T20:39:30Z

activesupport/lib/active_support/cache/redis_cache_store.rb

+        unless String === matcher
+          raise ArgumentError, "Only Redis glob strings are supported: #{matcher.inspect}"
+        end
+        options = merged_options(options)


Is this call to merged_options necessary?

Ah, you're right, it's not needed at the moment because namespace_key will merge the options anyways.

Previously, the `Cache::Store` instrumentation would call `normalize_key` when adding a key to the log. However, this resulted in the logged key not always matching the actual key written/read from the cache: ```irb irb(main):004> cache.write("foo", "bar", namespace: "baz") D, [2023-11-10T12:44:59.286362 #169586] DEBUG -- : Cache write: baz:foo ({:compress=>false, :compress_threshold=>1024, :namespace=>"baz"}) => true irb(main):005> cache.delete("foo", namespace: "baz") D, [2023-11-10T12:45:03.071300 #169586] DEBUG -- : Cache delete: foo => true ``` In this example, `#write` would correctly log that the key written to was `baz:foo` because the `namespace` option would be passed to the `instrument` method. However, other methods like `#delete` would log that the `foo` key was deleted because the `namespace` option was _not_ passed to `instrument`. This commit fixes the issue by making the caller responsible for passing the correct key to `#instrument`. This allows `normalize_key` to be removed from the log generation which both prevents the key from being normalized a second time and removes the need to pass the full options hash into `#instrument`. Co-authored-by: Jonathan Hefner <jonathan@hefner.pro>

jonathanhefner · 2023-11-11T19:12:51Z

Thank you, @skipkayhil! 🪵

Thanks to rails/rails#50008, I found that the Rails cache key should be treated as String. This patch changes the Rails cache to set String instead of Integer to follow the expected cache key type.

rails-bot bot added the activesupport label Nov 10, 2023

skipkayhil commented Nov 10, 2023

View reviewed changes

jonathanhefner reviewed Nov 10, 2023

View reviewed changes

skipkayhil force-pushed the hm-cache-key-normalization branch from f567679 to 638fbaa Compare November 11, 2023 03:25

jonathanhefner force-pushed the hm-cache-key-normalization branch from 8a8fa08 to 9af99bf Compare November 11, 2023 18:59

jonathanhefner merged commit 9194b33 into rails:main Nov 11, 2023
4 checks passed

skipkayhil deleted the hm-cache-key-normalization branch November 11, 2023 19:14

yykamei mentioned this pull request Nov 12, 2023

Set explicit string key for Rails cache yykamei/rails_band#123

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix logged cache key normalization #50008

Fix logged cache key normalization #50008

skipkayhil commented Nov 10, 2023

skipkayhil Nov 10, 2023

jonathanhefner Nov 10, 2023

skipkayhil Nov 10, 2023

jonathanhefner Nov 10, 2023

jonathanhefner Nov 10, 2023

skipkayhil Nov 10, 2023

skipkayhil Nov 11, 2023

jonathanhefner Nov 11, 2023

skipkayhil Nov 11, 2023

jonathanhefner Nov 10, 2023

skipkayhil Nov 11, 2023

jonathanhefner commented Nov 11, 2023

Fix logged cache key normalization #50008

Fix logged cache key normalization #50008

Conversation

skipkayhil commented Nov 10, 2023

Motivation / Background

Detail

Checklist

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jonathanhefner commented Nov 11, 2023