diff --git a/CHANGELOG.md b/CHANGELOG.md index f136d44a..c2ae2dc5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -120,6 +120,13 @@ floor on the release that ships them): when the count is only known to the display service. - The Logs tab has a **Plugin errors** panel: per-plugin counts, repeating errors and a Clear button. +- Credential redaction in exception text (`src/redaction.py`) takes time + proportional to the text, not its square. Two patterns were quadratic: URL + `user:password@`, on a long unbroken run of letters or digits (a hex digest, + an ID), and `Authorization:` followed by a long run of whitespace. Either + used to stall every thread of the display service for up to seconds each + time the snapshot was published: about 0.5s for 20k characters of hex, 8s + for 20k spaces. What gets redacted is unchanged. ### Removed diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 82e9f912..b588adfc 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -303,6 +303,76 @@ journalctl -u ledmatrix --since "-5min" --no-pager | grep -iE "px/s|px/frame" If a plugin logs its scroll config **twice** with different modes, the second line is what is running. +--- + +## A tear across the middle on fast scrolls + +**Symptom:** while text scrolls, the top and bottom halves of the panel look +shifted sideways against each other along a horizontal line at mid-height, and +the shift grows with scroll speed. It shows most in Vegas mode at high speed. + +**It is the panel's scan, not the software.** The measured panel, like most +64-row panels, is multiplexed 1:32 (some panels of the same size scan +differently, so check yours): it lights two rows at a time, one from each half +(row 0 with row 32, row 1 with row 33, …), stepping down both halves together +once per refresh. So row 31, +the last row of the top half, lights almost a whole refresh period after row 32 +right below it. Your eye follows moving text, and moving content that lights at +different times lands in different places, so the two rows meet with an offset +of roughly + +``` +offset ≈ scroll speed × refresh period +``` + +Each frame already reaches the panel whole (`SwapOnVSync` swaps complete frames +between refreshes), so there is nothing to fix in the render path; the shift is +created inside a single refresh. Other panel heights show it too, at the point +where their two scan halves meet. + +On the 2×128×64 chain above, which refreshes at about 130 Hz flat out +(7.7 ms per pass): + +| scroll speed | offset at the midline | +|---|---| +| 50 px/s (Vegas default) | ~0.4 px | +| 100 px/s | ~0.8 px | +| 150 px/s | ~1.2 px, plainly visible | + +### What changes it + +Only a shorter scan period (a faster refresh) or a slower scroll. Measure what +the panel actually achieves first. The library prints the rate with a carriage +return and no newline, so read it from the raw journal: + +```bash +# set display.hardware.show_refresh_rate to true (web UI, Display tab), restart, then: +journalctl -u ledmatrix --since "-1min" --no-pager -o cat --all | grep -a -oE "[0-9.]+Hz" | tail -5 +``` + +Turn it off again afterwards. Measured on that panel (Pi 4, single chain), +changing one setting at a time from `pwm_bits: 7`, `gpio_slowdown: 3`: + +| change | refresh, uncapped | notes | +|---|---|---| +| none | ~130 Hz | the ceiling for this wiring | +| `pwm_bits: 6` | ~138 Hz | barely faster, and half the colour depth | +| `gpio_slowdown: 2` | ~130 Hz | no faster, **and visible glitching**; keep 3 | +| `limit_refresh_rate_hz: 0` | ~130 Hz | Vegas dropped from 100 to 72–95 fps as the refresh thread took more CPU | + +None of these helps much, because the time goes into shifting each row's pixels +out: a 2×128 chain pushes 256 pixels per row down one output. What does help is +**fewer pixels per output**. On a bonnet with more than one output (the +`regular` and `classic` mappings have 3; `adafruit-hat` has 1), put each panel +on its own output and set `parallel` to the number of outputs used and +`chain_length` to the panels per output, for example `parallel: 2`, +`chain_length: 1` for two panels. Each refresh then shifts half the data, which +should roughly double the refresh rate and halve the offset. That is a cable +change, so measure again afterwards. + +Short of rewiring, keep fast scrolls moderate: at the default 50 px/s the +offset is under half a pixel. + ## Rebuilding the binding ```bash diff --git a/src/background_data_service.py b/src/background_data_service.py index 22989a56..a41aef45 100644 --- a/src/background_data_service.py +++ b/src/background_data_service.py @@ -26,6 +26,7 @@ from enum import Enum from concurrent.futures import ThreadPoolExecutor import pytz from src.cache_manager import CacheManager +from src.common.json_body import response_json from src.common.espn_dates import ( RANGE_RETRY_SECONDS, _note_range_rejected, @@ -389,7 +390,7 @@ class BackgroundDataService: response.raise_for_status() else: response.raise_for_status() - data = response.json() + data = response_json(response) # Validate data structure if not isinstance(data, dict): diff --git a/src/cache/disk_cache.py b/src/cache/disk_cache.py index 87c3d7a9..fb776b56 100644 --- a/src/cache/disk_cache.py +++ b/src/cache/disk_cache.py @@ -7,6 +7,7 @@ Handles persistent disk-based caching with atomic writes and error recovery. import json import math import os +import re import stat import time import tempfile @@ -98,6 +99,40 @@ def _replace_nonfinite(obj: Any) -> Any: # deleted. Both halves are covered by test/test_cache_nonfinite_floats.py. +#: Enough of a record to hold its header: ``{"timestamp":,"ttl":,``. +_HEAD_BYTES = 256 + +#: A record written with its header first (CacheManager.set does). Anything +#: else -- older files with "data" first, records from other writers -- does not +#: match and is parsed in full, as before. +_HEAD_RE = re.compile( + rb'\A\s*\{\s*"timestamp"\s*:\s*(-?[0-9][0-9.eE+-]*)\s*' + rb'(?:,\s*"ttl"\s*:\s*(-?[0-9][0-9.eE+-]*))?\s*[,}]' +) + + +def _stale_from_head(head: bytes, max_age: Optional[int], now: float) -> bool: + """True when a record's header alone shows it has expired. + + Mirrors the expiry rule in DiskCache.get: a per-entry ttl wins over the + caller's max_age, and no limit at all means never stale. False whenever the + header cannot be read, so the full parse decides as it always did. + """ + match = _HEAD_RE.match(head) + if not match: + return False + try: + timestamp = float(match.group(1)) + limit = max_age + if match.group(2) is not None: + ttl = float(match.group(2)) + if ttl >= 0: + limit = ttl + except ValueError: + return False + return limit is not None and (now - timestamp) > limit + + if orjson is not None: # Encoding the cache record dominated the background fetch worker: on a # Pi 4, stdlib json.dumps runs ~12ms per MB and holds the GIL for all of @@ -266,6 +301,14 @@ class DiskCache: try: with self._lock: with open(cache_path, 'rb') as f: + # Decide staleness from the header before paying for the + # parse. A stale read is the common case for the biggest + # records (a season schedule is re-fetched when its cache + # expires), and parsing 53MB to throw it away held the GIL + # for ~1.8s -- a visible freeze on the panel. + if _stale_from_head(f.read(_HEAD_BYTES), max_age, time.time()): + return None + f.seek(0) record = _loads(f.read()) # Determine record timestamp (prefer embedded, else file mtime) diff --git a/src/cache_manager.py b/src/cache_manager.py index 4d80c986..d064a37f 100644 --- a/src/cache_manager.py +++ b/src/cache_manager.py @@ -522,8 +522,9 @@ class CacheManager: def update_cache(self, data_type: str, data: Dict[str, Any]) -> bool: """Update cache with new data.""" cache_data = { + # Header first; see DiskCache's stale check. + 'timestamp': time.time(), 'data': data, - 'timestamp': time.time() } return self.save_cache(data_type, cache_data) @@ -556,12 +557,15 @@ class CacheManager: from the key and is only a fallback for entries that did not say. Omit it to keep that inferred behaviour. """ - cache_data = { - 'data': data, - 'timestamp': time.time() - } + # timestamp and ttl before data, so they are the first bytes on disk: + # DiskCache.get reads them from the head of the file and can call a + # record stale without parsing it. That matters for the big ones -- a + # whole MLB season is 53MB and ~1.8s of orjson.loads with the GIL held, + # paid in full only to learn the record had expired. + cache_data: Dict[str, Any] = {'timestamp': time.time()} if ttl is not None: cache_data['ttl'] = ttl + cache_data['data'] = data self.save_cache(key, cache_data) @deprecated("3.7.0") diff --git a/src/common/espn_dates.py b/src/common/espn_dates.py index 9be705d1..bda7e86a 100644 --- a/src/common/espn_dates.py +++ b/src/common/espn_dates.py @@ -39,6 +39,14 @@ from datetime import date, timedelta from functools import partial from typing import Any, Dict, List, Optional, Tuple +try: + from src.common.json_body import response_json +except ImportError: + # Plugins bundle copies of this module for older cores, which predate + # json_body; the stdlib parse is what those cores always used. + def response_json(response: Any) -> Any: + return response.json() + # Above this, ESPN returns a truncated list instead of an error. See module # docstring: 500 is the largest value measured to return complete data. ESPN_MAX_LIMIT = 500 @@ -194,7 +202,7 @@ def _fetch_one_chunk( timeout=timeout, ) response.raise_for_status() - return response.json() + return response_json(response) except Exception as exc: # noqa: BLE001 - see docstring if logger: logger.warning("ESPN chunk %s failed, skipping it: %s", chunk, exc) @@ -371,4 +379,4 @@ def fetch_espn_scoreboard( if data is not None: return data response.raise_for_status() - return response.json() + return response_json(response) diff --git a/src/common/json_body.py b/src/common/json_body.py new file mode 100644 index 00000000..fb89301d --- /dev/null +++ b/src/common/json_body.py @@ -0,0 +1,29 @@ +"""Parse an HTTP response body as JSON, with orjson when it is installed. + +``requests``' ``response.json()`` uses the stdlib parser. For the payloads the +sports plugins fetch -- a season schedule is tens of MB -- that runs ~1.7x +slower than orjson on a Pi 4 (3.1s against 1.8s for the 53MB MLB season), and +both hold the GIL for the whole parse, which freezes the display for as long. +Nothing else changes: the result is the same Python objects. +""" + +from __future__ import annotations + +from typing import Any + +try: + import orjson +except ImportError: # optional dependency; see docs/SCROLL_PERFORMANCE.md + orjson = None + + +def response_json(response: Any) -> Any: + """``response.json()``, parsed by orjson when available.""" + body = getattr(response, "content", None) + if orjson is None or not isinstance(body, (bytes, bytearray)): + return response.json() + try: + return orjson.loads(body) + except orjson.JSONDecodeError: + # Let requests raise its usual error, with its usual message. + return response.json() diff --git a/src/redaction.py b/src/redaction.py index b84bf1b1..a1294309 100644 --- a/src/redaction.py +++ b/src/redaction.py @@ -24,8 +24,13 @@ _REDACT_CREDENTIAL = re.compile( # silently leak the ones nobody thought of. Not covered by the generic pattern # above, whose value part stops at whitespace and so would keep the credential # once a space follows the scheme. +# +# The opening quote and the whitespace after it are one optional unit. Written +# `\s*["\']?\s*`, a whitespace run with no quote in it could be split between +# the two `\s*` in every possible way, and a header with no credential after +# it tried them all: quadratic, 8s for 20k spaces. _REDACT_AUTH_HEADER = re.compile( - r'((?:proxy-)?authorization["\']?\s*[=:]\s*["\']?\s*' + r'((?:proxy-)?authorization["\']?\s*[=:]\s*(?:["\']\s*)?' r'(?:[A-Za-z][\w.+-]*[ \t]+)?)' # optional scheme name, kept r'([^\s,"\'<>}]+)', # the credential, redacted re.IGNORECASE, @@ -34,8 +39,16 @@ _REDACT_AUTH_HEADER = re.compile( # Credentials embedded in a URL: https://user:password@host. requests quotes # the full URL in its exceptions, so this is a realistic leak. The username is # kept -- it identifies which account failed without being the secret. -_REDACT_URL_USERINFO = re.compile(r'([a-z][a-z0-9+.-]*://[^/\s:@]+:)([^/\s@]+)(@)', - re.IGNORECASE) +# +# A match may only start where a run of scheme characters starts. Unanchored, +# `[a-z][a-z0-9+.-]*://` was tried from every letter of a long run (a hex +# digest, an ID, a blob of response body), each attempt reading to the end of +# the run: quadratic, 1.6s for 20k characters, all of it holding the GIL. +# Leading digits and `+.-` sit inside group 1 so the substitution puts them +# back; the scheme proper still has to start with a letter. +_REDACT_URL_USERINFO = re.compile( + r'((? str: diff --git a/test/test_cache_stale_header.py b/test/test_cache_stale_header.py new file mode 100644 index 00000000..026b982d --- /dev/null +++ b/test/test_cache_stale_header.py @@ -0,0 +1,118 @@ +"""A stale cache record is recognised from its header, without parsing it. + +The sports plugins cache whole season schedules -- 53MB for MLB, 18MB for NHL. +When one expired, DiskCache.get parsed all of it (~1.8s of orjson.loads on a +Pi 4, GIL held, the whole display frozen) only to find the timestamp too old +and throw the result away. CacheManager.set now writes timestamp and ttl ahead +of the data, and DiskCache.get reads them from the first bytes of the file. +""" + +import json +import time +from types import SimpleNamespace + +import pytest + +from src.cache import disk_cache as disk_cache_module +from src.cache.disk_cache import DiskCache, _stale_from_head +from src.common import json_body + + +@pytest.fixture +def disk(tmp_path): + return DiskCache(cache_dir=str(tmp_path)) + + +@pytest.fixture +def parses(monkeypatch): + """Count full parses of cache files.""" + calls = [] + real = disk_cache_module._loads + + def counting(raw): + calls.append(len(raw)) + return real(raw) + + monkeypatch.setattr(disk_cache_module, "_loads", counting) + return calls + + +def _header_first(age=0.0, ttl=None, events=100): + record = {"timestamp": time.time() - age} + if ttl is not None: + record["ttl"] = ttl + record["data"] = {"events": [{"id": n, "name": "x" * 50} for n in range(events)]} + return record + + +def test_cache_manager_writes_the_header_first(monkeypatch): + from src.cache_manager import CacheManager + written = {} + manager = CacheManager.__new__(CacheManager) + monkeypatch.setattr(manager, "save_cache", + lambda key, record: written.update({key: record}), + raising=False) + CacheManager.set(manager, "k", {"events": []}, ttl=60) + assert list(written["k"]) == ["timestamp", "ttl", "data"] + CacheManager.set(manager, "k", {"events": []}) + assert list(written["k"]) == ["timestamp", "data"] + + +def test_a_stale_record_is_not_parsed(disk, parses): + disk.set("season", _header_first(age=600)) + assert disk.get("season", max_age=300) is None + assert parses == [] + + +def test_a_fresh_record_is_parsed_and_returned(disk, parses): + disk.set("season", _header_first(age=10)) + record = disk.get("season", max_age=300) + assert record["data"]["events"][0]["id"] == 0 + assert len(parses) == 1 + + +def test_the_entry_ttl_wins_over_max_age(disk, parses): + disk.set("long", _header_first(age=600, ttl=3600)) + assert disk.get("long", max_age=300) is not None # ttl says fresh + disk.set("short", _header_first(age=60, ttl=30)) + parses.clear() + assert disk.get("short", max_age=300) is None # ttl says stale + assert parses == [] + + +def test_no_limit_means_never_stale(disk): + disk.set("forever", _header_first(age=10 ** 7)) + assert disk.get("forever", max_age=None) is not None + + +def test_older_files_with_data_first_still_work(disk, parses): + # Records written before the header moved: parsed in full, as before. + disk.set("legacy_fresh", {"data": {"v": 1}, "timestamp": time.time()}) + disk.set("legacy_stale", {"data": {"v": 1}, "timestamp": time.time() - 600}) + assert disk.get("legacy_fresh", max_age=300)["data"] == {"v": 1} + assert disk.get("legacy_stale", max_age=300) is None + assert len(parses) == 2 + + +@pytest.mark.parametrize("head, stale", [ + (b'{"timestamp":100.0,"data":{}}', True), + (b'{"timestamp": 100.0, "ttl": 1000, "data": {}}', False), # stdlib spacing + (b'{"timestamp":1e2,"ttl":5,"data":1}', True), + (b'{"timestamp":100.0}', True), + (b'{"data":{},"timestamp":100.0}', False), # unknown layout + (b'{"timestamp":"100.0","data":{}}', False), # string: parse it + (b'', False), +]) +def test_reading_the_header(head, stale): + assert _stale_from_head(head, 300, now=1000.0) is stale + + +def test_response_json_prefers_orjson_and_falls_back(): + payload = {"events": [1, 2, 3]} + response = SimpleNamespace(content=json.dumps(payload).encode(), + json=lambda: pytest.fail("used the slow path")) + if json_body.orjson is None: + pytest.skip("orjson not installed") + assert json_body.response_json(response) == payload + # A response object without bytes content (a test double) still works. + assert json_body.response_json(SimpleNamespace(json=lambda: payload)) == payload diff --git a/test/test_redaction.py b/test/test_redaction.py new file mode 100644 index 00000000..5f59d696 --- /dev/null +++ b/test/test_redaction.py @@ -0,0 +1,110 @@ +"""redact_credentials must stay linear in the length of its input. + +Regressions under test, both quadratic regexes in src/redaction.py: + +- The URL-userinfo pattern (`scheme://user:password@`) could start a match at + every letter of a run of scheme characters, and each attempt read to the end + of the run looking for `://`: 1.6s for a 20k-character run. +- The Authorization-header pattern had two `\\s*` separated only by an + optional quote, so a header followed by whitespace and no credential tried + every split of that whitespace between them: 8s for 20k spaces. + +The display service redacts every message, stack trace and context value it +publishes in the error snapshot, and re.sub holds the GIL throughout, so an +exception quoting a hex digest or a long ID stalled the render loop with it. +test_error_snapshot_cross_process.py's snapshot-size test spent 140s here. + +The fixed patterns have to redact exactly what the old ones did. +""" + +import time + +import pytest + +from src.redaction import redact_credentials + +# Each timed input took seconds before the fix and takes about a millisecond +# after it; the bound leaves CI plenty of headroom while still failing on a +# quadratic pattern. +_TIME_LIMIT = 1.0 + + +def _timed(text): + start = time.perf_counter() + result = redact_credentials(text) + return result, time.perf_counter() - start + + +class TestUrlUserinfo: + @pytest.mark.parametrize("text,expected", [ + ("401 for https://user:hunter2@example.com/api", + "401 for https://user:@example.com/api"), + ("HTTPS://USER:HUNTER2@EXAMPLE.COM", + "HTTPS://USER:@EXAMPLE.COM"), + ("git+ssh://deploy:hunter2@host/repo", + "git+ssh://deploy:@host/repo"), + # The scheme starts after digits or +.- in the same run. Those + # characters must survive, and the password must still go. + ("1http://user:hunter2@host", "1http://user:@host"), + ("+.-http://user:hunter2@host", "+.-http://user:@host"), + ("a1+http://user:hunter2@host", "a1+http://user:@host"), + ("see a://u:first@b and c://v:second@d", + "see a://u:@b and c://v:@d"), + ]) + def test_password_is_redacted_and_the_rest_kept(self, text, expected): + assert redact_credentials(text) == expected + + def test_a_url_without_a_password_is_untouched(self): + text = "GET https://user@example.com/path failed" + assert redact_credentials(text) == text + + +class TestAuthorizationHeader: + @pytest.mark.parametrize("text,expected", [ + ("Authorization: Bearer eyJ.SECRET.sig", "Authorization: Bearer "), + ("Proxy-Authorization: Basic dXNlcg==", "Proxy-Authorization: Basic "), + ("authorization: barecredential", "authorization: "), + # Whitespace and an opening quote around the value, in either order. + ('authorization=" Bearer tok"', 'authorization=" Bearer "'), + ("authorization: ' tok'", "authorization: ' '"), + ("authorization:\n\tBearer tok", "authorization:\n\tBearer "), + ]) + def test_credential_is_redacted_and_the_rest_kept(self, text, expected): + assert redact_credentials(text) == expected + + @pytest.mark.parametrize("text", ["authorization: ", "authorization: , next"]) + def test_a_header_without_a_credential_is_untouched(self, text): + assert redact_credentials(text) == text + + +class TestLinearTime: + @pytest.mark.parametrize("unit", ["x", "0123456789abcdef", "1a", "a+", "1"]) + def test_long_scheme_character_runs(self, unit): + text = (unit * 50_000)[:50_000] + result, elapsed = _timed(text) + assert result == text + assert elapsed < _TIME_LIMIT, f"{elapsed:.2f}s to redact {len(text)} chars of {unit!r}" + + def test_a_credential_after_a_long_run_is_still_found(self): + run = "ab12" * 10_000 + result, elapsed = _timed(f"{run} https://user:hunter2@example.com") + assert result == f"{run} https://user:@example.com" + assert elapsed < _TIME_LIMIT + + @pytest.mark.parametrize("header,whitespace", [ + ("authorization:", " "), + ("Proxy-Authorization:", "\t"), + ("authorization=", "\n"), + ]) + def test_a_header_followed_by_long_whitespace(self, header, whitespace): + text = header + whitespace * 20_000 + "," + result, elapsed = _timed(text) + assert result == text + assert elapsed < _TIME_LIMIT, ( + f"{elapsed:.2f}s to redact {header!r} and {len(text) - len(header)} more chars") + + def test_a_credential_after_long_whitespace_is_still_found(self): + gap = " " * 20_000 + result, elapsed = _timed(f"authorization:{gap}Bearer tok") + assert result == f"authorization:{gap}Bearer " + assert elapsed < _TIME_LIMIT diff --git a/test/web_interface/test_api_v3_names_resolve.py b/test/web_interface/test_api_v3_names_resolve.py new file mode 100644 index 00000000..6b6e6c1c --- /dev/null +++ b/test/web_interface/test_api_v3_names_resolve.py @@ -0,0 +1,25 @@ +"""Names two rarely-run api_v3 paths call must exist. + +Both slipped through because nothing exercised them: the Pixlet editor's +stop route only restarts the display after a SIGKILL, and the Starlark +device-location resolver only builds a cache manager when the web app has +not set one. Either raised NameError when it finally ran. +""" + +from unittest.mock import patch + +from test._api_v3_test_helpers import api_v3_module # noqa: F401 + + +def test_the_editor_stop_route_can_restart_the_display(): + from web_interface.blueprints.api_v3 import starlark + + assert callable(starlark._run_systemctl_command) + + +def test_the_device_location_resolver_builds_without_a_cache_manager(api_v3_module): + pkg = api_v3_module + with patch.object(pkg.api_v3, 'cache_manager', None, create=True), \ + patch.object(pkg, '_starlark_device_location', None): + resolver = pkg._get_starlark_device_location() + assert resolver.cache_manager is None diff --git a/web_interface/blueprints/api_v3/__init__.py b/web_interface/blueprints/api_v3/__init__.py index 6d26a980..29a9f4e4 100644 --- a/web_interface/blueprints/api_v3/__init__.py +++ b/web_interface/blueprints/api_v3/__init__.py @@ -1712,7 +1712,7 @@ def _get_starlark_device_location() -> DeviceLocationResolver: global _starlark_device_location if _starlark_device_location is None: _starlark_device_location = DeviceLocationResolver( - getattr(api_v3, 'cache_manager', None) or _ensure_cache_manager(), logger) + getattr(api_v3, 'cache_manager', None), logger) return _starlark_device_location diff --git a/web_interface/blueprints/api_v3/starlark.py b/web_interface/blueprints/api_v3/starlark.py index 856de4a4..08d592c7 100644 --- a/web_interface/blueprints/api_v3/starlark.py +++ b/web_interface/blueprints/api_v3/starlark.py @@ -11,6 +11,7 @@ from web_interface.blueprints.api_v3 import ( _PIXLET_EDITOR_DEFAULT_TIMEOUT, _PIXLET_EDITOR_MAX_TIMEOUT, _PIXLET_EDITOR_SCRIPT, _PIXLET_EDITOR_STATE, _clear_pixlet_editor_state, _find_pixlet_binary, _install_star_file, _pixlet_editor_alive, + _run_systemctl_command, _pixlet_editor_status, _read_pixlet_editor_state, _STARLARK_APPS_DIR, _standalone_render_starlark_app, _starlark_github_token, _starlark_manifest_lock,