From a6e9e3ef1ccb43fe0dd44988a7d7e208647eef6b Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Sat, 3 Oct 2026 22:18:00 -0400 Subject: [PATCH] fix(cache): cache keys too long to be a filename; memory hits judged by the record's own age (#738) * fix(cache): store keys too long to be a filename The calendar plugin's cache key joins every calendar id the user picked. On hdpi it passed 300 bytes; ext4 caps a filename at 255, so every write (the temp file, the direct-write fallback and the home-directory fallback) failed with ENAMETOOLONG, once an hour, and the final warning said "(permission denied)" whatever the error was. DiskCache.get_cache_path keeps a key of up to 200 UTF-8 bytes as its filename, exactly as before, and turns a longer one into its first 183 bytes (cut on a character boundary) plus a 16-hex-digit hash of the whole key. The temp file adds 15 bytes, so the longest name is 215. The shortened stem is itself short, so the web UI's cache list, which names a key by its filename, deletes the same file. The give-up warning now names the real error. Validated on ledpi's ext4: the old module drops the hdpi-shaped key, the new one writes a 205-byte filename and reads it back. Co-Authored-By: Claude Opus 5.5 * fix(cache): judge a memory hit by the record's own timestamp A record loaded from disk went into the memory tier timed from the load, so get(key, max_age=300) could return data close to 600 s old: after a restart, after the memory sweep, or in a second process. A stored ttl was stretched the same way. #728's _fresh_cached works around it for the scoreboard; every other caller was exposed. get_cached_data and load_cache now also check a memory hit against the record's embedded timestamp, with DiskCache.get's rule that a stored ttl wins over max_age. A stale copy is dropped and the read falls through to disk, which returns the other process's newer write if there is one. Records without a timestamp keep the memory tier's own clock. Co-Authored-By: Claude Opus 5.5 --------- Co-authored-by: Claude Opus 5.5 --- CHANGELOG.md | 17 +++++ src/cache/disk_cache.py | 45 ++++++++++++-- src/cache_manager.py | 36 ++++++++++- test/test_cache_long_keys.py | 99 ++++++++++++++++++++++++++++++ test/test_cache_memory_tier_age.py | 95 ++++++++++++++++++++++++++++ 5 files changed, 285 insertions(+), 7 deletions(-) create mode 100644 test/test_cache_long_keys.py create mode 100644 test/test_cache_memory_tier_age.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 35ac9182..93ea830f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -488,6 +488,23 @@ policies are unchanged. ### Fixes +- A cache key too long to be a filename is now cached. The calendar + plugin's key joins every calendar id the user picked; on a real install + it passed 300 bytes, ext4 refuses names over 255, and every write failed + with `File name too long` — logged as "(permission denied)", so it read + like a cache-directory ownership problem. `DiskCache.get_cache_path` now + keeps a key of up to 200 UTF-8 bytes as its filename, as before, and + turns a longer one into its first bytes plus a hash of the whole key. The + web UI's cache list and delete keep working, because the shortened name + maps back to the same file. A failed write now names the real error. +- The cache's memory tier no longer serves data older than the reader asked + for. A record loaded from disk was timed in memory from the load, not + from when it was written, so `get(key, max_age=300)` could return data + close to 600 s old (after a restart, after the hourly memory sweep, or in + the other process, which only ever loads the record from disk), and a + stored `ttl` was stretched the same way. A memory hit is now also checked against + the record's own timestamp, and a stale one falls through to disk, which + returns a newer write if there is one. - The garbage-collection timer (`GcMonitor`, above) no longer prints `Exception ignored while calling GC callback ... 'NoneType' object has no attribute 'perf_counter'` when the display service or a test run exits. diff --git a/src/cache/disk_cache.py b/src/cache/disk_cache.py index a31782b9..e66f4b10 100644 --- a/src/cache/disk_cache.py +++ b/src/cache/disk_cache.py @@ -4,6 +4,7 @@ Disk Cache Handles persistent disk-based caching with atomic writes and error recovery. """ +import hashlib import json import math import os @@ -31,6 +32,35 @@ except ImportError: # pragma: no cover - exercised on hosts without the wheel # useful, and a half-written file was never useful. _ORPHAN_TEMP_MAX_AGE_SECONDS = 3600 +# Longest key, in UTF-8 bytes, used verbatim as a filename stem. ext4 caps a +# name at 255 bytes and set()'s temp file is "..json.<8 random>", 15 +# bytes longer than the stem, so anything near the cap could never be written: +# the calendar plugin's key joins every calendar id and passed 300 bytes on a +# real install, failing every write with ENAMETOOLONG. Longer keys keep this +# many bytes as a readable prefix and end in a hash of the whole key. +_MAX_KEY_FILENAME_BYTES = 200 +_KEY_HASH_CHARS = 16 + + +def _filename_stem(key: str) -> str: + """The filename stem for a key that is already a safe path component. + + Short keys are used as they are, so every file already on disk keeps its + name. A long one becomes its first bytes plus a hash of the full key: the + prefix keeps the stem recognisable (and keeps the data-type words that + cleanup's retention lookup reads from it), the hash keeps two keys that + share a long prefix apart. The result is itself short, so a stem read back + from a filename -- which is how the web UI names a key it deletes -- maps to + the same file. + """ + encoded = key.encode('utf-8') + if len(encoded) <= _MAX_KEY_FILENAME_BYTES: + return key + digest = hashlib.sha256(encoded).hexdigest()[:_KEY_HASH_CHARS] + keep = _MAX_KEY_FILENAME_BYTES - _KEY_HASH_CHARS - 1 + prefix = encoded[:keep].decode('utf-8', errors='ignore') + return f"{prefix}-{digest}" + class CacheStrategyProtocol(Protocol): @@ -343,6 +373,8 @@ class DiskCache: derives them), so rejecting anything with a path component turns away only inputs that could never have been written here. + A key too long to be a filename is shortened by _filename_stem. + Args: key: Cache key @@ -356,7 +388,7 @@ class DiskCache: if safe_key is None: self.logger.warning("Rejected unsafe cache key %r", key) return None - return os.path.join(self.cache_dir, f"{safe_key}.json") + return os.path.join(self.cache_dir, f"{_filename_stem(safe_key)}.json") def get(self, key: str, max_age: Optional[int] = 300) -> Optional[Dict[str, Any]]: """ @@ -561,7 +593,7 @@ class DiskCache: # If direct write also fails, try fallback location self.logger.warning("Direct write failed for key '%s' to %s: %s", key, cache_path, write_error) raise # Re-raise to trigger fallback logic - except (IOError, OSError, PermissionError): + except (IOError, OSError, PermissionError) as primary_error: # Attempt one-time fallback write to user's home cache directory try: # Try user's home cache directory as fallback @@ -587,11 +619,14 @@ class DiskCache: self.logger.debug("Fallback cache write also failed for key '%s': %s", key, e2) # If all write attempts failed, log warning but don't raise exception - # Cache is a performance optimization, not critical for operation + # Cache is a performance optimization, not critical for operation. + # Name the real error: this used to say "permission denied" + # whatever happened, which sent a too-long filename off to + # be debugged as a directory-ownership problem. self.logger.warning( - "Could not write cache for key '%s' to %s (permission denied). " + "Could not write cache for key '%s' to %s (%s). " "Cache will be unavailable for this key, but application will continue.", - key, cache_path + key, cache_path, primary_error.strerror or primary_error ) return # Exit gracefully without raising exception diff --git a/src/cache_manager.py b/src/cache_manager.py index 56fbdf9a..f18d2380 100644 --- a/src/cache_manager.py +++ b/src/cache_manager.py @@ -46,6 +46,32 @@ from src.cache.disk_cache import DateTimeEncoder # noqa: F401 - deliberate re-e # CacheManager.config_manager not built yet (None means "not available"). _UNSET: Any = object() + +def _outlived(record: Any, max_age: Optional[float], now: float) -> bool: + """Whether a record's own timestamp puts it past max_age. + + The memory tier times an entry from when it was put there, and a record + loaded from disk is put there when it is read, not when it was written: a + record 290 s old, read after a restart, could be served for another + max_age from memory. This is the age check DiskCache.get makes, with the + same rule that a stored ttl wins over the caller's max_age. A record that + carries no timestamp is left to the memory tier's own clock. + """ + if not isinstance(record, dict): + return False + stored_ttl = record.get('ttl') + if isinstance(stored_ttl, (int, float)) and not isinstance(stored_ttl, bool) \ + and stored_ttl >= 0: + max_age = stored_ttl + stamp = record.get('timestamp') + if max_age is None or stamp is None or isinstance(stamp, bool): + return False + try: + return now - float(stamp) > max_age + except (TypeError, ValueError): + return False + + class CacheManager: """Manages caching of API responses to reduce API calls.""" @@ -284,7 +310,11 @@ class CacheManager: # 1) Memory cache cached = self._memory_cache_component.get(key, max_age=in_memory_ttl) if cached is not None: - return cached + if not _outlived(cached, max_age, time.time()): + return cached + # Too old for this reader. Disk may hold a newer write (from the + # other process), and if it does not, the miss is the right answer. + self._memory_cache_component.clear(key) # 2) Disk cache record = self._disk_cache_component.get(key, max_age=max_age) @@ -318,7 +348,9 @@ class CacheManager: # Check memory cache first (1 minute TTL) cached = self._memory_cache_component.get(key, max_age=60) if cached is not None: - return cached + if not _outlived(cached, 3600, time.time()): + return cached + self._memory_cache_component.clear(key) # Check disk cache data = self._disk_cache_component.get(key, max_age=3600) # 1 hour for load_cache diff --git a/test/test_cache_long_keys.py b/test/test_cache_long_keys.py new file mode 100644 index 00000000..22f4714f --- /dev/null +++ b/test/test_cache_long_keys.py @@ -0,0 +1,99 @@ +"""A cache key too long to be a filename still gets a cache file. + +The calendar plugin's key joins every calendar id the user picked; on a real +install it passed 300 bytes, and since ext4 caps a filename at 255 every write +failed with ENAMETOOLONG -- logged as "permission denied", every update. +""" + +import logging +import os +from unittest.mock import patch + +from src.cache.disk_cache import DiskCache, _MAX_KEY_FILENAME_BYTES, _filename_stem +from src.cache_manager import CacheManager + +# The shape of the key that failed on hdpi, ids anonymised. +CALENDAR_KEY = ( + "calendar_events_someone@example.com_en.usa#holiday@group.v.calendar.google.com_" + "family13997378751670666433@group.calendar.google.com_ncaaf_-m-07kbp5_" + "%47eorgia+%42ulldogs+football#sports@group.v.calendar.google.com_nfl_-m-07l24_" + "%54ampa+%42ay+%42uccaneers#sports@group.v.calendar.google.com_primary" +) + +# ext4/xfs/btrfs NAME_MAX; set()'s temp file adds 15 bytes to the stem. +NAME_MAX = 255 +TEMP_OVERHEAD = len(".") + len(".json") + len(".") + 8 + + +def test_the_real_key_was_too_long_to_write(): + assert len((CALENDAR_KEY + ".json").encode()) > NAME_MAX - 10 + + +def test_a_long_key_round_trips(tmp_path): + cache = DiskCache(str(tmp_path)) + cache.set(CALENDAR_KEY, {"events": [1, 2, 3]}) + + assert cache.get(CALENDAR_KEY, max_age=None) == {"events": [1, 2, 3]} + path = cache.get_cache_path(CALENDAR_KEY) + assert os.path.isfile(path) + stem = os.path.basename(path)[:-len(".json")] + assert len(stem.encode()) + TEMP_OVERHEAD <= NAME_MAX + + +def test_short_keys_keep_their_filename(tmp_path): + cache = DiskCache(str(tmp_path)) + exactly = "k" * _MAX_KEY_FILENAME_BYTES + assert cache.get_cache_path("weather_current") == str(tmp_path / "weather_current.json") + assert cache.get_cache_path(exactly) == str(tmp_path / f"{exactly}.json") + assert cache.get_cache_path(exactly + "k") != str(tmp_path / f"{exactly}k.json") + + +def test_long_keys_sharing_a_prefix_stay_apart(tmp_path): + cache = DiskCache(str(tmp_path)) + first, second = CALENDAR_KEY + "_a", CALENDAR_KEY + "_b" + cache.set(first, {"which": "a"}) + cache.set(second, {"which": "b"}) + + assert cache.get_cache_path(first) != cache.get_cache_path(second) + assert cache.get(first, max_age=None) == {"which": "a"} + assert cache.get(second, max_age=None) == {"which": "b"} + + +def test_the_prefix_never_splits_a_character(): + key = "news_" + "é" * 300 # two bytes each, so the cut lands mid-character + stem = _filename_stem(key) + + assert stem.startswith("news_é") + assert len(stem.encode("utf-8")) <= _MAX_KEY_FILENAME_BYTES + stem.encode("utf-8").decode("utf-8") # well-formed + + +def test_a_stem_listed_by_the_web_ui_deletes_the_same_file(tmp_path): + with patch('src.cache_manager.CacheManager._get_writable_cache_dir', return_value=str(tmp_path)): + manager = CacheManager() + try: + manager.save_cache(CALENDAR_KEY, {"events": []}) + + listed = [entry["key"] for entry in manager.list_cache_files()] + assert len(listed) == 1 + manager.clear_cache(listed[0]) + + assert [n for n in os.listdir(tmp_path) if n.endswith(".json")] == [] + finally: + manager.stop_cleanup_thread() + + +def test_a_failed_write_names_the_real_error(tmp_path, monkeypatch, caplog): + blocker = tmp_path / "a-file" + blocker.write_text("") + # No writable fallback either, so set() gives up and says why. + monkeypatch.setattr(os.path, "expanduser", lambda _p: str(blocker / "home")) + cache = DiskCache(str(tmp_path / "missing")) + + with caplog.at_level(logging.WARNING): + cache.set("weather_current", {"t": 1}) + + gave_up = [r.getMessage() for r in caplog.records if "Could not write cache" in r.getMessage()] + assert len(gave_up) == 1 + assert "permission denied" not in gave_up[0] + assert os.strerror(2) in gave_up[0] # ENOENT: the directory does not exist diff --git a/test/test_cache_memory_tier_age.py b/test/test_cache_memory_tier_age.py new file mode 100644 index 00000000..ca53df90 --- /dev/null +++ b/test/test_cache_memory_tier_age.py @@ -0,0 +1,95 @@ +"""The memory tier never serves a record older than the reader asked for. + +A record read from disk went into the memory tier timed from the read, not +from when it was written, so get(max_age=300) could hand out data up to twice +that old: after a restart, after the memory sweep, or in a second process that +loaded a record once and kept serving it. +""" + +import time +from unittest.mock import patch + +import pytest + +from src.cache_manager import CacheManager + + +class Clock: + def __init__(self, now): + self.now = now + + def __call__(self): + return self.now + + +@pytest.fixture +def clock(monkeypatch): + fake = Clock(1_800_000_000.0) + monkeypatch.setattr(time, "time", fake) + return fake + + +def _manager(path): + # No disk sweep: it judges files by their real mtime against the fake + # clock and would delete them as months old. + with patch('src.cache_manager.CacheManager._get_writable_cache_dir', + return_value=str(path)), \ + patch('src.cache_manager.CacheManager.start_cleanup_thread'): + return CacheManager() + + +def test_a_record_loaded_late_expires_on_its_own_timestamp(tmp_path, clock): + writer = _manager(tmp_path) + writer.set("weather_current", {"t": 1}) + + reader = _manager(tmp_path) # a restart, or the other process + clock.now += 250 + assert reader.get("weather_current", max_age=300) == {"t": 1} + + clock.now += 100 # the data is 350 s old; it sat in memory for 100 s + assert reader.get("weather_current", max_age=300) is None + + +def test_a_stored_ttl_bounds_the_memory_copy_too(tmp_path, clock): + writer = _manager(tmp_path) + writer.set("odds_espn_football_nfl_401", {"spread": 6.5}, ttl=60) + + reader = _manager(tmp_path) + clock.now += 55 + assert reader.get("odds_espn_football_nfl_401", max_age=3600) == {"spread": 6.5} + + clock.now += 60 + assert reader.get("odds_espn_football_nfl_401", max_age=3600) is None + + +def test_a_stale_memory_copy_gives_way_to_a_newer_write_on_disk(tmp_path, clock): + writer = _manager(tmp_path) + reader = _manager(tmp_path) + writer.set("stocks_AAPL", {"price": 1}) + assert reader.get("stocks_AAPL", max_age=300) == {"price": 1} + + clock.now += 280 + writer.set("stocks_AAPL", {"price": 2}) + clock.now += 40 # reader's copy: 40 s in memory, 320 s old + + assert reader.get("stocks_AAPL", max_age=300) == {"price": 2} + + +def test_fresh_records_are_still_served_from_memory(tmp_path, clock): + manager = _manager(tmp_path) + manager.set("news_NFL", {"items": []}) + clock.now += 100 + + with patch.object(manager._disk_cache_component, "get") as disk_get: + assert manager.get("news_NFL", max_age=300) == {"items": []} + disk_get.assert_not_called() + + +def test_max_age_none_and_records_without_a_timestamp_never_expire(tmp_path, clock): + manager = _manager(tmp_path) + manager.set("plugin_health_x", {"ok": True}) + manager.save_cache("raw_record", {"no": "timestamp"}) + clock.now += 10 ** 6 + + assert manager.get("plugin_health_x", max_age=None) == {"ok": True} + assert manager.get_cached_data("raw_record", max_age=None) == {"no": "timestamp"}