diff --git a/CHANGELOG.md b/CHANGELOG.md index f54edc55..8a5af2a0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,6 +17,25 @@ release that ships it. accepts both, but the store flags the old spelling as deprecated (`store_manager.py`) and only the new one is in `schema/manifest_schema.json`. +## Unreleased + +### Tooling + +- Golden trace tests for the display loop. `test/test_run_loop_golden.py` + runs the real `DisplayController.run()` against fake plugins on a fake + clock (`test/_run_loop_harness.py`), with no hardware and no real sleeps, + and compares which mode was shown, for how long and why it ended with + `test/fixtures/run_loop_golden/`. It has 15 scenarios: rotation, + empty and failing modes, dynamic duration, live priority, on-demand + (including pinned and resumed after a restart), the schedule and dim + schedule, WiFi notices, sync follower and Vegas. The whole file runs in + about a second. This is stage 1 of restructuring `run()`, described in + `docs/RUN_LOOP_REDESIGN.md`. The other part of stage 1 is internal and + changes no behaviour: twelve blocks of `run()` move into named helpers + (`_dispatch_first_frame`, `_resolve_durations`, `_resolve_active_mode`, + `_needs_high_fps`, `_advance_after_screen` and others), and the traces are + identical before and after the move. + ## 3.8.0 Live Vegas elements: plugin content that keeps changing while it scrolls diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 7a0d11c3..8f28883c 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -187,7 +187,8 @@ the scheduler), and sets up Vegas mode. enable/disable, poll on-demand requests, run scheduled plugin updates, check the on/off schedule and brightness, then show one screen. Priority is on-demand, then WiFi status messages, then live priority, then Vegas mode, -then normal rotation. +then normal rotation. [RUN_LOOP_REDESIGN.md](RUN_LOOP_REDESIGN.md) is the +plan for restructuring this loop and lists its golden trace tests. - **Rotation.** `available_modes` is the ordered list of display modes; `current_mode_index` advances after each screen. diff --git a/docs/RUN_LOOP_REDESIGN.md b/docs/RUN_LOOP_REDESIGN.md new file mode 100644 index 00000000..daedbd27 --- /dev/null +++ b/docs/RUN_LOOP_REDESIGN.md @@ -0,0 +1,277 @@ +# Restructuring `DisplayController.run()` + +`run()` in [`src/display_controller.py`](../src/display_controller.py) decides +what the panel shows and runs it. This document is the plan for turning it +from one long loop into three parts with clear jobs: an **Arbiter** that +decides, a **ScreenRunner** that runs one screen, and **Sources** that each +know about one kind of content. It covers the target design, the stages that +get there, and how each stage is checked. + +The goal is to change how the control flow is organised, not to move code +into more files. Each stage ships as its own PR, and none of them changes +what the panel shows unless that PR says so and updates the golden traces +on purpose. + +## Why + +- **The priority order is written in branch order, twice.** It is + Follower, on-demand, WiFi notice, live priority, Vegas, rotation. In + `run()` that order exists only as the order of `if` blocks. Vegas + repeats part of it in its interrupt callback (`_check_vegas_interrupt`). +- **Preemption is found by re-checking.** A screen ends early when + something else changed `current_display_mode` or `is_display_active` + underneath it. `run()` notices with five separate + `current_display_mode != active_mode` checks: after an empty pass, in each + of the two frame loops, after the frame loops, and before rotating. +- **Most recent fixes were ordering bugs** between these branches (#618, + #644, #649, #652): a lost mode switch, rotating past an on-demand request, + spinning when every mode is empty. +- **It could not be tested** without threads, real sleeps and stopping the + loop by raising from a patched method. + +## What `run()` does today + +Each pass, in order: + +1. `loop_pass()` (watchdog). Apply a pending plugin enable/disable. +2. With no modes: dwell 1 s, next pass. +3. Poll on-demand requests and expiry, release plugins loaded only for + on-demand, tick plugin updates, drop an expired WiFi notice, evaluate + the schedule (an on-demand session overrides scheduled-off), apply the + brightness target. +4. **Scheduled off:** blank, dwell up to 60 s. `_blank_while_scheduled_off` +5. **Follower:** render one frame from the leader. `_run_follower_frame` +6. **WiFi notice** (unless on-demand): draw it, dwell 0.5 s. `_show_wifi_notice` +7. **Live priority** (unless on-demand, or Vegas keeps live content in the + ticker): switch to the next live mode, or resume the rotation. +8. **Vegas** (unless on-demand, or live content preempts it): run one + iteration of up to `max_cycle_duration`. A completed iteration ends the + pass. An interrupted one falls through to step 9 in the same pass. +9. **One screen:** pick the mode (`_resolve_active_mode`), the plugin + (`_plugin_for_mode`), draw the first frame through the executor + (`_dispatch_first_frame`). On no content, rotate at once + (`_note_empty_pass`, `_skip_failed_plugin_modes`). Otherwise work out the + bounds (`_track_dynamic_cycle`, `_resolve_durations`, + `_clamp_to_on_demand`) and the frame rate (`_needs_high_fps`), run the + 125 Hz or 1 Hz frame loop, make up the minimum duration, then pick the + next mode (`_advance_after_screen`). + +The helpers named above were extracted in stage 1 without changing +behaviour. The frame loops, the Vegas branch and every early exit are still +inline in `run()`. + +## Target design + +```python +def run(self): + while True: + inputs = self._drain_inputs() # requests, schedule, config, sync + plan = self.arbiter.decide(self.state, inputs, clock.now()) + outcome = self.runner.run(plan) # ExitReason + elapsed + self.state = self.state.after(plan, outcome) # rotation, on-demand index, live resume +``` + +### Sources + +Each kind of content is a Source. A Source looks at the state and the +inputs and either offers a screen or passes. The Arbiter asks them in this +order: + +| Order | Source | Offers a screen when | Today | +|---|---|---|---| +| gate | ScheduledOff | the schedule is off and no on-demand session overrides it | step 4 | +| 1 | Follower | a sync leader is driving this panel | step 5 | +| 2 | OnDemand | a session is active (its mode list, index, expiry and pin) | `_resolve_active_mode` | +| 3 | Wifi | a status message is pending and on-demand is not active | step 6 | +| 4 | Live | a live-priority plugin has live content (round-robin across several) | step 7 | +| 5 | Vegas | Vegas is enabled and nothing above wants the panel | step 8 | +| 6 | Rotation | always: `available_modes[current_mode_index]` | step 9 | + +ScheduledOff is a gate in front of the Sources because that is how it works +today: a scheduled-off panel stays blank even for a follower, and only an +on-demand session overrides it. + +### Arbiter + +```python +Arbiter.decide(state, inputs, now) -> ScreenPlan +``` + +`decide` is a pure function: it does no I/O, takes no locks and does not +sleep. It can be tested with plain tables of (state, inputs, now) mapped to +an expected plan. It returns a `ScreenPlan`: + +| Field | Meaning | +|---|---| +| `source` | which Source won | +| `mode`, `plugin` | what to draw (None for a blank or follower plan) | +| `min_duration`, `max_duration` | from `_resolve_durations` and `_clamp_to_on_demand` | +| `dynamic` | run until the plugin's cycle completes, between min and max | +| `frame_policy` | today `_needs_high_fps` (125 Hz or 1 Hz); see stage 5 | +| `preemptible_by` | the Sources allowed to interrupt this plan mid-screen | + +### ScreenRunner + +```python +ScreenRunner(clock: FrameClock).run(plan) -> Outcome(exit_reason, elapsed) +``` + +The ScreenRunner draws the first frame (`_dispatch_first_frame`), runs the +frame loop that the plan's frame policy selects, services pending changes +between frames, and returns one `ExitReason`: + +| ExitReason | Today's equivalent (golden-trace exit) | +|---|---| +| `DURATION` | target duration reached (`duration`) | +| `CYCLE_COMPLETE` | dynamic plugin finished after its minimum (`cycle-complete`) | +| `EMPTY` | first frame returned False (`empty`; `raised` when display() raised inside the executor) | +| `ERROR` | the dispatch itself raised (`error`) | +| `DISPLAY_FALSE` | a later frame returned False (`display-false`) | +| `PREEMPTED` | another Source took the panel (`on-demand-*`, `schedule-off`, `vegas-interrupt`, ...) | + +`PREEMPTED` replaces the five `current_display_mode != active_mode` checks. +The runner asks the Arbiter, at the throttled service points it already has, +whether a Source in `plan.preemptible_by` now wants the panel. + +`FrameClock` provides `now()` and `sleep()`. In production it is +`time.monotonic`/`time.sleep`. In the golden traces it is the fake clock +that the harness patches in today. + +## Stages + +| Stage | Change | Behaviour change | Verified by | +|---|---|---|---| +| 1 | Golden traces; extract helpers from `run()` | none | traces generated on main pass unchanged; mutation check | +| 2 | Arbiter with Follower and Wifi Sources | none | traces unchanged; Arbiter unit tables; ledpi smoke | +| 3 | ScreenRunner, FrameClock, ExitReason, `PREEMPTED`; OnDemand, Live, Rotation Sources | none | traces unchanged; ledpi frame soak A/B | +| 4 | Vegas as a Source driven by `run_frame()` | none intended | traces against the real coordinator; ledpi Vegas soak A/B | +| 5 | Plugins declare `frame_policy` | DEBUG instead of INFO for the FPS line | traces; soak on a static-heavy rotation | + +### Stage 1 (this PR) + +- `test/_run_loop_harness.py` builds a real `DisplayController` through + `__init__` on in-memory fakes (plugins, cache, config service, plugin + manager, sync manager, display manager). It swaps the module's `time` and + `datetime` for one fake clock and runs the real `run()` until a horizon. + The first frame of each screen still goes through the real + `PluginExecutor` and the per-plugin locks. +- `test/test_run_loop_golden.py` has 15 scenarios, each compared with + `test/fixtures/run_loop_golden/.json`: + - plain rotation (display_durations override, a high-FPS scroller, a + plugin whose `display()` takes no `display_mode`) + - empty modes and a mode with no plugin; an all-empty rotation (the 1 s + pause) + - plugin errors and the circuit breaker + - dynamic duration (cycle complete, plugin cap, global cap) + - live priority taking over and handing back; live round-robin + - on-demand start/stop/expiry; pinned on-demand; a session resumed after + a restart + - schedule off and dim, with an on-demand override during downtime + - WiFi notice; sync follower + - Vegas, with and without `live_in_ticker` +- Each trace row is `[start, mode, duration, exit_reason, frames, + force_clear]`. The exit reason is the event that decided what came next. +- All 16 tests run in under a second. The goldens were generated from + main's `run()` before any code moved. +- Vegas uses `FakeVegas`, which implements only the contract the controller + depends on: `run_iteration()` returns True after its duration and False + when the interrupt or live check asks it to yield, checking at the real + coordinator's cadence. Running the real coordinator on the fake clock + belongs to stage 4. +- Twelve helpers were extracted from `run()` (listed under "What `run()` + does today"). Breaking any one of them fails at least one golden trace. + +### Stage 2: Arbiter, starting with Follower and Wifi + +1. Add `ScreenPlan` and an `Arbiter` with the ScheduledOff gate, Follower + and Wifi. Every other case returns a `LEGACY` plan, which means "carry on + with the existing code" (steps 7-9). +2. `run()` calls `decide()` after the bookkeeping in step 3 and dispatches + on `plan.source`: blank, `_run_follower_frame()`, the WiFi notice, or the + existing path. Inputs that Sources read (follower active, the pending + WiFi message, schedule state) are collected first, so `decide()` stays + pure. +3. Unit-test `decide()` with tables. The golden traces must not change. + This includes the missed WiFi notice described below: fixing it is a + separate PR. + +Follower and Wifi go first because each is one self-contained branch that +ends the pass. They prove the plumbing without touching the frame loops. + +### Stage 3: ScreenRunner and `PREEMPTED` + +Move the two frame loops, the make-up dwell and the dynamic-duration exit +into `ScreenRunner.run(plan)` with an injected `FrameClock`. Replace the +five re-checks with `PREEMPTED`. Add the OnDemand, Live and Rotation Sources +so `LEGACY` is left meaning only Vegas. + +This stage touches frame pacing (the 8 ms deadline sleep, the 1 ms yield), +so it needs a frame soak on ledpi, A/B against main. Coordinate with +whoever owns scroll performance (`docs/SCROLL_PERFORMANCE.md`). + +### Stage 4: Vegas as a Source + +The controller calls `coordinator.run_frame()` once per frame from the +ScreenRunner instead of handing over to `run_iteration()` for up to +`max_cycle_duration`. The interrupt callback and the second copy of the +priority order go away, because preemption becomes `PREEMPTED`. The +`vegas-plugin-tick` thread that is spawned every 4 s becomes the +controller's normal update tick. Extend the harness to drive the real +coordinator on the fake clock, which means patching its `time` and running +its prefetch inline. Verify with a Vegas soak on ledpi, A/B. + +### Stage 5: `frame_policy` + +Plugins declare `frame_policy` (STATIC, PERIODIC(hz), ANIMATED(fps), +SCROLL). `_needs_high_fps` becomes the mapping for legacy plugins +(`needs_high_fps`, the `static-image` special case, `enable_scrolling`), +and its per-screen INFO line drops to DEBUG. + +## How each stage is verified + +- **Golden traces.** Run `python -m pytest test/test_run_loop_golden.py`; + it takes about a second. A refactoring stage must leave every trace + unchanged. A deliberate behaviour change regenerates them with + `LEDMATRIX_REGEN_GOLDEN=1` in its own commit, and the commit message + explains each changed row. A new scenario's golden is generated against + main's `run()` first, then checked against the branch. +- **Mutation check.** Break each moved or new piece once, for example take + `max` of the caps instead of `min`, or skip the live hold. At least one + trace must fail each time. Stage 1 did this for all twelve helpers. +- **Full suite.** Diff the FAILED/ERROR ids against a baseline run of main + in a separate worktree. The Windows host has a stable set of + pre-existing failures, so never compare against zero. +- **ledpi soak** (stages 2-5). With the service running the branch: + `python3 scripts/frame_soak.py --preview` for 10 minutes on a scrolling + rotation, and on Vegas for stages 3-4. Alternate which build goes first. + Compare late-frame rate and freezes with main. Also check by hand that + on-demand start, stop and expiry, a live game taking over and handing + back, and the schedule turning the panel off and on all behave as before. + +## Behaviour the traces pin down that may be wrong + +These are recorded as they are today. Each one should be fixed in its own +PR, which updates the affected trace and explains why. None of them is +changed by the restructure. + +1. **A WiFi notice is only checked between screens.** A 5 s notice posted + during a 20 s screen expires before the screen ends and is never shown + (`wifi_notice`, t=25). +2. **Vegas yields to a WiFi notice, then shows a rotation screen instead of + the notice.** An interrupted iteration falls through to step 9 in the + same pass, and the notice has expired by the next pass (`vegas`, t=200). +3. **Vegas yields to live content, then shows a rotation screen first.** + The live game appears one screen later (`vegas`, t=70-90). +4. **Live priority only takes over between screens.** A game that goes + live mid-screen waits for that screen to end (`live_priority`: live at + t=50, shown at t=60). +5. **An on-demand session that expires during scheduled-off keeps the panel + on** until the next minute boundary, because the schedule check runs at + most once a minute (`schedule`, t=190-210). +6. **A schedule window's end minute is inclusive**, and whether the panel + turns off at the start of that minute or the end depends on when in the + minute the first check runs. +7. **A plugin whose `display()` raises inside the executor counts as "no + content"**, and the circuit breaker records it as a success, so it never + trips (`plugin_error`, `crashy`). Only an exception raised outside the + executor counts as a failure. diff --git a/src/display_controller.py b/src/display_controller.py index ff7d5e2d..bc7a0f03 100644 --- a/src/display_controller.py +++ b/src/display_controller.py @@ -2297,6 +2297,533 @@ class DisplayController: return self.current_display_mode return live_modes[0] + # -- Pieces of run() -------------------------------------------------- + # Extracted from run() unchanged, as the first step of restructuring it + # into an Arbiter / ScreenRunner / Sources (docs/RUN_LOOP_REDESIGN.md). + # test/test_run_loop_golden.py pins down what the loop does with them. + + def _blank_while_scheduled_off(self) -> None: + """One pass while the schedule has the panel off: blank it and dwell. + + The dwell returns early when on-demand starts or the schedule turns + the panel back on (see _sleep_with_plugin_updates). + """ + # Clear display when schedule makes it inactive to ensure blank screen + # (not showing initialization screen) + try: + self.display_manager.clear() + self.display_manager.update_display() + except Exception as e: + logger.debug(f"Error clearing display when inactive: {e}") + + logger.info(f"Display not active (is_display_active={self.is_display_active}), sleeping...") + self._publish_current_mode_state() + self._sleep_with_plugin_updates(60) + + def _run_follower_frame(self) -> None: + """One frame while a sync leader drives this panel (follower mode). + + Dead-reckoning follower render: advance the local position at the + configured speed each tick, then snap or nudge it toward the + leader's scroll_x to absorb UDP jitter. Paced to a fixed deadline + grid of _FOLLOWER_FRAME_INTERVAL. + """ + now_dr = time.perf_counter() + last_t = self._follower_dr_last_t + dt = now_dr - last_t if last_t is not None else 0.0 + self._follower_dr_last_t = now_dr + + vc = self.vegas_coordinator + rp = vc.render_pipeline if (vc and vc.render_pipeline) else None + width = self.display_manager.width + self._adopt_follower_scroll_image(rp) + + local_x = self._follower_local_x + if local_x is None: + local_x = float(width) # safe start (past pre-roll guard) + local_x += self._scroll_speed * dt + + # Latest position from the leader (None until a packet arrives) + scroll_x = self.sync_manager.get_latest_scroll_x() + if scroll_x is not None: + diff = scroll_x - local_x + total_w = ( + rp.scroll_helper.total_scroll_width + if rp and rp.scroll_helper.total_scroll_width + else width * _FOLLOWER_FALLBACK_STRIP_SCREENS + ) + if abs(diff) > total_w * _FOLLOWER_SNAP_FRACTION: + # A jump that large is a cycle reset: snap. + local_x = float(scroll_x) + self._follower_pending_new_image = True + elif abs(diff) > _FOLLOWER_DRIFT_PX: + local_x += diff * _FOLLOWER_DRIFT_GAIN + else: + local_x += diff * _FOLLOWER_NEAR_GAIN + + self._follower_local_x = local_x + + if rp and rp.scroll_helper.cached_image is not None: + # Hold last frame until TCP image arrives after cycle reset + if not self._follower_pending_new_image and local_x >= width: + rp.scroll_helper.scroll_position = ( + local_x + self._follower_sign() * width) + frame = rp.scroll_helper.get_visible_portion() + if frame is not None: + self._follower_last_frame = frame + elif scroll_x is None: + # Fallback: pixel frame before first scroll_x arrives + frame = self.sync_manager.get_latest_frame() + if frame is not None: + self._follower_last_frame = frame + + if self._follower_last_frame is not None: + self.display_manager.image = self._follower_last_frame + self.display_manager._sync_render_allowed = True + self.display_manager.update_display() + self.display_manager._sync_render_allowed = False + + # Pace to a fixed deadline grid rather than sleeping a + # flat interval, so render time doesn't lower the rate. + # After a stall longer than _FOLLOWER_DEADLINE_SLIP the + # grid restarts instead of rendering a burst to catch up. + now = time.perf_counter() + deadline = self._follower_deadline + if deadline is None or now > deadline + _FOLLOWER_DEADLINE_SLIP: + deadline = now + deadline += _FOLLOWER_FRAME_INTERVAL + self._follower_deadline = deadline + remaining = deadline - time.perf_counter() + if remaining > 0: + time.sleep(remaining) + + def _show_wifi_notice(self) -> bool: + """Show a pending WiFi status message for one pass. + + Returns True when the message was drawn, and the pass ends there + (no rotation). On-demand outranks it, so nothing is checked while + on-demand is active; a message that fails to draw is treated as no + message. + """ + if self.on_demand_active: + return False + wifi_status_data = self._check_wifi_status_message() + if not wifi_status_data: + return False + if not self._display_wifi_status_message(wifi_status_data): + # Display failed, clear the status and continue normally + return False + # The plugin that resumes afterwards must redraw + # the whole panel, not paint over the message. + self.force_change = True + self._sleep_with_plugin_updates(0.5) + return True + + def _resolve_active_mode(self): + """The mode this pass shows: the on-demand session's current mode + while one is active, else the rotation's. + + Moves current_display_mode onto the on-demand mode (forcing a clear) + when they differ, and ends an on-demand session that has no modes. + None when the rotation has no current mode. + """ + if not self.on_demand_active: + return self.current_display_mode + # Guard against empty on_demand_modes + if not self.on_demand_modes: + logger.warning("On-demand active but no modes available, clearing on-demand mode") + self._clear_on_demand(reason='no-modes-available') + return self.current_display_mode + # Rotate through on-demand plugin modes + if self.on_demand_mode_index >= len(self.on_demand_modes): + # Reset to first mode if index is out of bounds + self.on_demand_mode_index = 0 + active_mode = self.on_demand_modes[self.on_demand_mode_index] + if self.current_display_mode != active_mode: + self.current_display_mode = active_mode + self.force_change = True + return active_mode + + def _plugin_for_mode(self, mode: Optional[str]): + """The plugin to draw ``mode``, or None to skip it this pass. + + None when no plugin owns the mode, it has no display(), or the + circuit breaker has it switched off. + """ + if mode not in self.plugin_modes: + logger.warning(f"Mode {mode} not found in plugin_modes (available: {list(self.plugin_modes.keys())})") + return None + plugin_instance = self.plugin_modes[mode] + if not hasattr(plugin_instance, 'display'): + logger.warning(f"Plugin {mode} found but has no display() method") + return None + # Check plugin health before attempting to display + plugin_id = getattr(plugin_instance, 'plugin_id', mode) + health_tracker = self._health_tracker() + if health_tracker is not None and health_tracker.should_skip_plugin(plugin_id): + logger.info("Skipping plugin %s due to circuit breaker (mode: %s)", plugin_id, mode) + return None + logger.debug(f"Found plugin manager for mode {mode}: {type(plugin_instance).__name__}") + return plugin_instance + + def _dispatch_first_frame(self, plugin, active_mode: str) -> Tuple[bool, bool, bool]: + """Draw the first frame of a screen through the PluginExecutor. + + Later frames call display() directly (_display_once). This one goes + through the executor so a hang or an exception here is bounded and + recorded. + + Returns: + (shown, raised, accepts_display_mode). ``shown`` is False when + display() returned False (nothing to show) or anything raised; + ``raised`` says it was an exception rather than no content. + ``accepts_display_mode`` is the cached signature check the + screen's later frames need; it is only meaningful when shown. + """ + # A plugin that returns nothing (None) counts as having displayed. + display_result = True + # Whether a False result came from an exception rather than + # the plugin having no content. + display_failed_due_to_exception = False + _accepts_display_mode = False + plugin_id = getattr(plugin, 'plugin_id', active_mode) + try: + logger.debug(f"Calling display() for {active_mode} with force_clear={self.force_change}") + if plugin_id not in self._plugin_accepts_display_mode: + self._plugin_accepts_display_mode[plugin_id] = ( + 'display_mode' in inspect.signature(plugin.display).parameters + ) + _accepts_display_mode = self._plugin_accepts_display_mode[plugin_id] + + pm = self.plugin_manager + display_lock = pm.get_plugin_lock(plugin_id) if pm else None + can_display = display_lock is None or display_lock.acquire(blocking=False) + display_hung = False + + if display_lock is None: + # Only when plugin loading failed part-way. + result = self._display_once( + plugin, active_mode, _accepts_display_mode, + force_clear=self.force_change) + elif not can_display: + # update() in flight on the worker — hold + # the last frame; not a plugin failure + result = True + else: + # PluginExecutor's own thread.join(timeout) can + # return before the real display() call + # finishes (a lingering daemon thread keeps + # running it) -- so the lock is released from + # inside the wrapped call itself, whichever + # thread actually finishes it, rather than + # here when this dispatch merely returns. + release_guard = threading.Lock() + released = {'done': False, 'started': False} + + def _release_display_lock(): + with release_guard: + if released['done']: + return + released['done'] = True + display_lock.release() + + if _accepts_display_mode: + def _display_target(display_mode=None, force_clear=False): + released['started'] = True + try: + return plugin.display( + display_mode=display_mode, force_clear=force_clear) + finally: + _release_display_lock() + else: + def _display_target(force_clear=False): + released['started'] = True + try: + return plugin.display(force_clear=force_clear) + finally: + _release_display_lock() + + dispatch_start = time.monotonic() + try: + result = pm.plugin_executor.execute_display( + types.SimpleNamespace(display=_display_target), + plugin_id, + force_clear=self.force_change, + display_mode=active_mode if _accepts_display_mode else None, + # Already resolved and cached above. + # Without this the executor re-derives + # it with inspect.signature() against + # the SimpleNamespace built above -- a + # fresh callable every call, so nothing + # there can ever cache. + accepts_display_mode=_accepts_display_mode + ) + except Exception: # pragma: no cover - defensive; + # execute_display catches everything + # internally, but guarantee the lock is + # never leaked if something unexpected + # slips through. + _release_display_lock() + raise + + dispatch_seconds = time.monotonic() - dispatch_start + if released['started'] and not released['done']: + # The executor gave up waiting and display() + # is still running on its thread, holding + # the lock. A hang, not a success: recorded + # so repeats open the circuit breaker, and + # the update worker's bounded wait skips it. + display_hung = True + pm.record_display_hang(plugin_id, dispatch_seconds) + else: + pm.note_display_duration(plugin_id, dispatch_seconds) + + logger.debug(f"display() returned: {result} (type: {type(result)})") + if isinstance(result, bool): + display_result = result + if not display_result: + logger.debug("Plugin %s display() returned False for mode %s", plugin_id, active_mode) + + # Record success only when display() actually ran this + # frame -- a skipped frame (lock busy) held the last + # frame, not a real success, and must not clear + # force_change or the pending mode-switch clear will + # be lost when display() finally does run. + if can_display: + health_tracker = self._health_tracker() + if health_tracker is not None and not display_hung: + health_tracker.record_success(plugin_id) + self.force_change = False + except Exception as exc: # pylint: disable=broad-except + logger.exception("Error displaying %s", self.current_display_mode) + health_tracker = self._health_tracker() + if health_tracker is not None: + health_tracker.record_failure(plugin_id, exc) + self.force_change = True + display_result = False + display_failed_due_to_exception = True + return display_result, display_failed_due_to_exception, _accepts_display_mode + + def _skip_failed_plugin_modes(self, active_mode: str) -> bool: + """After a plugin's dispatch raised, move the rotation past every + mode that plugin owns. + + Returns True when it moved to another plugin's mode. False when + every remaining mode is the failed plugin's (or the mode has no + known plugin): the caller then rotates normally. + """ + current_plugin_id = self.mode_to_plugin_id.get(active_mode) + if not (current_plugin_id and current_plugin_id in self.plugin_display_modes): + return False + plugin_modes = self.plugin_display_modes[current_plugin_id] + logger.warning("Skipping all %d mode(s) for plugin %s due to exception: %s", + len(plugin_modes), current_plugin_id, plugin_modes) + # Find the next mode that's not from this plugin + next_index = self.current_mode_index + attempts = 0 + max_attempts = len(self.available_modes) + while attempts < max_attempts: + next_index = (next_index + 1) % len(self.available_modes) + next_mode = self.available_modes[next_index] + next_plugin_id = self.mode_to_plugin_id.get(next_mode) + if next_plugin_id != current_plugin_id: + self.current_mode_index = next_index + self.current_display_mode = next_mode + self.force_change = True + logger.info("Switching to mode: %s (skipped plugin %s due to exception)", + self.current_display_mode, current_plugin_id) + return True + attempts += 1 + # If we couldn't find a different plugin, just advance normally + logger.warning("All remaining modes are from plugin %s, advancing normally", current_plugin_id) + return False + + def _track_dynamic_cycle(self, plugin, active_mode: str, dynamic_enabled: bool) -> None: + """Reset the plugin's cycle when a different dynamic-duration mode + comes on screen; forget the active one when dynamic duration is off. + + Only switching to a different dynamic mode resets the cycle. Staying + on the same live-priority mode with force_change=True (which is used + for display clearing, not cycle resets) must not. + """ + if dynamic_enabled and self._active_dynamic_mode != active_mode: + if self._active_dynamic_mode is not None: + logger.debug( + "Switching dynamic duration mode from %s to %s - resetting cycle", + self._active_dynamic_mode, + active_mode, + ) + else: + logger.debug( + "Starting dynamic duration mode %s - resetting cycle", + active_mode, + ) + self._plugin_reset_cycle(plugin) + self._active_dynamic_mode = active_mode + elif not dynamic_enabled and self._active_dynamic_mode == active_mode: + logger.debug( + "Dynamic duration disabled for mode %s - clearing active dynamic mode", + active_mode, + ) + self._active_dynamic_mode = None + + def _resolve_durations(self, plugin, active_mode: str, base_duration: float, + dynamic_enabled: bool) -> Tuple[float, float]: + """The (min, max) seconds a screen of ``active_mode`` runs for. + + Without dynamic duration both are the mode's display duration. With + it, min is the display duration and max is the plugin's own cycle + duration if it reports one, capped by the smaller of the plugin's + and the global cap (DEFAULT_DYNAMIC_DURATION_CAP when neither is + set), and never below min. A non-positive duration becomes 15 s. + + Changes no controller state; it only asks the plugin and config. + """ + min_duration = base_duration + if dynamic_enabled: + # Try to get plugin-calculated cycle duration first + logger.debug("Attempting to get cycle duration for mode %s", active_mode) + plugin_cycle_duration = self._plugin_cycle_duration(plugin, active_mode) + logger.debug("Got cycle duration: %s", plugin_cycle_duration) + + # Get caps for validation + plugin_cap = self._plugin_dynamic_cap(plugin) + global_cap = self._get_global_dynamic_cap() + cap_candidates = [ + cap + for cap in (plugin_cap, global_cap) + if cap is not None and cap > 0 + ] + if cap_candidates: + chosen_cap = min(cap_candidates) + else: + chosen_cap = DEFAULT_DYNAMIC_DURATION_CAP + + # Validate and sanitize durations + if min_duration <= 0: + logger.warning( + "Invalid min_duration %s for mode %s, using default 15s", + min_duration, + active_mode, + ) + min_duration = 15.0 + + # Use plugin-calculated duration if available, capped by max + if plugin_cycle_duration is not None and plugin_cycle_duration > 0: + # Plugin provided a calculated duration - use it but respect cap + max_duration = min(plugin_cycle_duration, chosen_cap) + logger.info( + "Using plugin-calculated cycle duration for %s: %.1fs (capped at %.1fs)", + active_mode, + plugin_cycle_duration, + chosen_cap, + ) + else: + # No calculated duration - use cap as max + max_duration = chosen_cap + + # Ensure max_duration >= min_duration + max_duration = max(min_duration, max_duration) + else: + max_duration = base_duration + + # Validate base duration even when not dynamic + if max_duration <= 0: + logger.warning( + "Invalid base_duration %s for mode %s, using default 15s", + max_duration, + active_mode, + ) + max_duration = 15.0 + return min_duration, max_duration + + def _clamp_to_on_demand(self, min_duration: float, + max_duration: float) -> Optional[Tuple[float, float]]: + """Shorten a screen's (min, max) to what is left of a timed on-demand + session. None when the session has no time left (nothing to show). + """ + if self.on_demand_active: + remaining = self._get_on_demand_remaining() + if remaining is not None: + min_duration = min(min_duration, remaining) + max_duration = min(max_duration, remaining) + if max_duration <= 0: + return None + return min_duration, max_duration + + def _needs_high_fps(self, plugin, active_mode: str) -> bool: + """Whether a screen runs the high-FPS (8 ms) loop or the 1 s one. + + In precedence order: + 1. A plugin that declares needs_high_fps knows best + (e.g. static-image sets it False for still PNGs, + True for animated GIFs). + 2. Back-compat: older static-image versions without + the attribute keep the historical forced high-FPS + (GIF support). + 3. Otherwise scrolling plugins get high FPS. + """ + plugin_id = getattr(plugin, 'plugin_id', None) + declared = getattr(plugin, 'needs_high_fps', None) + if declared is not None: + needs_high_fps = bool(declared) + logger.debug( + "[DisplayController] FPS check for %s (plugin=%s) - " + "plugin declares needs_high_fps=%s", + active_mode, plugin_id, needs_high_fps) + elif plugin_id == 'static-image': + needs_high_fps = True + logger.debug("FPS check - static-image plugin: forcing high-FPS mode for GIF support") + else: + has_enable_scrolling = hasattr(plugin, 'enable_scrolling') + enable_scrolling_value = getattr(plugin, 'enable_scrolling', False) + needs_high_fps = has_enable_scrolling and enable_scrolling_value + logger.info( + "FPS check for %s - has_enable_scrolling: %s, enable_scrolling_value: %s, needs_high_fps: %s", + active_mode, + has_enable_scrolling, + enable_scrolling_value, + needs_high_fps, + ) + return needs_high_fps + + def _advance_after_screen(self, active_mode: Optional[str]) -> None: + """Pick the next mode once a screen has run its course. + + An on-demand session moves to its next mode (one with no modes left + is ended, and the rotation advances instead). Otherwise the rotation + advances -- unless the mode just shown is a live-priority mode that + is still live, which holds the panel. + """ + if self.on_demand_active: + # Guard against empty on_demand_modes to prevent ZeroDivisionError + if not self.on_demand_modes: + logger.warning("On-demand active but no modes available, clearing on-demand mode") + self._clear_on_demand(reason='no-modes-available') + # Fall through to normal rotation + else: + self._advance_on_demand() + return + + # Check for live priority - don't rotate if current plugin has live content + should_rotate = True + if active_mode in self.plugin_modes: + plugin_instance = self.plugin_modes[active_mode] + if hasattr(plugin_instance, 'has_live_priority') and hasattr(plugin_instance, 'has_live_content'): + try: + if plugin_instance.has_live_priority() and plugin_instance.has_live_content(): + logger.info("Live priority active for %s - staying on current mode", active_mode) + should_rotate = False + except Exception as e: + logger.warning("Error checking live priority for %s: %s", active_mode, e) + + if should_rotate and self.available_modes: + self.current_mode_index = (self.current_mode_index + 1) % len(self.available_modes) + self.current_display_mode = self.available_modes[self.current_mode_index] + self.force_change = True + + logger.info("Switching to mode: %s", self.current_display_mode) + def run(self): """Run the display controller, switching between displays.""" if not self.available_modes: @@ -2372,17 +2899,7 @@ class DisplayController: self._apply_brightness_target() if not self.is_display_active: - # Clear display when schedule makes it inactive to ensure blank screen - # (not showing initialization screen) - try: - self.display_manager.clear() - self.display_manager.update_display() - except Exception as e: - logger.debug(f"Error clearing display when inactive: {e}") - - logger.info(f"Display not active (is_display_active={self.is_display_active}), sleeping...") - self._publish_current_mode_state() - self._sleep_with_plugin_updates(60) + self._blank_while_scheduled_off() continue self._publish_current_mode_state_if_changed() @@ -2396,78 +2913,7 @@ class DisplayController: # Plugin update() threads still run (via _tick_plugin_updates above) so # data is fresh when we return to standalone if the leader goes offline. if self.sync_manager.is_follower_active(): - # Dead-reckoning follower render: advance the local - # position at the configured speed each tick, then snap or - # nudge it toward the leader's scroll_x to absorb UDP - # jitter. - now_dr = time.perf_counter() - last_t = self._follower_dr_last_t - dt = now_dr - last_t if last_t is not None else 0.0 - self._follower_dr_last_t = now_dr - - vc = self.vegas_coordinator - rp = vc.render_pipeline if (vc and vc.render_pipeline) else None - width = self.display_manager.width - self._adopt_follower_scroll_image(rp) - - local_x = self._follower_local_x - if local_x is None: - local_x = float(width) # safe start (past pre-roll guard) - local_x += self._scroll_speed * dt - - # Latest position from the leader (None until a packet arrives) - scroll_x = self.sync_manager.get_latest_scroll_x() - if scroll_x is not None: - diff = scroll_x - local_x - total_w = ( - rp.scroll_helper.total_scroll_width - if rp and rp.scroll_helper.total_scroll_width - else width * _FOLLOWER_FALLBACK_STRIP_SCREENS - ) - if abs(diff) > total_w * _FOLLOWER_SNAP_FRACTION: - # A jump that large is a cycle reset: snap. - local_x = float(scroll_x) - self._follower_pending_new_image = True - elif abs(diff) > _FOLLOWER_DRIFT_PX: - local_x += diff * _FOLLOWER_DRIFT_GAIN - else: - local_x += diff * _FOLLOWER_NEAR_GAIN - - self._follower_local_x = local_x - - if rp and rp.scroll_helper.cached_image is not None: - # Hold last frame until TCP image arrives after cycle reset - if not self._follower_pending_new_image and local_x >= width: - rp.scroll_helper.scroll_position = ( - local_x + self._follower_sign() * width) - frame = rp.scroll_helper.get_visible_portion() - if frame is not None: - self._follower_last_frame = frame - elif scroll_x is None: - # Fallback: pixel frame before first scroll_x arrives - frame = self.sync_manager.get_latest_frame() - if frame is not None: - self._follower_last_frame = frame - - if self._follower_last_frame is not None: - self.display_manager.image = self._follower_last_frame - self.display_manager._sync_render_allowed = True - self.display_manager.update_display() - self.display_manager._sync_render_allowed = False - - # Pace to a fixed deadline grid rather than sleeping a - # flat interval, so render time doesn't lower the rate. - # After a stall longer than _FOLLOWER_DEADLINE_SLIP the - # grid restarts instead of rendering a burst to catch up. - now = time.perf_counter() - deadline = self._follower_deadline - if deadline is None or now > deadline + _FOLLOWER_DEADLINE_SLIP: - deadline = now - deadline += _FOLLOWER_FRAME_INTERVAL - self._follower_deadline = deadline - remaining = deadline - time.perf_counter() - if remaining > 0: - time.sleep(remaining) + self._run_follower_frame() continue # Process any deferred updates that may have accumulated @@ -2476,20 +2922,9 @@ class DisplayController: # Check for WiFi status message (interrupts normal rotation, but respects on-demand) # Priority: on-demand > wifi-status > live-priority > normal rotation - wifi_status_data = None - if not self.on_demand_active: - wifi_status_data = self._check_wifi_status_message() - if wifi_status_data: - # Display WiFi status message and skip normal rotation - if self._display_wifi_status_message(wifi_status_data): - # The plugin that resumes afterwards must redraw - # the whole panel, not paint over the message. - self.force_change = True - self._sleep_with_plugin_updates(0.5) - continue # Skip to next iteration, don't rotate - else: - # Display failed, clear the status and continue normally - wifi_status_data = None + # Past this point no WiFi message is showing this pass. + if self._show_wifi_notice(): + continue # Skip to next iteration, don't rotate # Check for live priority content and switch to it immediately. # advance=True so multiple simultaneously-live games take turns @@ -2497,7 +2932,7 @@ class DisplayController: # Skipped when the ticker is keeping live content: switching # the rotation underneath Vegas would move current_mode_index # and stash a resume point for a takeover that never happens. - if (not self.on_demand_active and not wifi_status_data + if (not self.on_demand_active and not (self._is_vegas_mode_active() and self._vegas_keeps_live_in_ticker())): live_priority_mode = self._check_live_priority(advance=True) @@ -2505,7 +2940,7 @@ class DisplayController: # Vegas scroll mode - continuous ticker across all plugins # Priority: on-demand > wifi-status > live-priority > vegas > normal rotation - if self._is_vegas_mode_active() and not wifi_status_data: + if self._is_vegas_mode_active(): # Live content normally preempts the ticker entirely. With # vegas_scroll.live_in_ticker the marquee keeps running and # the live plugin takes extra turns inside it instead -- @@ -2529,186 +2964,30 @@ class DisplayController: logger.exception("Vegas mode error") # Fall through to normal rotation on error - if self.on_demand_active: - # Guard against empty on_demand_modes - if not self.on_demand_modes: - logger.warning("On-demand active but no modes available, clearing on-demand mode") - self._clear_on_demand(reason='no-modes-available') - active_mode = self.current_display_mode - else: - # Rotate through on-demand plugin modes - if self.on_demand_mode_index < len(self.on_demand_modes): - active_mode = self.on_demand_modes[self.on_demand_mode_index] - if self.current_display_mode != active_mode: - self.current_display_mode = active_mode - self.force_change = True - else: - # Reset to first mode if index is out of bounds - self.on_demand_mode_index = 0 - active_mode = self.on_demand_modes[0] - if self.current_display_mode != active_mode: - self.current_display_mode = active_mode - self.force_change = True - else: - active_mode = self.current_display_mode + active_mode = self._resolve_active_mode() if self._active_dynamic_mode and self._active_dynamic_mode != active_mode: self._active_dynamic_mode = None - manager_to_display = None - # DEBUG, not INFO: "Switching to mode" already logged this mode. Every # routine rotation line lands in the persistent journal, and on an SD # card each one costs far more than its bytes: measured on ledpi, about # 9 KB of card writes per stored line. logger.debug("Processing mode: %s (%d available)", active_mode, len(self.available_modes)) logger.debug("Loaded plugin modes: %s", list(self.plugin_modes.keys())) - + # Handle plugin-based display modes - if active_mode in self.plugin_modes: - plugin_instance = self.plugin_modes[active_mode] - if hasattr(plugin_instance, 'display'): - # Check plugin health before attempting to display - plugin_id = getattr(plugin_instance, 'plugin_id', active_mode) - health_tracker = self._health_tracker() - should_skip = (health_tracker is not None - and health_tracker.should_skip_plugin(plugin_id)) - if should_skip: - logger.info("Skipping plugin %s due to circuit breaker (mode: %s)", plugin_id, active_mode) - else: - manager_to_display = plugin_instance - logger.debug(f"Found plugin manager for mode {active_mode}: {type(plugin_instance).__name__}") - else: - logger.warning(f"Plugin {active_mode} found but has no display() method") - else: - logger.warning(f"Mode {active_mode} not found in plugin_modes (available: {list(self.plugin_modes.keys())})") - - # Display the current mode. A plugin that returns nothing - # (None) counts as having displayed. - display_result = True - # Whether a False result came from an exception rather than - # the plugin having no content. - display_failed_due_to_exception = False + manager_to_display = self._plugin_for_mode(active_mode) + + # Display the current mode. if not manager_to_display: logger.warning(f"No plugin manager found for mode {active_mode} - skipping display and rotating to next mode") display_result = False + display_failed_due_to_exception = False else: - plugin_id = getattr(manager_to_display, 'plugin_id', active_mode) - try: - logger.debug(f"Calling display() for {active_mode} with force_clear={self.force_change}") - if plugin_id not in self._plugin_accepts_display_mode: - self._plugin_accepts_display_mode[plugin_id] = ( - 'display_mode' in inspect.signature(manager_to_display.display).parameters - ) - _accepts_display_mode = self._plugin_accepts_display_mode[plugin_id] - - pm = self.plugin_manager - display_lock = pm.get_plugin_lock(plugin_id) if pm else None - can_display = display_lock is None or display_lock.acquire(blocking=False) - display_hung = False - - if display_lock is None: - # Only when plugin loading failed part-way. - result = self._display_once( - manager_to_display, active_mode, _accepts_display_mode, - force_clear=self.force_change) - elif not can_display: - # update() in flight on the worker — hold - # the last frame; not a plugin failure - result = True - else: - # PluginExecutor's own thread.join(timeout) can - # return before the real display() call - # finishes (a lingering daemon thread keeps - # running it) -- so the lock is released from - # inside the wrapped call itself, whichever - # thread actually finishes it, rather than - # here when this dispatch merely returns. - release_guard = threading.Lock() - released = {'done': False, 'started': False} - - def _release_display_lock(): - with release_guard: - if released['done']: - return - released['done'] = True - display_lock.release() - - if _accepts_display_mode: - def _display_target(display_mode=None, force_clear=False): - released['started'] = True - try: - return manager_to_display.display( - display_mode=display_mode, force_clear=force_clear) - finally: - _release_display_lock() - else: - def _display_target(force_clear=False): - released['started'] = True - try: - return manager_to_display.display(force_clear=force_clear) - finally: - _release_display_lock() - - dispatch_start = time.monotonic() - try: - result = pm.plugin_executor.execute_display( - types.SimpleNamespace(display=_display_target), - plugin_id, - force_clear=self.force_change, - display_mode=active_mode if _accepts_display_mode else None, - # Already resolved and cached above. - # Without this the executor re-derives - # it with inspect.signature() against - # the SimpleNamespace built above -- a - # fresh callable every call, so nothing - # there can ever cache. - accepts_display_mode=_accepts_display_mode - ) - except Exception: # pragma: no cover - defensive; - # execute_display catches everything - # internally, but guarantee the lock is - # never leaked if something unexpected - # slips through. - _release_display_lock() - raise - - dispatch_seconds = time.monotonic() - dispatch_start - if released['started'] and not released['done']: - # The executor gave up waiting and display() - # is still running on its thread, holding - # the lock. A hang, not a success: recorded - # so repeats open the circuit breaker, and - # the update worker's bounded wait skips it. - display_hung = True - pm.record_display_hang(plugin_id, dispatch_seconds) - else: - pm.note_display_duration(plugin_id, dispatch_seconds) - - logger.debug(f"display() returned: {result} (type: {type(result)})") - if isinstance(result, bool): - display_result = result - if not display_result: - logger.debug("Plugin %s display() returned False for mode %s", plugin_id, active_mode) - - # Record success only when display() actually ran this - # frame -- a skipped frame (lock busy) held the last - # frame, not a real success, and must not clear - # force_change or the pending mode-switch clear will - # be lost when display() finally does run. - if can_display: - health_tracker = self._health_tracker() - if health_tracker is not None and not display_hung: - health_tracker.record_success(plugin_id) - self.force_change = False - except Exception as exc: # pylint: disable=broad-except - logger.exception("Error displaying %s", self.current_display_mode) - health_tracker = self._health_tracker() - if health_tracker is not None: - health_tracker.record_failure(plugin_id, exc) - self.force_change = True - display_result = False - display_failed_due_to_exception = True + (display_result, display_failed_due_to_exception, + _accepts_display_mode) = self._dispatch_first_frame( + manager_to_display, active_mode) # If display() returned False, skip to next mode immediately if not display_result: @@ -2737,37 +3016,10 @@ class DisplayController: # Only skip all modes for this plugin if there was an exception (broken plugin) # If it's just "no content", we should still try other modes (recent, upcoming) - if display_failed_due_to_exception: - current_plugin_id = self.mode_to_plugin_id.get(active_mode) - if current_plugin_id and current_plugin_id in self.plugin_display_modes: - plugin_modes = self.plugin_display_modes[current_plugin_id] - logger.warning("Skipping all %d mode(s) for plugin %s due to exception: %s", - len(plugin_modes), current_plugin_id, plugin_modes) - # Find the next mode that's not from this plugin - next_index = self.current_mode_index - attempts = 0 - max_attempts = len(self.available_modes) - found_next = False - while attempts < max_attempts: - next_index = (next_index + 1) % len(self.available_modes) - next_mode = self.available_modes[next_index] - next_plugin_id = self.mode_to_plugin_id.get(next_mode) - if next_plugin_id != current_plugin_id: - self.current_mode_index = next_index - self.current_display_mode = next_mode - self.force_change = True - logger.info("Switching to mode: %s (skipped plugin %s due to exception)", - self.current_display_mode, current_plugin_id) - found_next = True - break - attempts += 1 - # If we couldn't find a different plugin, just advance normally - if not found_next: - logger.warning("All remaining modes are from plugin %s, advancing normally", current_plugin_id) - # Will fall through to normal rotation logic below - else: - # Already set next mode, skip to next iteration - continue + if (display_failed_due_to_exception + and self._skip_failed_plugin_modes(active_mode)): + # Already set next mode, skip to next iteration + continue # If no exception (just no content), fall through to normal rotation logic # This allows trying other modes (recent, upcoming) from the same plugin else: @@ -2775,7 +3027,7 @@ class DisplayController: # Get base duration for current mode base_duration = self._get_display_duration(active_mode) dynamic_enabled = self._plugin_supports_dynamic(manager_to_display) - + # Log dynamic duration status if dynamic_enabled: logger.debug( @@ -2784,127 +3036,17 @@ class DisplayController: getattr(manager_to_display, "plugin_id", "unknown"), ) - # Only reset cycle when actually switching to a different dynamic mode. - # This prevents resetting the cycle when staying on the same live priority mode - # with force_change=True (which is used for display clearing, not cycle resets). - if dynamic_enabled and self._active_dynamic_mode != active_mode: - if self._active_dynamic_mode is not None: - logger.debug( - "Switching dynamic duration mode from %s to %s - resetting cycle", - self._active_dynamic_mode, - active_mode, - ) - else: - logger.debug( - "Starting dynamic duration mode %s - resetting cycle", - active_mode, - ) - self._plugin_reset_cycle(manager_to_display) - self._active_dynamic_mode = active_mode - elif not dynamic_enabled and self._active_dynamic_mode == active_mode: - logger.debug( - "Dynamic duration disabled for mode %s - clearing active dynamic mode", - active_mode, - ) - self._active_dynamic_mode = None + self._track_dynamic_cycle(manager_to_display, active_mode, dynamic_enabled) + min_duration, max_duration = self._resolve_durations( + manager_to_display, active_mode, base_duration, dynamic_enabled) - min_duration = base_duration - if dynamic_enabled: - # Try to get plugin-calculated cycle duration first - logger.debug("Attempting to get cycle duration for mode %s", active_mode) - plugin_cycle_duration = self._plugin_cycle_duration(manager_to_display, active_mode) - logger.debug("Got cycle duration: %s", plugin_cycle_duration) - - # Get caps for validation - plugin_cap = self._plugin_dynamic_cap(manager_to_display) - global_cap = self._get_global_dynamic_cap() - cap_candidates = [ - cap - for cap in (plugin_cap, global_cap) - if cap is not None and cap > 0 - ] - if cap_candidates: - chosen_cap = min(cap_candidates) - else: - chosen_cap = DEFAULT_DYNAMIC_DURATION_CAP - - # Validate and sanitize durations - if min_duration <= 0: - logger.warning( - "Invalid min_duration %s for mode %s, using default 15s", - min_duration, - active_mode, - ) - min_duration = 15.0 - - # Use plugin-calculated duration if available, capped by max - if plugin_cycle_duration is not None and plugin_cycle_duration > 0: - # Plugin provided a calculated duration - use it but respect cap - target_duration = min(plugin_cycle_duration, chosen_cap) - max_duration = target_duration - logger.info( - "Using plugin-calculated cycle duration for %s: %.1fs (capped at %.1fs)", - active_mode, - plugin_cycle_duration, - chosen_cap, - ) - else: - # No calculated duration - use cap as max - max_duration = chosen_cap - - # Ensure max_duration >= min_duration - max_duration = max(min_duration, max_duration) - else: - max_duration = base_duration - - # Validate base duration even when not dynamic - if max_duration <= 0: - logger.warning( - "Invalid base_duration %s for mode %s, using default 15s", - max_duration, - active_mode, - ) - max_duration = 15.0 + bounds = self._clamp_to_on_demand(min_duration, max_duration) + if bounds is None: + self._check_on_demand_expiration() + continue + min_duration, max_duration = bounds - if self.on_demand_active: - remaining = self._get_on_demand_remaining() - if remaining is not None: - min_duration = min(min_duration, remaining) - max_duration = min(max_duration, remaining) - if max_duration <= 0: - self._check_on_demand_expiration() - continue - - # High-FPS decision, in precedence order: - # 1. A plugin that declares needs_high_fps knows best - # (e.g. static-image sets it False for still PNGs, - # True for animated GIFs). - # 2. Back-compat: older static-image versions without - # the attribute keep the historical forced high-FPS - # (GIF support). - # 3. Otherwise scrolling plugins get high FPS. - plugin_id = getattr(manager_to_display, 'plugin_id', None) - declared = getattr(manager_to_display, 'needs_high_fps', None) - if declared is not None: - needs_high_fps = bool(declared) - logger.debug( - "[DisplayController] FPS check for %s (plugin=%s) - " - "plugin declares needs_high_fps=%s", - active_mode, plugin_id, needs_high_fps) - elif plugin_id == 'static-image': - needs_high_fps = True - logger.debug("FPS check - static-image plugin: forcing high-FPS mode for GIF support") - else: - has_enable_scrolling = hasattr(manager_to_display, 'enable_scrolling') - enable_scrolling_value = getattr(manager_to_display, 'enable_scrolling', False) - needs_high_fps = has_enable_scrolling and enable_scrolling_value - logger.info( - "FPS check for %s - has_enable_scrolling: %s, enable_scrolling_value: %s, needs_high_fps: %s", - active_mode, - has_enable_scrolling, - enable_scrolling_value, - needs_high_fps, - ) + needs_high_fps = self._needs_high_fps(manager_to_display, active_mode) target_duration = max_duration start_time = time.time() @@ -3131,34 +3273,7 @@ class DisplayController: continue # Move to next mode - if self.on_demand_active: - # Guard against empty on_demand_modes to prevent ZeroDivisionError - if not self.on_demand_modes: - logger.warning("On-demand active but no modes available, clearing on-demand mode") - self._clear_on_demand(reason='no-modes-available') - # Fall through to normal rotation - else: - self._advance_on_demand() - continue - - # Check for live priority - don't rotate if current plugin has live content - should_rotate = True - if active_mode in self.plugin_modes: - plugin_instance = self.plugin_modes[active_mode] - if hasattr(plugin_instance, 'has_live_priority') and hasattr(plugin_instance, 'has_live_content'): - try: - if plugin_instance.has_live_priority() and plugin_instance.has_live_content(): - logger.info("Live priority active for %s - staying on current mode", active_mode) - should_rotate = False - except Exception as e: - logger.warning("Error checking live priority for %s: %s", active_mode, e) - - if should_rotate and self.available_modes: - self.current_mode_index = (self.current_mode_index + 1) % len(self.available_modes) - self.current_display_mode = self.available_modes[self.current_mode_index] - self.force_change = True - - logger.info("Switching to mode: %s", self.current_display_mode) + self._advance_after_screen(active_mode) except KeyboardInterrupt: logger.info("Received interrupt signal, shutting down...") diff --git a/test/_run_loop_harness.py b/test/_run_loop_harness.py new file mode 100644 index 00000000..c2684885 --- /dev/null +++ b/test/_run_loop_harness.py @@ -0,0 +1,814 @@ +"""Drive the real DisplayController.run() on a fake clock and record a trace. + +The golden trace tests (test_run_loop_golden.py) use this to pin down what +run() does today -- which mode is on the panel, for how long, and why it +left -- so that the loop can be restructured (docs/RUN_LOOP_REDESIGN.md) +without changing any of it. + +What is real and what is fake +----------------------------- +Real: DisplayController itself (constructed through __init__, then run()), +PluginExecutor (each screen's first frame still goes through its thread), +the per-plugin display locks, and every controller method run() calls. + +Fake, so the run is deterministic and takes milliseconds: + +* the clock -- ``src.display_controller.time`` and ``datetime`` are replaced + by one FakeClock; sleeping only advances it. Scripted events (an on-demand + request, a WiFi notice, live content starting) fire as it passes them. +* plugins -- FakePlugin, whose content, liveness and dynamic-duration answers + are functions of the fake clock. +* the plugin manager, cache, config service, display manager and sync + manager -- in-memory stand-ins with no threads. +* the Vegas coordinator -- FakeVegas implements only the contract the + controller relies on (run_iteration() returning True when it ran its + duration and False when interrupted, the interrupt and live checks it + calls back into). The real coordinator spawns threads and renders a strip; + driving it on the fake clock is part of stage 4 (Vegas as a Source). + +The run ends when the fake clock passes the scenario's horizon: the clock +raises StopRun, a BaseException, which run()'s ``except Exception`` lets +through after its ``finally`` has run cleanup(). + +How the trace is read +--------------------- +Everything observable is appended to one ordered event log. reduce_trace() +folds it into screens: a screen starts at the first display() call of a +loop pass (a "pass" is one call of the watchdog's loop_pass(), at the top of +run()'s loop), or at the first follower / Vegas / WiFi / blank frame. Its +exit reason is the first reason-bearing event logged before the next screen +starts, else ``duration``. +""" + +from __future__ import annotations + +import json +import os +import threading +from datetime import datetime, timezone +from pathlib import Path +from types import SimpleNamespace +from typing import Any, Callable, Dict, List, Optional, Tuple +from unittest.mock import MagicMock, patch + +from src.common.sync_manager import SyncRole +from src.plugin_system.plugin_executor import PluginExecutor + +GOLDEN_DIR = Path(__file__).parent / "fixtures" / "run_loop_golden" + +#: Monday 2026-01-05 22:59:30 UTC. The schedule scenario's windows are set +#: around 23:00; every other scenario has no schedule, so the date is moot. +T0 = datetime(2026, 1, 5, 22, 59, 30, tzinfo=timezone.utc).timestamp() + +#: Loop passes allowed without the clock moving before the run is called a +#: spin. run() must sleep somewhere on every few passes. +SPIN_LIMIT = 500 + + +class StopRun(BaseException): + """Ends a harness run. A BaseException so run()'s handlers pass it on.""" + + +class SpinError(BaseException): + """run() went round SPIN_LIMIT times without the clock moving. + + A BaseException for the same reason as StopRun: run() would log and + swallow anything less, and the test would see a short trace.""" + + +# --------------------------------------------------------------------------- +# Clock +# --------------------------------------------------------------------------- + +class FakeClock: + """time.time/monotonic/perf_counter all read ``now``; sleep() advances it. + + Alarms are (time, callback) pairs fired, in time order, by the sleep that + carries the clock past them. Reaching the horizon raises StopRun. + """ + + def __init__(self, start: float, horizon: float): + self.start = start + self.now = start + self.horizon = start + horizon + self._alarms: List[Tuple[float, int, Callable[[], None]]] = [] + self._seq = 0 + self.passes_since_advance = 0 + + def rel(self) -> float: + return self.now - self.start + + def at(self, t: float, callback: Callable[[], None]) -> None: + self._alarms.append((self.start + t, self._seq, callback)) + self._seq += 1 + self._alarms.sort() + + def time(self) -> float: + return self.now + + def sleep(self, seconds: float) -> None: + target = self.now + max(0.0, seconds) + while self._alarms and self._alarms[0][0] <= target: + when, _, callback = self._alarms.pop(0) + self.now = max(self.now, when) + callback() + self.now = target + if seconds > 0: + self.passes_since_advance = 0 + if self.now >= self.horizon: + raise StopRun() + + def time_module(self) -> SimpleNamespace: + return SimpleNamespace(time=self.time, monotonic=self.time, + perf_counter=self.time, sleep=self.sleep) + + def datetime_class(self): + clock = self + + class FakeDateTime(datetime): + @classmethod + def now(cls, tz=None): # type: ignore[override] + return datetime.fromtimestamp(clock.now, tz or timezone.utc) + + return FakeDateTime + + +# --------------------------------------------------------------------------- +# Fakes +# --------------------------------------------------------------------------- + +class FakeCache: + """The in-memory slice of CacheManager that run() and its helpers use.""" + + def __init__(self): + self.data: Dict[str, Any] = {} + self.cache_dir = "/nonexistent/run-loop-harness" + + def get(self, key, max_age=None, memory_ttl=None): + return self.data.get(key) + + def set(self, key, data, ttl=None): + self.data[key] = data + + def delete(self, key): + self.data.pop(key, None) + + def clear_cache(self, key=None): + if key is None: + self.data.clear() + else: + self.data.pop(key, None) + + def __getattr__(self, name): + # Anything else (stats, cleanup hooks) is a no-op. + return lambda *a, **k: None + + +class FakeConfigService: + def __init__(self, config): + self.config = config + + def get_config(self): + return self.config + + def subscribe(self, *a, **k): + pass + + def unsubscribe(self, *a, **k): + pass + + def shutdown(self): + pass + + +class FakeSync: + """A standalone sync manager whose follower state follows the script.""" + + role = SyncRole.STANDALONE + + def __init__(self, harness: "RunLoopHarness"): + self._h = harness + self.follower_windows: List[Tuple[float, float]] = [] + + def is_follower_active(self) -> bool: + t = self._h.clock.rel() + return any(a <= t < b for a, b in self.follower_windows) + + def get_latest_scroll_x(self): + return None + + def get_latest_frame(self): + return "leader-frame" + + def stop(self): + pass + + def __getattr__(self, name): + return lambda *a, **k: None + + +class FakeHealthTracker: + """Circuit breaker stand-in: opens after two consecutive failures and + stays open (no wall-clock cooldown, which would not be deterministic).""" + + def __init__(self, harness: "RunLoopHarness"): + self._h = harness + self.failures: Dict[str, int] = {} + + def should_skip_plugin(self, plugin_id): + skip = self.failures.get(plugin_id, 0) >= 2 + if skip: + self._h.log("breaker-open", plugin_id, quiet=True) + return skip + + def record_success(self, plugin_id): + self.failures[plugin_id] = 0 + + def record_failure(self, plugin_id, exc=None): + self.failures[plugin_id] = self.failures.get(plugin_id, 0) + 1 + self._h.log("health-failure", plugin_id) + + +class FakePluginManager: + def __init__(self): + self.plugins: Dict[str, Any] = {} + self.plugin_manifests: Dict[str, Any] = {} + self.plugin_last_update: Dict[str, float] = {} + self.health_tracker = None + self.resource_monitor = None + self.state_manager = None + self.plugin_executor = PluginExecutor() + self.no_lock: set = set() + self._locks: Dict[str, threading.Lock] = {} + self.hangs: List[str] = [] + + def discover_plugins(self): + return [] + + def discovered_plugin_ids(self): + return set(self.plugins) + + def load_plugin(self, plugin_id, force_enabled=False): + return False + + def get_plugin(self, plugin_id): + return self.plugins.get(plugin_id) + + def unload_plugin(self, plugin_id): + self.plugins.pop(plugin_id, None) + return True + + def get_plugin_lock(self, plugin_id): + if plugin_id in self.no_lock: + return None # as when loading failed part-way + return self._locks.setdefault(plugin_id, threading.Lock()) + + def record_display_hang(self, plugin_id, seconds): + self.hangs.append(plugin_id) + + def note_display_duration(self, plugin_id, seconds): + pass + + def run_scheduled_updates(self): + pass + + def run_scheduled_updates_with_changes(self): + return [] + + def stop_update_worker(self): + pass + + +class FakePlugin: + """A plugin whose answers are functions of the harness clock. + + Args: + plugin_id: The plugin id. + modes: Its display modes, registered in this order. + duration: get_display_duration(). + content: ``content(t, mode) -> bool``: what display() returns. + Defaults to always True. + live: ``(start, end)`` seconds during which has_live_content() is + True; get_live_modes() then names its modes ending in ``_live``. + live_priority: has_live_priority(). + dynamic: Enables dynamic duration. Keys: ``cap`` (the plugin's cap), + ``cycle`` (get_cycle_duration()), ``complete_after`` (seconds + after reset_cycle_state() that is_cycle_complete() turns True; + None means never). + needs_high_fps / enable_scrolling: Set as attributes only when given, + since run() tests for their presence. + raises: display() raises RuntimeError. + first_frame_only: display() returns True on a screen's first frame + and False on every later one. + """ + + def __init__(self, plugin_id: str, modes: List[str], duration: float = 30, + content: Optional[Callable[[float, str], bool]] = None, + live: Optional[Tuple[float, float]] = None, + live_priority: bool = False, + dynamic: Optional[Dict[str, Any]] = None, + needs_high_fps: Optional[bool] = None, + enable_scrolling: Optional[bool] = None, + raises: bool = False, + first_frame_only: bool = False): + self.plugin_id = plugin_id + self.modes = list(modes) + self.duration = duration + self.content = content + self.live = live + self.live_priority = live_priority + self.dynamic = dynamic + self.raises = raises + self.first_frame_only = first_frame_only + if needs_high_fps is not None: + self.needs_high_fps = needs_high_fps + if enable_scrolling is not None: + self.enable_scrolling = enable_scrolling + self._h: Optional["RunLoopHarness"] = None + self._reset_at: Optional[float] = None + + # -- display ----------------------------------------------------------- + def display(self, display_mode=None, force_clear=False): + assert self._h is not None + return self._h.on_display(self, display_mode or self.modes[0], force_clear) + + def get_display_duration(self): + return self.duration + + # -- live -------------------------------------------------------------- + def _is_live(self) -> bool: + if not self.live or self._h is None: + return False + t = self._h.clock.rel() + return self.live[0] <= t < self.live[1] + + def has_live_priority(self): + return self.live_priority + + def has_live_content(self): + return self._is_live() + + def get_live_modes(self): + return [m for m in self.modes if m.endswith("_live")] + + # -- dynamic duration ---------------------------------------------------- + def supports_dynamic_duration(self): + return bool(self.dynamic) + + def get_dynamic_duration_cap(self): + return (self.dynamic or {}).get("cap") + + def get_cycle_duration(self, display_mode=None): + return (self.dynamic or {}).get("cycle") + + def reset_cycle_state(self): + assert self._h is not None + self._reset_at = self._h.clock.rel() + self._h.log("cycle-reset", self.plugin_id) + + def is_cycle_complete(self): + if not self.dynamic: + return True + after = self.dynamic.get("complete_after") + if after is None or self._reset_at is None or self._h is None: + return False + done = self._h.clock.rel() - self._reset_at >= after + if done: + self._h.log("cycle-complete", self.plugin_id, quiet=True) + return done + + +class LegacyFakePlugin(FakePlugin): + """display() without a display_mode parameter, as older plugins have.""" + + def display(self, force_clear=False): # type: ignore[override] + assert self._h is not None + return self._h.on_display(self, self.modes[0], force_clear) + + +class FakeVegas: + """The coordinator contract DisplayController relies on, nothing more. + + run_iteration() renders frames at 125 Hz on the fake clock for + ``cycle`` seconds and returns True, or returns False as soon as the + interrupt checker (every 10 frames) or the live-priority checker (every + 0.25 s) asks it to yield -- the same cadence the real coordinator uses. + A live-priority pause is lifted by the next call, as in the real one. + """ + + FRAME = 1.0 / 125 + INTERRUPT_EVERY = 10 + LIVE_EVERY = 0.25 + + def __init__(self, harness: "RunLoopHarness", cycle: float = 30.0, + live_in_ticker: bool = False): + self._h = harness + self.cycle = cycle + self.is_enabled = True + self.vegas_config = SimpleNamespace(live_in_ticker=live_in_ticker) + self.render_pipeline = None + self._interrupt: Optional[Callable[[], bool]] = None + self._live: Optional[Callable[[], Any]] = None + self._paused_for_live = False + + def set_live_priority_checker(self, fn): + self._live = fn + + def set_interrupt_checker(self, fn, check_interval=10): + self._interrupt = fn + + def apply_pending_config_if_idle(self): + pass + + def cleanup(self): + pass + + def run_iteration(self) -> bool: + h = self._h + clock = h.clock + if self._paused_for_live: + self._paused_for_live = False + h.log("vegas-start", None, quiet=True) + start = clock.now + last_live = None + frames = 0 + while True: + now = clock.now + if (self._live and not self.vegas_config.live_in_ticker + and (last_live is None or now - last_live >= self.LIVE_EVERY)): + last_live = now + if self._live(): + self._paused_for_live = True + h.log("vegas-live") + return False + h.log("vegas-frame", None, quiet=True) + clock.sleep(self.FRAME) + frames += 1 + if self._interrupt and frames % self.INTERRUPT_EVERY == 0 and self._interrupt(): + h.log("vegas-interrupt") + return False + if clock.now - start >= self.cycle: + return True + + +# --------------------------------------------------------------------------- +# Harness +# --------------------------------------------------------------------------- + +#: Events that can end a screen, as they appear in the trace. +REASON_EVENTS = { + "schedule-off", "schedule-on", "live", "live-ended", "on-demand-start", + "on-demand-requested-stop", "on-demand-expired", + "on-demand-no-modes-available", "vegas-live", "vegas-interrupt", + "cycle-complete", "display-false", +} + +_SEGMENT_FOR = { + "follower-frame": "", + "vegas-frame": "", + "wifi": "", + "blank": "", +} + + +class RunLoopHarness: + """Build a DisplayController on fakes, run it, and return its trace.""" + + def __init__(self, tmp_path: Path, horizon: float): + self.clock = FakeClock(T0, horizon) + self.events: List[Tuple[float, str, Any, Dict[str, Any]]] = [] + self.tmp_path = tmp_path + # The controller keeps this very dict as self.config, so a scenario + # can edit what run() reads live (durations, schedules). Values + # __init__ copies out (global_dynamic_config) are set on the + # controller instead. + self.config: Dict[str, Any] = { + "timezone": "UTC", + "display": {"hardware": {"brightness": 90}}, + } + self.cache = FakeCache() + self.pm = FakePluginManager() + self.sync = FakeSync(self) + self.dm = self._display_manager() + self._displayed_this_pass = False + self.controller = self._build() + + # -- event log ----------------------------------------------------------- + def log(self, kind: str, subject: Any = None, quiet: bool = False, **data): + data["quiet"] = quiet + self.events.append((round(self.clock.rel(), 3), kind, subject, data)) + + def on_display(self, plugin: FakePlugin, mode: str, force_clear: bool): + first = not self._displayed_this_pass + self._displayed_this_pass = True + if plugin.raises: + self.log("first" if first else "frame", mode, quiet=True, + clear=bool(force_clear), result="raised") + raise RuntimeError(f"{plugin.plugin_id} display() failed") + if plugin.first_frame_only: + result = first + elif plugin.content is None: + result = True + else: + result = bool(plugin.content(self.clock.rel(), mode)) + self.log("first" if first else "frame", mode, quiet=True, + clear=bool(force_clear), result=result) + return result + + # -- construction ---------------------------------------------------------- + def _display_manager(self): + dm = MagicMock(name="DisplayManager") + dm.width = 128 + dm.height = 32 + dm._sync_render_allowed = False + dm.set_brightness = MagicMock(side_effect=self._on_set_brightness) + dm.update_display = MagicMock(side_effect=self._on_update_display) + dm.get_font_height = MagicMock(return_value=8) + return dm + + def _on_set_brightness(self, value): + self.log("brightness", value) + return True + + def _on_update_display(self): + if getattr(self.dm, "_sync_render_allowed", False): + self.log("follower-frame", None, quiet=True) + elif not self.controller.is_display_active: + self.log("blank", None, quiet=True) + + def _build(self): + from src import display_controller as dc_mod + + clock = self.clock + env = {"LEDMATRIX_HOT_RELOAD": "false", "EMULATOR": "true"} + with patch.dict(os.environ, env), \ + patch.object(dc_mod, "time", clock.time_module()), \ + patch.object(dc_mod, "datetime", clock.datetime_class()), \ + patch.object(dc_mod, "ConfigManager", MagicMock()), \ + patch.object(dc_mod, "ConfigService", lambda **kw: FakeConfigService(self.config)), \ + patch.object(dc_mod, "CacheManager", lambda: self.cache), \ + patch.object(dc_mod, "DisplayManager", lambda config: self.dm), \ + patch.object(dc_mod, "FontManager", MagicMock()), \ + patch.object(dc_mod, "DisplaySyncManager", lambda **kw: self.sync), \ + patch("src.plugin_system.PluginManager", lambda **kw: self.pm), \ + patch("src.error_aggregator.start_error_snapshot_publisher", lambda cm: None), \ + patch("src.font_usage.start_font_usage_publisher", lambda *a, **k: None), \ + patch("src.plugin_system.plugin_runtime.start_plugin_runtime_publisher", + lambda *a, **k: None), \ + patch("src.auto_update_setup.ensure_update_helper", lambda config: None): + controller = dc_mod.DisplayController() + + # __init__ wires real health/resource monitors; swap in the fake + # breaker so failures and skips are deterministic. + self.pm.health_tracker = FakeHealthTracker(self) + self.pm.resource_monitor = None + controller.wifi_status_file = self.tmp_path / "wifi_status.json" + self._instrument(controller) + return controller + + def _instrument(self, dc) -> None: + """Log the controller's decisions without changing any of them. + + Each wrapper calls straight through to the real method; only methods + that exist both before and after the stage-1 extraction are wrapped, + so the same harness records the same trace from either. + """ + h = self + + def wrap(name, before, after): + real = getattr(dc, name) + + def wrapper(*args, **kwargs): + token = before(*args, **kwargs) + result = real(*args, **kwargs) + after(token, *args, **kwargs) + return result + setattr(dc, name, wrapper) + + wrap("_evaluate_schedule", + lambda: dc.is_display_active, + lambda was: (h.log("schedule-off") if was and not dc.is_display_active + else h.log("schedule-on") if not was and dc.is_display_active + else None)) + wrap("_activate_on_demand", + lambda request: None, + lambda _, request: h.log("on-demand-start", request.get("plugin_id")) + if dc.on_demand_active else h.log("on-demand-error", dc.on_demand_last_error)) + wrap("_clear_on_demand", + lambda reason=None: dc.on_demand_active, + lambda was, reason=None: h.log(f"on-demand-{reason}") if was else None) + wrap("_apply_live_priority", + lambda mode: dc.current_display_mode, + lambda prev, mode: (None if dc.current_display_mode == prev + else h.log("live" if mode else "live-ended", + dc.current_display_mode))) + real_note = dc._note_empty_pass + + def note_empty_pass(): + h.log("empty", dc.current_display_mode, quiet=True) + return real_note() + dc._note_empty_pass = note_empty_pass + + real_wifi = dc._display_wifi_status_message + + def display_wifi(status): + shown = real_wifi(status) + if shown: + h.log("wifi", status.get("message"), quiet=True) + return shown + dc._display_wifi_status_message = display_wifi + + # -- scenario setup ------------------------------------------------------ + def add_plugin(self, plugin: FakePlugin, lock: bool = True) -> FakePlugin: + """Register a plugin the way _register_loaded_plugin leaves things.""" + dc = self.controller + plugin._h = self + self.pm.plugins[plugin.plugin_id] = plugin + if not lock: + self.pm.no_lock.add(plugin.plugin_id) + dc.plugin_display_modes[plugin.plugin_id] = list(plugin.modes) + for mode in plugin.modes: + if mode not in dc.available_modes: + dc.available_modes.append(mode) + dc.plugin_modes[mode] = plugin + dc.mode_to_plugin_id[mode] = plugin.plugin_id + return plugin + + def add_mode_without_plugin(self, mode: str) -> None: + self.controller.available_modes.append(mode) + + def on_demand_request(self, t: float, request_id: str, action: str = "start", **fields): + def post(): + self.log("request", f"{action}:{request_id}") + self.cache.set("display_on_demand_request", + {"request_id": request_id, "action": action, **fields}) + self.clock.at(t, post) + + def restore_on_demand(self, plugin_id: str, mode: Optional[str] = None, + duration: Optional[float] = None, pinned: bool = False): + """Start with an on-demand session resumed from the cache, as after + a restart: the state _select_startup_plugins restores, then + _populate_on_demand_modes_from_plugin, as __init__ calls it.""" + dc = self.controller + dc.on_demand_active = True + dc.on_demand_plugin_id = plugin_id + dc.on_demand_mode = mode + dc.on_demand_duration = duration + dc.on_demand_pinned = pinned + dc.on_demand_requested_at = self.clock.now + dc.on_demand_expires_at = self.clock.now + duration if duration else None + dc.on_demand_status = 'active' + dc.on_demand_schedule_override = True + dc._populate_on_demand_modes_from_plugin() + + def wifi_message(self, t: float, message: str, duration: float = 5): + def write(): + self.log("wifi-file", message) + self.controller.wifi_status_file.write_text(json.dumps( + {"message": message, "timestamp": self.clock.now, "duration": duration}), + encoding="utf-8") + self.clock.at(t, write) + + def enable_vegas(self, cycle: float = 30.0, live_in_ticker: bool = False) -> FakeVegas: + """Install FakeVegas, wired up as _initialize_vegas_mode wires the real one.""" + dc = self.controller + vegas = FakeVegas(self, cycle=cycle, live_in_ticker=live_in_ticker) + vegas.set_live_priority_checker(dc._check_live_priority) + vegas.set_interrupt_checker( + lambda: dc._check_vegas_interrupt() or dc.sync_manager.is_follower_active(), + check_interval=10) + dc.vegas_coordinator = vegas + return vegas + + # -- running ------------------------------------------------------------- + def run(self) -> Dict[str, Any]: + from src import display_controller as dc_mod + from src import display_watchdog + + clock = self.clock + watchdog = display_watchdog.watchdog + real_loop_pass = watchdog.loop_pass + + def loop_pass(): + self._displayed_this_pass = False + self.log("pass", None, quiet=True) + clock.passes_since_advance += 1 + if clock.passes_since_advance > SPIN_LIMIT: + raise SpinError(f"run() spun {SPIN_LIMIT} passes at t={clock.rel():.3f}") + return real_loop_pass() + + with patch.object(dc_mod, "time", clock.time_module()), \ + patch.object(dc_mod, "datetime", clock.datetime_class()), \ + patch.object(watchdog, "loop_pass", loop_pass): + try: + self.controller.run() + except StopRun: + pass + else: + # run() only returns after catching something itself. + raise AssertionError( + f"run() returned at t={clock.rel():.3f} before the horizon") + return reduce_trace(self.events, round(clock.horizon - clock.start, 3)) + + +def reduce_trace(events, horizon: float) -> Dict[str, Any]: + """Fold the event log into screens and the notable events.""" + screens: List[Dict[str, Any]] = [] + notable: List[List[Any]] = [] + cur: Optional[Dict[str, Any]] = None + # What happened in the current loop pass, for attributing an empty pass. + shown_this_pass = False + failed_this_pass = False + breaker_this_pass = False + + def start(t, mode, clear=None): + nonlocal cur + cur = {"t": t, "mode": mode, "frames": 0, "clear": clear, "exit": None} + screens.append(cur) + + for t, kind, subject, data in events: + if not data.get("quiet"): + notable.append([t, kind] + ([subject] if subject is not None else [])) + if kind == "pass": + shown_this_pass = failed_this_pass = breaker_this_pass = False + elif kind in ("first", "frame"): + if kind == "first" or cur is None: + start(t, subject, data["clear"]) + shown_this_pass = True + cur["result"] = data["result"] + cur["frames"] += 1 + if kind == "frame" and data["result"] is False and cur["exit"] is None: + cur["exit"] = "display-false" + elif kind in _SEGMENT_FOR: + segment = _SEGMENT_FOR[kind] + if cur is None or cur["mode"] != segment or cur["exit"] is not None: + start(t, segment) + cur["frames"] += 1 + elif kind == "vegas-start": + start(t, "") + elif kind == "health-failure": + failed_this_pass = True + elif kind == "breaker-open": + breaker_this_pass = True + elif kind == "empty": + if shown_this_pass and cur is not None and cur["exit"] is None: + # display() ran and had nothing (False) or raised. + cur["exit"] = "raised" if cur.get("result") == "raised" else "empty" + else: + # Never reached display(): no plugin, the breaker is open, or + # the dispatch itself raised. + start(t, subject) + cur["exit"] = ("error" if failed_this_pass + else "breaker" if breaker_this_pass else "no-plugin") + elif kind in REASON_EVENTS and cur is not None and cur["exit"] is None: + cur["exit"] = kind + + rows = [] + for i, screen in enumerate(screens): + end = screens[i + 1]["t"] if i + 1 < len(screens) else horizon + exit_reason = screen["exit"] or ("horizon" if i + 1 == len(screens) else "duration") + rows.append([screen["t"], screen["mode"], round(end - screen["t"], 3), + exit_reason, screen["frames"], screen["clear"]]) + return {"screens": rows, "events": notable} + + +# --------------------------------------------------------------------------- +# Golden files +# --------------------------------------------------------------------------- + +def dump_golden(trace: Dict[str, Any]) -> str: + """One screen or event per line, so a diff points at the row that moved.""" + def block(name, rows, last=False): + end = "" if last else "," + if not rows: + return [f' "{name}": []{end}'] + return [f' "{name}": [', + ",\n".join(" " + json.dumps(row) for row in rows), + f" ]{end}"] + + lines = (["{"] + block("screens", trace["screens"]) + + block("events", trace["events"], last=True) + ["}"]) + return "\n".join(lines) + "\n" + + +def check_golden(name: str, trace: Dict[str, Any]) -> None: + """Compare against test/fixtures/run_loop_golden/.json. + + LEDMATRIX_REGEN_GOLDEN=1 rewrites the file instead. Only do that for a + deliberate behaviour change, and say why in the commit. + """ + path = GOLDEN_DIR / f"{name}.json" + text = dump_golden(trace) + if os.environ.get("LEDMATRIX_REGEN_GOLDEN") == "1": + GOLDEN_DIR.mkdir(parents=True, exist_ok=True) + path.write_text(text, encoding="utf-8", newline="\n") + return + assert path.exists(), f"no golden trace {path}; run with LEDMATRIX_REGEN_GOLDEN=1" + expected = json.loads(path.read_text(encoding="utf-8")) + actual = json.loads(text) + if actual != expected: + import difflib + diff = "\n".join(difflib.unified_diff( + dump_golden(expected).splitlines(), text.splitlines(), + "golden", "actual", lineterm="", n=2)) + raise AssertionError(f"run() trace for {name!r} changed:\n{diff}") diff --git a/test/fixtures/run_loop_golden/all_empty.json b/test/fixtures/run_loop_golden/all_empty.json new file mode 100644 index 00000000..d4772989 --- /dev/null +++ b/test/fixtures/run_loop_golden/all_empty.json @@ -0,0 +1,14 @@ +{ + "screens": [ + [0.0, "a", 0.0, "empty", 1, false], + [0.0, "b", 0.0, "empty", 1, true], + [0.0, "c", 1.0, "empty", 1, true], + [1.0, "a", 1.0, "empty", 1, true], + [2.0, "b", 1.0, "empty", 1, true], + [3.0, "c", 1.0, "empty", 1, true], + [4.0, "a", 1.0, "empty", 1, true], + [5.0, "b", 1.0, "empty", 1, true], + [6.0, "c", 6.0, "horizon", 6, true] + ], + "events": [] +} diff --git a/test/fixtures/run_loop_golden/dynamic_duration.json b/test/fixtures/run_loop_golden/dynamic_duration.json new file mode 100644 index 00000000..25e92e8a --- /dev/null +++ b/test/fixtures/run_loop_golden/dynamic_duration.json @@ -0,0 +1,24 @@ +{ + "screens": [ + [0.0, "scroller", 20.008, "cycle-complete", 2502, false], + [20.008, "news", 40.0, "duration", 40, true], + [60.008, "board", 11.0, "cycle-complete", 12, true], + [71.008, "clock", 10.0, "duration", 10, true], + [81.008, "scroller", 20.007, "cycle-complete", 2502, true], + [101.015, "news", 40.0, "duration", 40, true], + [141.015, "board", 11.0, "cycle-complete", 12, true], + [152.015, "clock", 10.0, "duration", 10, true], + [162.015, "scroller", 20.008, "cycle-complete", 2502, true], + [182.023, "news", 37.977, "horizon", 38, true] + ], + "events": [ + [0.0, "cycle-reset", "scroller"], + [20.008, "cycle-reset", "news"], + [60.008, "cycle-reset", "board"], + [81.008, "cycle-reset", "scroller"], + [101.015, "cycle-reset", "news"], + [141.015, "cycle-reset", "board"], + [162.015, "cycle-reset", "scroller"], + [182.023, "cycle-reset", "news"] + ] +} diff --git a/test/fixtures/run_loop_golden/empty_modes.json b/test/fixtures/run_loop_golden/empty_modes.json new file mode 100644 index 00000000..2735ee02 --- /dev/null +++ b/test/fixtures/run_loop_golden/empty_modes.json @@ -0,0 +1,22 @@ +{ + "screens": [ + [0.0, "clock", 10.0, "duration", 10, false], + [10.0, "empty", 0.0, "empty", 1, true], + [10.0, "ghost", 0.0, "no-plugin", 0, null], + [10.0, "flaky", 12.0, "display-false", 2, true], + [22.0, "clock", 10.0, "duration", 10, true], + [32.0, "empty", 0.0, "empty", 1, true], + [32.0, "ghost", 0.0, "no-plugin", 0, null], + [32.0, "flaky", 12.0, "display-false", 2, true], + [44.0, "clock", 10.0, "duration", 10, true], + [54.0, "empty", 0.0, "empty", 1, true], + [54.0, "ghost", 0.0, "no-plugin", 0, null], + [54.0, "flaky", 12.0, "display-false", 2, true], + [66.0, "clock", 10.0, "duration", 10, true], + [76.0, "empty", 0.0, "empty", 1, true], + [76.0, "ghost", 0.0, "no-plugin", 0, null], + [76.0, "flaky", 12.0, "display-false", 2, true], + [88.0, "clock", 2.0, "horizon", 2, true] + ], + "events": [] +} diff --git a/test/fixtures/run_loop_golden/follower.json b/test/fixtures/run_loop_golden/follower.json new file mode 100644 index 00000000..89123c33 --- /dev/null +++ b/test/fixtures/run_loop_golden/follower.json @@ -0,0 +1,10 @@ +{ + "screens": [ + [0.0, "clock", 20.0, "duration", 20, false], + [20.0, "weather", 20.0, "duration", 20, true], + [40.0, "", 10.017, "duration", 601, null], + [50.017, "clock", 20.0, "duration", 20, true], + [70.017, "weather", 9.983, "horizon", 10, true] + ], + "events": [] +} diff --git a/test/fixtures/run_loop_golden/live_priority.json b/test/fixtures/run_loop_golden/live_priority.json new file mode 100644 index 00000000..301ca37b --- /dev/null +++ b/test/fixtures/run_loop_golden/live_priority.json @@ -0,0 +1,19 @@ +{ + "screens": [ + [0.0, "clock", 20.0, "duration", 20, false], + [20.0, "weather", 20.0, "duration", 20, true], + [40.0, "sports_recent", 20.0, "live", 20, true], + [60.0, "sports_live", 20.0, "duration", 20, true], + [80.0, "sports_live", 20.0, "duration", 20, false], + [100.0, "sports_live", 20.0, "display-false", 11, false], + [120.0, "sports_recent", 20.0, "duration", 20, true], + [140.0, "sports_live", 0.0, "empty", 1, true], + [140.0, "clock", 20.0, "duration", 20, true], + [160.0, "weather", 20.0, "duration", 20, true], + [180.0, "sports_recent", 20.0, "horizon", 20, true] + ], + "events": [ + [60.0, "live", "sports_live"], + [120.0, "live-ended", "sports_recent"] + ] +} diff --git a/test/fixtures/run_loop_golden/live_round_robin.json b/test/fixtures/run_loop_golden/live_round_robin.json new file mode 100644 index 00000000..250283af --- /dev/null +++ b/test/fixtures/run_loop_golden/live_round_robin.json @@ -0,0 +1,20 @@ +{ + "screens": [ + [0.0, "nfl_live", 15.0, "duration", 15, true], + [15.0, "nfl_live", 15.0, "live", 15, false], + [30.0, "nhl_live", 15.0, "live", 15, true], + [45.0, "nfl_live", 15.0, "live", 15, true], + [60.0, "nhl_live", 15.0, "duration", 15, true], + [75.0, "nhl_live", 15.0, "duration", 15, false], + [90.0, "nhl_live", 15.0, "duration", 15, false], + [105.0, "clock", 15.0, "duration", 15, true], + [120.0, "nfl_live", 15.0, "duration", 15, true], + [135.0, "nhl_live", 15.0, "horizon", 15, true] + ], + "events": [ + [0.0, "live", "nfl_live"], + [30.0, "live", "nhl_live"], + [45.0, "live", "nfl_live"], + [60.0, "live", "nhl_live"] + ] +} diff --git a/test/fixtures/run_loop_golden/on_demand.json b/test/fixtures/run_loop_golden/on_demand.json new file mode 100644 index 00000000..34947fcb --- /dev/null +++ b/test/fixtures/run_loop_golden/on_demand.json @@ -0,0 +1,30 @@ +{ + "screens": [ + [0.0, "clock", 20.0, "duration", 20, false], + [20.0, "weather", 5.0, "on-demand-start", 6, true], + [25.0, "sports_recent", 15.0, "duration", 15, true], + [40.0, "sports_upcoming", 15.0, "duration", 15, true], + [55.0, "sports_recent", 15.0, "duration", 15, true], + [70.0, "sports_upcoming", 15.0, "duration", 15, true], + [85.0, "sports_recent", 10.0, "on-demand-requested-stop", 11, true], + [95.0, "weather", 20.0, "duration", 20, true], + [115.0, "sports_recent", 15.0, "duration", 15, true], + [130.0, "sports_upcoming", 15.0, "duration", 15, true], + [145.0, "clock", 5.0, "on-demand-start", 6, true], + [150.0, "weather", 20.0, "duration", 20, true], + [170.0, "weather", 10.0, "on-demand-expired", 10, true], + [180.0, "clock", 20.0, "duration", 20, true], + [200.0, "weather", 20.0, "duration", 20, true], + [220.0, "sports_recent", 15.0, "duration", 15, true], + [235.0, "sports_upcoming", 5.0, "horizon", 5, true] + ], + "events": [ + [25.0, "request", "start:r1"], + [25.0, "on-demand-start", "sports"], + [95.0, "request", "stop:r2"], + [95.0, "on-demand-requested-stop"], + [150.0, "request", "start:r3"], + [150.0, "on-demand-start", "weather"], + [180.0, "on-demand-expired"] + ] +} diff --git a/test/fixtures/run_loop_golden/on_demand_pinned.json b/test/fixtures/run_loop_golden/on_demand_pinned.json new file mode 100644 index 00000000..c23ee9be --- /dev/null +++ b/test/fixtures/run_loop_golden/on_demand_pinned.json @@ -0,0 +1,29 @@ +{ + "screens": [ + [0.0, "clock", 12.0, "on-demand-start", 13, false], + [12.0, "sports_upcoming", 15.0, "duration", 15, true], + [27.0, "sports_upcoming", 15.0, "duration", 15, true], + [42.0, "sports_upcoming", 15.0, "duration", 15, true], + [57.0, "sports_upcoming", 15.0, "duration", 15, true], + [72.0, "sports_upcoming", 8.0, "on-demand-start", 9, true], + [80.0, "app_a", 0.0, "empty", 1, true], + [80.0, "app_b", 10.0, "duration", 10, true], + [90.0, "app_a", 0.0, "empty", 1, true], + [90.0, "app_b", 10.0, "duration", 10, true], + [100.0, "app_a", 0.0, "empty", 1, true], + [100.0, "app_b", 10.0, "duration", 10, true], + [110.0, "app_a", 0.0, "empty", 1, true], + [110.0, "app_b", 10.0, "on-demand-requested-stop", 10, true], + [120.0, "clock", 20.0, "duration", 20, true], + [140.0, "sports_recent", 15.0, "duration", 15, true], + [155.0, "sports_upcoming", 5.0, "horizon", 5, true] + ], + "events": [ + [12.0, "request", "start:p1"], + [12.0, "on-demand-start", "sports"], + [80.0, "request", "start:p2"], + [80.0, "on-demand-start", "starlark"], + [120.0, "request", "stop:p3"], + [120.0, "on-demand-requested-stop"] + ] +} diff --git a/test/fixtures/run_loop_golden/on_demand_restored.json b/test/fixtures/run_loop_golden/on_demand_restored.json new file mode 100644 index 00000000..fb71735c --- /dev/null +++ b/test/fixtures/run_loop_golden/on_demand_restored.json @@ -0,0 +1,14 @@ +{ + "screens": [ + [0.0, "sports_upcoming", 15.0, "duration", 15, true], + [15.0, "sports_recent", 15.0, "duration", 15, true], + [30.0, "sports_upcoming", 10.0, "on-demand-expired", 10, true], + [40.0, "clock", 20.0, "duration", 20, true], + [60.0, "weather", 20.0, "duration", 20, true], + [80.0, "sports_recent", 15.0, "duration", 15, true], + [95.0, "sports_upcoming", 5.0, "horizon", 5, true] + ], + "events": [ + [40.0, "on-demand-expired"] + ] +} diff --git a/test/fixtures/run_loop_golden/plain_rotation.json b/test/fixtures/run_loop_golden/plain_rotation.json new file mode 100644 index 00000000..d58191ea --- /dev/null +++ b/test/fixtures/run_loop_golden/plain_rotation.json @@ -0,0 +1,17 @@ +{ + "screens": [ + [0.0, "clock", 15.0, "duration", 15, false], + [15.0, "weather_now", 20.0, "duration", 20, true], + [35.0, "weather_forecast", 20.0, "duration", 20, true], + [55.0, "ticker", 10.008, "duration", 1252, true], + [65.008, "legacy", 5.0, "duration", 5, true], + [70.008, "clock", 15.0, "duration", 15, true], + [85.008, "weather_now", 20.0, "duration", 20, true], + [105.008, "weather_forecast", 20.0, "duration", 20, true], + [125.008, "ticker", 10.008, "duration", 1252, true], + [135.016, "legacy", 5.0, "duration", 5, true], + [140.016, "clock", 15.0, "duration", 15, true], + [155.016, "weather_now", 4.984, "horizon", 5, true] + ], + "events": [] +} diff --git a/test/fixtures/run_loop_golden/plugin_error.json b/test/fixtures/run_loop_golden/plugin_error.json new file mode 100644 index 00000000..28ec4a86 --- /dev/null +++ b/test/fixtures/run_loop_golden/plugin_error.json @@ -0,0 +1,27 @@ +{ + "screens": [ + [0.0, "clock", 10.0, "duration", 10, false], + [10.0, "broken_a", 0.0, "error", 0, null], + [10.0, "weather", 10.0, "duration", 10, true], + [20.0, "crashy", 0.0, "raised", 1, true], + [20.0, "clock", 10.0, "duration", 10, true], + [30.0, "broken_a", 0.0, "error", 0, null], + [30.0, "weather", 10.0, "duration", 10, true], + [40.0, "crashy", 0.0, "raised", 1, true], + [40.0, "clock", 10.0, "duration", 10, true], + [50.0, "broken_a", 0.0, "breaker", 0, null], + [50.0, "broken_b", 0.0, "breaker", 0, null], + [50.0, "weather", 10.0, "duration", 10, true], + [60.0, "crashy", 0.0, "raised", 1, true], + [60.0, "clock", 10.0, "duration", 10, true], + [70.0, "broken_a", 0.0, "breaker", 0, null], + [70.0, "broken_b", 0.0, "breaker", 0, null], + [70.0, "weather", 10.0, "duration", 10, true], + [80.0, "crashy", 0.0, "raised", 1, true], + [80.0, "clock", 10.0, "horizon", 10, true] + ], + "events": [ + [10.0, "health-failure", "broken"], + [30.0, "health-failure", "broken"] + ] +} diff --git a/test/fixtures/run_loop_golden/schedule.json b/test/fixtures/run_loop_golden/schedule.json new file mode 100644 index 00000000..e86f0f56 --- /dev/null +++ b/test/fixtures/run_loop_golden/schedule.json @@ -0,0 +1,31 @@ +{ + "screens": [ + [0.0, "clock", 20.0, "duration", 20, false], + [20.0, "weather", 20.0, "duration", 20, true], + [40.0, "clock", 20.0, "duration", 20, true], + [60.0, "weather", 20.0, "duration", 20, true], + [80.0, "clock", 20.0, "duration", 20, true], + [100.0, "weather", 20.0, "duration", 20, true], + [120.0, "clock", 20.0, "duration", 20, true], + [140.0, "weather", 10.0, "schedule-off", 11, true], + [150.0, "", 20.0, "on-demand-start", 2, null], + [170.0, "weather", 20.0, "on-demand-expired", 20, true], + [190.0, "weather", 20.0, "schedule-off", 20, true], + [210.0, "", 120.0, "schedule-on", 2, null], + [330.0, "clock", 20.0, "duration", 20, true], + [350.0, "weather", 20.0, "duration", 20, true], + [370.0, "clock", 20.0, "duration", 20, true], + [390.0, "weather", 10.0, "horizon", 10, true] + ], + "events": [ + [30.0, "brightness", 30], + [150.0, "schedule-off"], + [170.0, "request", "start:s1"], + [170.0, "on-demand-start", "weather"], + [170.0, "schedule-on"], + [170.0, "brightness", 90], + [190.0, "on-demand-expired"], + [210.0, "schedule-off"], + [330.0, "schedule-on"] + ] +} diff --git a/test/fixtures/run_loop_golden/vegas.json b/test/fixtures/run_loop_golden/vegas.json new file mode 100644 index 00000000..468c89f6 --- /dev/null +++ b/test/fixtures/run_loop_golden/vegas.json @@ -0,0 +1,26 @@ +{ + "screens": [ + [0.0, "", 30.008, "duration", 3751, null], + [30.008, "", 30.007, "duration", 3751, null], + [60.015, "", 10.24, "vegas-live", 1280, null], + [70.255, "clock", 20.0, "duration", 20, false], + [90.255, "sports_live", 20.0, "display-false", 11, true], + [110.255, "", 30.008, "duration", 3751, null], + [140.263, "", 10.0, "on-demand-start", 1250, null], + [150.263, "clock", 20.0, "duration", 20, true], + [170.263, "clock", 5.0, "on-demand-expired", 5, true], + [175.263, "", 24.959, "vegas-interrupt", 3120, null], + [200.222, "clock", 20.0, "duration", 20, true], + [220.222, "", 30.008, "duration", 3751, null], + [250.23, "", 9.77, "horizon", 1222, null] + ], + "events": [ + [70.255, "vegas-live"], + [150.0, "request", "start:v1"], + [150.263, "on-demand-start", "clock"], + [150.263, "vegas-interrupt"], + [175.263, "on-demand-expired"], + [200.0, "wifi-file", "Connected to HomeNet"], + [200.222, "vegas-interrupt"] + ] +} diff --git a/test/fixtures/run_loop_golden/vegas_live_in_ticker.json b/test/fixtures/run_loop_golden/vegas_live_in_ticker.json new file mode 100644 index 00000000..10e7b741 --- /dev/null +++ b/test/fixtures/run_loop_golden/vegas_live_in_ticker.json @@ -0,0 +1,9 @@ +{ + "screens": [ + [0.0, "", 30.008, "duration", 3751, null], + [30.008, "", 30.007, "duration", 3751, null], + [60.015, "", 30.008, "duration", 3751, null], + [90.023, "", 9.977, "horizon", 1248, null] + ], + "events": [] +} diff --git a/test/fixtures/run_loop_golden/wifi_notice.json b/test/fixtures/run_loop_golden/wifi_notice.json new file mode 100644 index 00000000..7349b9f7 --- /dev/null +++ b/test/fixtures/run_loop_golden/wifi_notice.json @@ -0,0 +1,19 @@ +{ + "screens": [ + [0.0, "clock", 20.0, "duration", 20, false], + [20.0, "weather", 20.0, "duration", 20, true], + [40.0, "clock", 20.0, "on-demand-start", 20, true], + [60.0, "clock", 20.0, "on-demand-expired", 20, true], + [80.0, "", 15.0, "duration", 30, null], + [95.0, "weather", 20.0, "duration", 20, true], + [115.0, "clock", 20.0, "duration", 20, true], + [135.0, "weather", 15.0, "horizon", 15, true] + ], + "events": [ + [25.0, "wifi-file", "Connected to HomeNet"], + [60.0, "request", "start:w1"], + [60.0, "on-demand-start", "clock"], + [65.0, "wifi-file", "AP mode on"], + [80.0, "on-demand-expired"] + ] +} diff --git a/test/test_run_loop_golden.py b/test/test_run_loop_golden.py new file mode 100644 index 00000000..cf003373 --- /dev/null +++ b/test/test_run_loop_golden.py @@ -0,0 +1,220 @@ +"""Golden traces of DisplayController.run(): what is shown, for how long, and why. + +Each scenario runs the real run() loop against fake plugins on a fake clock +(see test/_run_loop_harness.py) and compares the screens it produced with +test/fixtures/run_loop_golden/.json. A trace row is + + [start_s, mode, duration_s, exit_reason, frames, force_clear_on_first_frame] + +and ``events`` lists what else happened (requests, live changes, schedule, +brightness) with its time. + +These pin down today's behaviour so run() can be restructured into an +Arbiter / ScreenRunner / Sources (docs/RUN_LOOP_REDESIGN.md) without changing +it. A diff here is a behaviour change: if it is intended, regenerate with +LEDMATRIX_REGEN_GOLDEN=1 and explain the change in the commit message. +""" + +import os + +import pytest + +os.environ.setdefault("EMULATOR", "true") + +from test._run_loop_harness import ( # noqa: E402 + FakePlugin, + LegacyFakePlugin, + RunLoopHarness, + check_golden, +) + + +def scenario_plain_rotation(h: RunLoopHarness): + # clock: duration from display_durations, which beats the plugin's own. + # weather: the plugin's own duration. ticker: scrolls, so high-FPS. + # legacy: display() without display_mode. + h.config["display"]["display_durations"] = {"clock": 15} + h.add_plugin(FakePlugin("clock", ["clock"], duration=99)) + h.add_plugin(FakePlugin("weather", ["weather_now", "weather_forecast"], duration=20)) + h.add_plugin(FakePlugin("ticker", ["ticker"], duration=10, enable_scrolling=True)) + h.add_plugin(LegacyFakePlugin("legacy", ["legacy"], duration=5)) + + +def scenario_empty_modes(h: RunLoopHarness): + # empty: never has content, skipped at once. ghost: a mode with no + # plugin behind it. flaky: content on the first frame only, so the + # 1 s loop breaks early and the dwell is made up by sleeping. + h.add_plugin(FakePlugin("clock", ["clock"], duration=10)) + h.add_plugin(FakePlugin("empty", ["empty"], duration=10, content=lambda t, m: False)) + h.add_mode_without_plugin("ghost") + h.add_plugin(FakePlugin("flaky", ["flaky"], duration=12, first_frame_only=True)) + + +def scenario_all_empty(h: RunLoopHarness): + # Nothing to show anywhere: one rotation of empty passes, then a 1 s + # pause per pass instead of a spin. + h.add_plugin(FakePlugin("a", ["a"], content=lambda t, m: False)) + h.add_plugin(FakePlugin("b", ["b"], content=lambda t, m: False)) + h.add_plugin(FakePlugin("c", ["c"], content=lambda t, m: t >= 6)) + + +def scenario_plugin_error(h: RunLoopHarness): + # broken's dispatch raises (no display lock: loading failed part-way), + # so all its modes are skipped together; two failures open the breaker. + # crashy's display() raises inside the executor, which reports False: + # an empty pass ("raised"), not a failure, so its modes are not skipped. + h.add_plugin(FakePlugin("clock", ["clock"], duration=10)) + h.add_plugin(FakePlugin("broken", ["broken_a", "broken_b"], duration=10), lock=False) + h.add_plugin(FakePlugin("weather", ["weather"], duration=10)) + h.add_plugin(FakePlugin("crashy", ["crashy"], duration=10, raises=True)) + + +def scenario_dynamic_duration(h: RunLoopHarness): + # Read once at startup, so set where __init__ left it. + h.controller.global_dynamic_config = {"max_duration_seconds": 50} + # scroller: high-FPS, completes its cycle 20 s after each reset. + h.add_plugin(FakePlugin("scroller", ["scroller"], duration=10, needs_high_fps=True, + dynamic={"cap": None, "complete_after": 20})) + # news: 1 s loop, asks for 45 s but its own cap is 40; never completes. + h.add_plugin(FakePlugin("news", ["news"], duration=10, + dynamic={"cap": 40, "cycle": 45, "complete_after": None})) + # board: no cap of its own, so the global 50 s applies; done after 5 s, + # but the 10 s minimum (+0.5 s grace) holds it. + h.add_plugin(FakePlugin("board", ["board"], duration=10, + dynamic={"cap": None, "complete_after": 5})) + h.add_plugin(FakePlugin("clock", ["clock"], duration=10)) + + +def scenario_live_priority(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=20)) + h.add_plugin(FakePlugin( + "sports", ["sports_recent", "sports_live"], duration=20, + live=(50, 110), live_priority=True, + content=lambda t, mode: mode != "sports_live" or 50 <= t < 110)) + + +def scenario_live_round_robin(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=15)) + h.add_plugin(FakePlugin("nfl", ["nfl_live"], duration=15, live=(0, 70), live_priority=True)) + h.add_plugin(FakePlugin("nhl", ["nhl_live"], duration=15, live=(20, 100), live_priority=True)) + + +def scenario_on_demand(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=20)) + h.add_plugin(FakePlugin("sports", ["sports_recent", "sports_upcoming"], duration=15)) + # Mid-way through clock's first screen; then stopped by request. + h.on_demand_request(25, "r1", plugin_id="sports") + h.on_demand_request(95, "r2", action="stop") + # A timed request that expires on its own. + h.on_demand_request(150, "r3", plugin_id="weather", duration=30) + + +def scenario_on_demand_pinned(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("sports", ["sports_recent", "sports_upcoming"], duration=15)) + h.on_demand_request(12, "p1", plugin_id="sports", mode="sports_upcoming", pinned=True) + # An on-demand mode with nothing to show is skipped like any other. + h.add_plugin(FakePlugin("starlark", ["app_a", "app_b"], duration=10, + content=lambda t, mode: mode != "app_a")) + h.on_demand_request(80, "p2", plugin_id="starlark") + h.on_demand_request(120, "p3", action="stop") + + +def scenario_on_demand_restored(h: RunLoopHarness): + # A restart during an on-demand session resumes it: the first screen is + # the saved mode (with a full clear), not the rotation's first mode, and + # the rotation starts from the top once it expires. + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=20)) + h.add_plugin(FakePlugin("sports", ["sports_recent", "sports_upcoming"], duration=15)) + h.restore_on_demand("sports", mode="sports_upcoming", duration=40) + + +def scenario_schedule(h: RunLoopHarness): + # The clock starts at 22:59:30. Off from 23:01 until 23:05 (the window + # spans midnight); dimmed from 23:00 until 23:01. + h.config["schedule"] = {"enabled": True, "start_time": "23:05", "end_time": "23:01"} + h.config["dim_schedule"] = {"enabled": True, "start_time": "23:00", + "end_time": "23:01", "dim_brightness": 30} + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=20)) + # An on-demand request during scheduled downtime overrides it. + h.on_demand_request(170, "s1", plugin_id="weather", duration=20) + + +def scenario_wifi_notice(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=20)) + # Posted mid-screen and expired before the screen ends: never shown, + # because the notice is only checked between screens. + h.wifi_message(25, "Connected to HomeNet", duration=5) + # While on-demand is active the notice waits. + h.on_demand_request(60, "w1", plugin_id="clock", duration=20) + h.wifi_message(65, "AP mode on", duration=30) + + +def scenario_follower(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=20)) + # Only checked at the top of a pass, so it takes over when the screen + # running at t=35 ends, and hands back the pass after it ends. + h.sync.follower_windows = [(35, 50)] + + +def scenario_vegas(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin( + "sports", ["sports_live"], duration=20, live=(70, 100), live_priority=True, + content=lambda t, mode: 70 <= t < 100)) + h.enable_vegas(cycle=30) + # On-demand takes the panel from Vegas mid-iteration, then hands back. + h.on_demand_request(150, "v1", plugin_id="clock", duration=25) + h.wifi_message(200, "Connected to HomeNet", duration=3) + + +def scenario_vegas_live_in_ticker(h: RunLoopHarness): + h.add_plugin(FakePlugin("clock", ["clock"], duration=20)) + h.add_plugin(FakePlugin("sports", ["sports_live"], duration=20, live=(10, 50), + live_priority=True)) + h.enable_vegas(cycle=30, live_in_ticker=True) + + +SCENARIOS = { + "plain_rotation": (scenario_plain_rotation, 160), + "empty_modes": (scenario_empty_modes, 90), + "all_empty": (scenario_all_empty, 12), + "plugin_error": (scenario_plugin_error, 90), + "dynamic_duration": (scenario_dynamic_duration, 220), + "live_priority": (scenario_live_priority, 200), + "live_round_robin": (scenario_live_round_robin, 150), + "on_demand": (scenario_on_demand, 240), + "on_demand_pinned": (scenario_on_demand_pinned, 160), + "on_demand_restored": (scenario_on_demand_restored, 100), + "schedule": (scenario_schedule, 400), + "wifi_notice": (scenario_wifi_notice, 150), + "follower": (scenario_follower, 80), + "vegas": (scenario_vegas, 260), + "vegas_live_in_ticker": (scenario_vegas_live_in_ticker, 100), +} + + +@pytest.mark.parametrize("name", sorted(SCENARIOS)) +def test_run_loop_golden_trace(name, tmp_path): + build, horizon = SCENARIOS[name] + harness = RunLoopHarness(tmp_path, horizon=horizon) + build(harness) + trace = harness.run() + check_golden(name, trace) + + +def test_traces_are_repeatable(tmp_path): + """Two runs of the busiest scenario give the identical trace.""" + traces = [] + for i in range(2): + (tmp_path / str(i)).mkdir() + harness = RunLoopHarness(tmp_path / str(i), horizon=240) + scenario_on_demand(harness) + traces.append(harness.run()) + assert traces[0] == traces[1]