fix(display): thread-safety for deferred updates, BDF faces and follower image; one refresh default (#652)

- DisplayManager.defer_update()/process_deferred_updates(): one lock around
  every queue mutation (appends from the update thread were lost to the
  render thread's filter/slice reassignments); callables run outside it.
- FontManager and element_style no longer cache BDF freetype.Face objects
  process-wide (load_bdf_face caches them per thread); element_style's LRU
  is locked against get/move_to_end vs eviction races.
- limit_refresh_rate_hz default is one constant, DEFAULT_REFRESH_LIMIT_HZ =
  100 (the template's), for the library options, refresh_hz, the matrix
  guard, Vegas and scroll_config. Previously a missing key capped the panel
  at 90 while pacing assumed 100.
- Sync follower: the TCP thread queues the leader's scroll image; the render
  thread swaps image/array/width in between frames.
- update_display() error log rate-limited (traceback first, then once a
  minute with a count); swallowed DisplayController exceptions log at DEBUG.
- Root display_controller.py runs run.py via runpy.
- stream_manager: correct the RLock release comments; merge duplicate if.

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

test/test_bdf_face_per_thread.py

@@ -0,0 +1,93 @@
+"""BDF faces must not be shared between threads.
+
+src/common/bdf_font.load_bdf_face caches ``freetype.Face`` objects per thread
+because FreeType does not allow two threads to use one face at once
+(``load_char`` rewrites its glyph slot). FontManager.font_cache and
+element_style._font_cache are process-wide, and used to cache the returned
+face for every thread -- so the display thread and a plugin update thread
+drew through the same Face.
+"""
+
+import threading
+
+import freetype
+import pytest
+
+from src import element_style
+from src.font_manager import FontManager
+
+
+def _on_other_thread(fn):
+    box = {}
+
+    def run():
+        box['value'] = fn()
+
+    t = threading.Thread(target=run)
+    t.start()
+    t.join(timeout=10)
+    assert not t.is_alive()
+    return box['value']
+
+
+def test_font_manager_gives_each_thread_its_own_bdf_face():
+    fm = FontManager({})
+    here = fm.get_font("five_by_seven", 7)
+    there = _on_other_thread(lambda: fm.get_font("five_by_seven", 7))
+    assert isinstance(here, freetype.Face) and isinstance(there, freetype.Face)
+    assert here is not there
+    # Within one thread the face is still reused.
+    assert fm.get_font("five_by_seven", 7) is here
+
+
+def test_font_manager_still_caches_ttf():
+    fm = FontManager({})
+    here = fm.get_font("press_start", 8)
+    assert _on_other_thread(lambda: fm.get_font("press_start", 8)) is here
+
+
+def test_element_style_gives_each_thread_its_own_bdf_face():
+    element_style._font_cache.clear()
+    try:
+        here = element_style.load_font("5x7.bdf", 7)
+        there = _on_other_thread(lambda: element_style.load_font("5x7.bdf", 7))
+        assert isinstance(here, freetype.Face) and isinstance(there, freetype.Face)
+        assert here is not there
+        assert element_style.load_font("5x7.bdf", 7) is here
+    finally:
+        element_style._font_cache.clear()
+
+
+def test_element_style_cache_survives_concurrent_eviction(monkeypatch):
+    """get() then move_to_end() on the shared OrderedDict raised KeyError when
+    another thread evicted the key in between. Forced deterministically: the
+    first get() hands the cache to a second thread that fills it past the
+    bound before get() returns."""
+    from collections import OrderedDict
+
+    owner = threading.get_ident()
+    state = {'worker': None}
+
+    class RacingCache(OrderedDict):
+        def get(self, key, default=None):
+            value = super().get(key, default)
+            if state['worker'] is None and threading.get_ident() == owner:
+                state['worker'] = threading.Thread(
+                    target=lambda: [element_style.load_font(
+                        "PressStart2P-Regular.ttf", s) for s in (20, 21, 22)],
+                    daemon=True)
+                state['worker'].start()
+                # Unguarded, the worker evicts `key` now; guarded, it waits
+                # for the lock this thread holds.
+                state['worker'].join(timeout=0.5)
+            return value
+
+    monkeypatch.setattr(element_style, "_FONT_CACHE_MAX", 2)
+    cache = RacingCache()
+    monkeypatch.setattr(element_style, "_font_cache", cache)
+    element_style.load_font("PressStart2P-Regular.ttf", 8)  # populate
+    state['worker'] = None
+    element_style.load_font("PressStart2P-Regular.ttf", 8)  # hit, raced
+    state['worker'].join(timeout=10)
+    assert not state['worker'].is_alive()
+    assert len(cache) <= 2

test/test_deferred_updates_threads.py

@@ -0,0 +1,111 @@
+"""DisplayManager's deferred-update queue across threads.
+
+defer_update() is called from plugin update() on the update worker thread
+while process_deferred_updates() runs on the render thread. Both rebuild the
+queue list (TTL filter, [n:] slice) and assign it back, so an append that
+landed between one side's read and its assignment used to be dropped.
+
+The race is forced deterministically: _scrolling_state is swapped for a dict
+whose first store of 'deferred_updates' (made by the render side) first lets
+a worker-thread defer_update() run. Unlocked, the worker appends to the list
+the render side is about to overwrite; locked, the worker waits and appends
+to the list that was stored.
+"""
+
+import os
+import sys
+import threading
+
+os.environ["EMULATOR"] = "true"
+
+import pytest
+
+sys.path.insert(0, os.path.join(os.path.dirname(__file__), ".."))
+
+
+@pytest.fixture(scope="module")
+def dm():
+    from src.display_manager import DisplayManager
+    DisplayManager._instance = None
+    manager = DisplayManager({
+        "display": {
+            "hardware": {"rows": 32, "cols": 64, "chain_length": 1,
+                         "parallel": 1, "brightness": 90},
+            "runtime": {"gpio_slowdown": 0},
+        },
+    }, suppress_test_pattern=True)
+    yield manager
+    DisplayManager._instance = None
+
+
+class _InterleavingState(dict):
+    """On the first 'deferred_updates' store from the owning thread, run
+    ``interleave`` on another thread before the store happens."""
+
+    def __init__(self, base, interleave):
+        super().__init__(base)
+        dict.__setitem__(self, 'deferred_updates', [])
+        self._owner = threading.get_ident()
+        self._interleave = interleave
+        self.worker = None
+
+    def __setitem__(self, key, value):
+        if (key == 'deferred_updates' and self.worker is None
+                and threading.get_ident() == self._owner):
+            self.worker = threading.Thread(target=self._interleave, daemon=True)
+            self.worker.start()
+            # Unlocked code lets the worker finish here; locked code blocks
+            # it on the lock this thread holds, so give up waiting quickly.
+            self.worker.join(timeout=0.5)
+        super().__setitem__(key, value)
+
+
+def test_defer_from_another_thread_is_not_lost(dm):
+    original = dm._scrolling_state
+    ran = []  # the callables never run here; they only need to exist
+    try:
+        state = _InterleavingState(
+            original, lambda: dm.defer_update(lambda: ran.append('late')))
+        dm._scrolling_state = state
+        dm.defer_update(lambda: ran.append('first'))
+        state.worker.join(timeout=5)
+        assert not state.worker.is_alive()
+        assert len(state['deferred_updates']) == 2, (
+            "a defer_update() from another thread was lost")
+    finally:
+        dm._scrolling_state = original
+        original['deferred_updates'] = []
+
+
+def test_process_during_defer_keeps_both(dm):
+    original = dm._scrolling_state
+    try:
+        state = _InterleavingState(
+            original, lambda: dm.defer_update(lambda: None))
+        dict.__setitem__(state, 'is_scrolling', True)
+        dict.__setitem__(state, 'last_scroll_activity', 1e18)  # stays "scrolling"
+        dm._scrolling_state = state
+        # Render side: only the TTL cleanup runs while scrolling.
+        dm.process_deferred_updates()
+        state.worker.join(timeout=5)
+        assert not state.worker.is_alive()
+        assert len(state['deferred_updates']) == 1, (
+            "a defer_update() during the render-side cleanup was lost")
+    finally:
+        dm._scrolling_state = original
+        original['deferred_updates'] = []
+
+
+def test_queued_callable_may_defer_again(dm):
+    """The callables run outside the lock, so one that re-defers (a plugin
+    retrying later) must not deadlock the render thread."""
+    dm._scrolling_state['is_scrolling'] = False
+    try:
+        dm.defer_update(lambda: dm.defer_update(lambda: None))
+        t = threading.Thread(target=dm.process_deferred_updates, daemon=True)
+        t.start()
+        t.join(timeout=5)
+        assert not t.is_alive(), "process_deferred_updates deadlocked"
+        assert len(dm._scrolling_state['deferred_updates']) == 1
+    finally:
+        dm._scrolling_state['deferred_updates'] = []

test/test_display_controller_swallowed_errors.py

@@ -0,0 +1,31 @@
+"""Errors DisplayController deliberately swallows must still leave a trace.
+
+Several ``except Exception: pass`` blocks hid plugin and filesystem faults
+completely; they now log at DEBUG with the traceback, and still don't raise.
+"""
+
+import logging
+import os
+from unittest.mock import MagicMock
+
+os.environ.setdefault("EMULATOR", "true")
+
+from src.display_controller import DisplayController  # noqa: E402
+
+
+def test_has_live_content_failure_is_logged_not_raised(caplog):
+    dc = object.__new__(DisplayController)
+    broken = MagicMock()
+    broken.has_live_content.side_effect = RuntimeError("feed parse failed")
+    dc.plugin_display_modes = {"nfl": ["nfl_live", "nfl_recent"]}
+    dc.mode_to_plugin_id = {}
+    dc.plugin_modes = {"nfl_live": broken, "nfl_recent": MagicMock()}
+
+    with caplog.at_level(logging.DEBUG, logger="src.display_controller"):
+        modes = dc._on_demand_modes_for_plugin("nfl")
+
+    # Behaviour unchanged: the raising live mode counts as having no content.
+    assert modes == ["nfl_recent"]
+    records = [r for r in caplog.records
+               if "has_live_content() failed for nfl_live" in r.getMessage()]
+    assert len(records) == 1 and records[0].exc_info is not None

test/test_display_manager_logging.py

@@ -47,3 +47,28 @@ def test_debug_output_appears_when_the_root_is_at_debug():
         assert dm.logger.isEnabledFor(logging.DEBUG)
     finally:
         root.setLevel(previous)
+
+
+def test_update_display_errors_are_rate_limited(caplog):
+    # update_display() runs every frame; a persistent fault logged an ERROR
+    # line per frame (~100 a second) and never a traceback.
+    from unittest.mock import MagicMock
+
+    dm_obj = object.__new__(dm.DisplayManager)
+    dm_obj._writes_suppressed = MagicMock(side_effect=RuntimeError("boom"))
+
+    with caplog.at_level(logging.ERROR, logger='src.display_manager'):
+        for _ in range(50):
+            dm_obj.update_display()  # must not raise
+        errors = [r for r in caplog.records
+                  if r.getMessage().startswith('Error updating display')]
+        assert len(errors) == 1
+        assert errors[0].exc_info is not None
+
+        # Once the interval has passed, one more line reports what was skipped.
+        dm_obj._update_error_logged_at -= dm._UPDATE_ERROR_LOG_INTERVAL + 1
+        dm_obj.update_display()
+        errors = [r for r in caplog.records
+                  if r.getMessage().startswith('Error updating display')]
+        assert len(errors) == 2
+        assert '49 more' in errors[1].getMessage()

test/test_follower_scroll_image_handoff.py

@@ -0,0 +1,78 @@
+"""Follower adoption of the leader's scroll image (src/display_controller.py).
+
+The leader's image arrives on the sync TCP thread. That callback used to set
+scroll_helper.cached_image, cached_array and total_scroll_width one after
+another while the render thread sliced frames out of them, so a frame could
+pair the new array with the old width. The callback now only queues the
+image; the render thread swaps all three in at the start of a follower frame.
+"""
+
+import os
+from collections import deque
+from types import SimpleNamespace
+from unittest.mock import MagicMock, patch
+
+os.environ.setdefault("EMULATOR", "true")
+
+from PIL import Image  # noqa: E402
+
+from src.display_controller import DisplayController  # noqa: E402
+
+
+def _wired_controller():
+    dc = object.__new__(DisplayController)
+    dc.config = {"display": {"vegas_scroll": {"enabled": True}}, "sync": {}}
+    dc.display_manager = MagicMock()
+    dc.plugin_manager = MagicMock()
+    dc.sync_manager = MagicMock()
+    dc._check_live_priority = MagicMock()
+    dc._check_vegas_interrupt = MagicMock(return_value=False)
+    dc._follower_pending_new_image = True
+    dc._follower_incoming_image = deque(maxlen=1)
+
+    old = Image.new("RGB", (100, 16))
+    helper = SimpleNamespace(cached_image=old, cached_array="old-array",
+                             total_scroll_width=100)
+    coordinator = MagicMock()
+    coordinator.render_pipeline = SimpleNamespace(scroll_helper=helper)
+    with patch('src.vegas_mode.VegasModeCoordinator',
+               MagicMock(return_value=coordinator)):
+        dc._initialize_vegas_mode()
+    on_image = dc.sync_manager.set_on_scroll_image.call_args[0][0]
+    return dc, coordinator.render_pipeline, helper, old, on_image
+
+
+def test_tcp_callback_does_not_touch_the_render_state():
+    dc, _rp, helper, old, on_image = _wired_controller()
+    on_image(Image.new("RGB", (300, 16)))
+    # Nothing the render thread reads has changed yet.
+    assert helper.cached_image is old
+    assert helper.cached_array == "old-array"
+    assert helper.total_scroll_width == 100
+    assert dc._follower_pending_new_image is True
+
+
+def test_render_thread_adopts_all_three_together():
+    dc, rp, helper, _old, on_image = _wired_controller()
+    new = Image.new("RGB", (300, 16), (255, 0, 0))
+    on_image(new)
+    dc._adopt_follower_scroll_image(rp)
+    assert helper.cached_image is new
+    assert helper.cached_array.shape == (16, 300, 3)
+    assert helper.cached_array[0, 0].tolist() == [255, 0, 0]
+    assert helper.total_scroll_width == 300
+    assert dc._follower_pending_new_image is False
+    # Consumed: a second frame changes nothing.
+    helper.total_scroll_width = 7
+    dc._adopt_follower_scroll_image(rp)
+    assert helper.total_scroll_width == 7
+
+
+def test_only_the_latest_image_is_adopted():
+    dc, rp, helper, _old, on_image = _wired_controller()
+    on_image(Image.new("RGB", (200, 16)))
+    latest = Image.new("RGB", (400, 16))
+    on_image(latest)
+    dc._adopt_follower_scroll_image(rp)
+    assert helper.cached_image is latest
+    assert helper.total_scroll_width == 400

test/test_matrix_support.py

@@ -122,4 +122,24 @@ def test_display_manager_defaults_match_display_manager():
     for field, value in ms.DISPLAY_MANAGER_DEFAULTS.items():
         if field in ('rows', 'cols', 'chain_length', 'parallel'):
             continue  # read through display_geometry's DEFAULT_* constants
+        if field == 'limit_refresh_rate_hz':
+            assert "get('limit_refresh_rate_hz', DEFAULT_REFRESH_LIMIT_HZ)" in source
+            continue
         assert f"get('{field}', {value!r})" in source, field
+
+
+def test_missing_refresh_limit_applies_the_rate_pacing_assumes():
+    """With limit_refresh_rate_hz absent the library was capped at 90 Hz while
+    refresh_hz (what scroll pacing solves against) reported 100. One default,
+    and it is the template's."""
+    import os
+    from types import SimpleNamespace
+    os.environ.setdefault("EMULATOR", "true")  # import off-Pi, as other modules do
+    from src.display_manager import DisplayManager
+
+    options = DisplayManager.apply_matrix_options(SimpleNamespace(), {})
+    reported = DisplayManager.refresh_hz.fget(SimpleNamespace(config={}))
+    assert options.limit_refresh_rate_hz == reported
+    template = json.loads((REPO_ROOT / 'config' / 'config.template.json').read_text(encoding='utf-8'))
+    assert options.limit_refresh_rate_hz == template['display']['hardware']['limit_refresh_rate_hz']
+    assert ms.DISPLAY_MANAGER_DEFAULTS['limit_refresh_rate_hz'] == options.limit_refresh_rate_hz

test/test_root_display_controller_shim.py

@@ -0,0 +1,21 @@
+"""The repo-root display_controller.py goes through run.py.
+
+It used to call src.display_controller.main() directly, skipping run.py's
+sys.dont_write_bytecode, its -e/-d flags and its logging setup. run.py's
+argument parser answering --help shows the shim now runs run.py.
+"""
+
+import subprocess
+import sys
+from pathlib import Path
+
+REPO_ROOT = Path(__file__).resolve().parents[1]
+
+
+def test_root_display_controller_runs_run_py():
+    result = subprocess.run(
+        [sys.executable, str(REPO_ROOT / "display_controller.py"), "--help"],
+        cwd=str(REPO_ROOT), capture_output=True, text=True, timeout=60,
+    )
+    assert result.returncode == 0, result.stderr
+    assert "--emulator" in result.stdout and "--debug" in result.stdout