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"}