diff --git a/CLAUDE.md b/CLAUDE.md index 4dc7fc92..562fbc4c 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -92,6 +92,11 @@ Terminology: **body / duration** = media playback length (`media.duration` for A - **A stop takes its scheduled chain with it.** `stop`/`pause`/`fade_out` actions call `cancel_pending_descendants`: walks `_target_object` past the target, cancelling every local+enabled cue that has **not** produced output yet (`_revealed`), transitively, stopping at a chain break. A cue already on stage is never touched and the walk continues past it. Each node runs it on its own graph (ActionCues are local everywhere). Cancelled cues also get `remove_cue` — their threads exit through the generation guard, upstream of the normal one. - **Enable/disable mid-pass are honoured.** Nothing downstream re-reads `enabled` once a cue is dispatched, so: disabling a parked cue **cancels** it (`cancel_parked`), and enabling one **rejoins** it (`rejoin_chain`) at the anchor stamped on it when the walk skipped it (`_chain_pass`), dispatched with `unroll=False` so the running chain is not re-dispatched. Refused if its slot already passed (a loud journal line — firing late by surprise is worse), if a STOP ended that pass, or if a stop action already claimed it. - **Auto-follow / auto-pause postwait = an MTC-gated tail after the body**: when `loop_cue` returns, the engine blanks the video (`blank_cue`: `/visible 0`, cue stays armed → STOP-reachable), waits until `body_end + postwait` on the MTC timeline, then ends illumination (`remove_cue`) and — for follow — fires the target via `go_from`. A manual GO during the tail **preempts** the auto-fire. Follow fires at `body_end + postwait`, not at media end. +- **An Auto follow into a cue on another node is relayed** (`cues/FollowRelay.py`, ClickUp 869fc8ytz). Only the nodes where the source is local run it and fire its follow, so a target on another node used to never start, silently. For an **AudioCue or VideoCue** source (ActionCue, FadeCue, CueList and DmxCue are local on every node, so every node already fires their follow) the owning node **announces** the follow instant (`_follow_instant_ms`: the same expression its own fire uses) right after the reveal, or at the start of the last loop for `loop > 1`; never for an endless loop. The controller relays it to every node (`_relay_follow`); the others pre-arm what they would start, wait for the instant on MTC and dispatch it there through `go_from`. If the follow does not happen the owner **cancels**: reason `stop` (stop/pause/fade-out action), `restart` (the source was started again: `go()`'s commit section sends it, the replaced thread notices too late), `error`; nothing for a STOP, a load or the yield, which every node handles itself. A cancel that reaches a target already on stage stops it only within `FOLLOW_CANCEL_GRACE_S` (2 s) and only for `stop`/`restart` -- a cue is never cut for an internal error. + - **Run counter.** The controller's `run_seq` (from the clock) travels in every GO; STOP, load and unload bump it before forwarding. A node records it, and empties its pending follows, in the **receive hook** (`NodeCommunications.set_receive_hook`), i.e. in bus order, before the command threads race for `_command_lock`. Follow messages are applied there too and never take that lock. A message of another run is dropped at the controller and at the node. Between a STOP/load's receipt and the moment the node has run it (`run_command` marks it applied), the node's epochs still belong to the ending run: it announces nothing and reads no epochs for incoming follows until then. + - **`go()` has a `commit_gate`**, evaluated inside the commit section after every other refusal: the follow's dispatch and its cancel are decided in one place. Order inside that section: refusals → gate → restart cancel → assignments. + - **`disarm_if_unchanged`** is the one other place that may disarm a published cue from a background thread (the stopped follow target): it re-checks generation, STOP/load epoch and arm stamp in one `_lock` section and releases the player while holding the cue's **arm claim**. Extend it, don't bypass it (publish-or-abandon contract, 869f9wqpn). + - Version skew: an old controller sends no `run_seq`, so nothing is announced (the bug stays); an old node logs `Command follow not found` for every relayed message. Upgrade the whole cluster together. - `prewait` is applied at exactly one point (`start = arrival + prewait`), never as a wall-clock sleep. The postwait `sleep` in `go_threaded` is **auto-continue only** and no longer paces anything (the chain left at the trigger): it holds the thread past the body when `post > body`, and **it is the sole mechanism producing auto-continue's `prewait + max(body, postwait)` illumination** — `loop_cue` never reads `postwait` and `remove_cue` fires only after it returns — so removing it would silently shorten the highlight to `prewait + body`. Guarded by a test. Cross-cutting invariants: **never auto-stop a running project**; `_reveal_wait` exits on `_stop_requested` (STOP) or a changed `_go_generation` (newer GO/reload) and does **not** bail on a recoverable MTC stall (reveal fires late on resume); anchor comparisons use wrap-accumulated `milliseconds_exact` (24h-safe). See `Plans/postwait-postgo-chain-semantics.md` and `Plans/postwait-engine-only-implementation.md` in the cuems-RELATIONS index repo for the full design/diagnosis. @@ -100,7 +105,8 @@ Cross-cutting invariants: **never auto-stop a running project**; `_reveal_wait` Engine → VideoComposer and engine → DmxPlayer are inter-component protocols documented once in the cuems-RELATIONS CLAUDE.md ("Video/DMX Cue Lifecycle"). The engine side: arm → send load/`/frame` bundle → run (set offset/visible/mtcfollow, or scene bundle) → reveal on MTC. See the videocomposer and dmxplayer CLAUDE.md for the player halves. -- **Audio mixer wiring waits for the player's JACK port** (`AudioMixer.connect_player_to_outputs`, ~15 s `port_exists` loop): a fresh `cuems-audioplayer` does OSC bind + RtMidi + FFmpeg probe before RtAudio registers `outport 0/1`, so connecting immediately after spawn hits jackd "Unknown source port" and the cue plays **green but silent** (2026-07 isil multilingual incident). The function returns success/failure; `new_audio_output` and the GO-time repair in `run_cue` log a loud "will be SILENT" error on failure. +- **Audio mixer wiring waits for the player to report itself started** (`AudioMixer.connect_player_to_outputs`, `ready=Player.ready`, 869fbyjzx). A fresh `cuems-audioplayer` does OSC bind + RtMidi + FFmpeg probe, then registers `outport 0/1` (`openStream`), then RtAudio **auto-connects them to `system:playback_*`** (`startStream`), then finishes its constructor and prints `[OK] RUNNING!` (`main.cpp`); the stdout reader in `Player.call_subprocess` sets `Player.ready` on that line. The wiring waits for it, then disconnects whatever the outports are connected to (the auto-connects) and connects the mixer. Wiring on port visibility alone (before 869fbyjzx) either hit jackd "Unknown source port" (green but **silent**, 2026-07 isil) or ran before the auto-connect, which then stayed: the cue sounded through the mixer **and** straight to the outputs, doubled and outside mixer volume/mute (869fcvz85, ~3.5 % of arms). One 14.5 s budget for the ready wait and the port wait; a dead player ends it; a player that never prints the line is wired on port presence with a WARNING. **At GO** `run_cue._verify_audio_wiring_at_go` checks with `player_connection_diff` (missing + stray edges, one `get_connections` per outport) and repairs **edge by edge** (`repair_player_connections`) — never a full rewire, because a GO can reach a cue that is still playing. Failures log a loud "will be SILENT" error (or "stray edge(s) still connected"). **Known limit:** the arm still takes ~0.47 s cold (0.35 s warm; the player's own start-up), so a GO that reaches the cue sooner than that after its arm began waits and fires LATE (test2, node audio behind another node's pause: second GO at 0.3 s → ~0.2 s late; 0.5 s and later → on time). Only arming **before** the hand-off removes it — **plan B / Part B**, not built: arm the first local segment at load even behind another node's pause and the next after each GO (measured cost ~15 MB per held audio player, ~40 MB GPU per held 1080p layer; or pre-launch players). Deferred because no real show hits it (sala1's node segments are video only); revisit if a venue reports a late node audio cue after a fast double GO. See `Plans/2026-10-06-engine-audio-arm-port-wait.md` (cuems-RELATIONS). +- **Orphan sweeps never abort their caller and see only our own players** (869evtdf7). `kill_orphaned_audio_processes` runs in the middle of `_load_project_inner` and `kill_orphaned_mixer_processes` before the mixer starts; an EPERM from either used to abort the load half-way through its teardown (old project torn down, new one never armed, only `Error executing command callback for load: [Errno 1]`) or leave the node without a mixer. Both now go through module-level helpers in `PlayerHandler.py` (`_orphan_pids`, `_kill_orphan`) that log and go on: EPERM names the PID and its owner, pgrep rc ≥ 2 is a WARNING, not silence. `cleanup_zombie_jack_clients` is guarded the same way, and `run_command` logs a callback failure with its traceback. They match **own-user** processes only (`pgrep -u `), the audioplayer one anchored on argv[0] (`^([^ ]*/)?cuems-audioplayer( |$)`), so an operator's `tail -f …cuems-audioplayer.log` is no longer killed. ⚠ The cleanup now depends on the **binary name**: a configured `audioplayer`/`audiomixer`/`dmxplayer` path with another basename escapes these sweeps **and** the node-engine unit's `pkill` (anchored the same way in cuems-common ≥ 1.3.0-24); only the cgroup kill of a `systemctl restart` remains. `set_players` warns at start when that happens (`check_orphan_binary_names`). See `Plans/2026-10-07-engine-orphan-kill-eperm-aborts-load.md` (cuems-RELATIONS). - **`enable`/`disable` actions arm/disarm their target** via `NodeEngine._action_result_sink` → `_apply_cue_enabled_side_effects` (same helper as the Controller's `cue_enabled` toggle): enable spawns an async `ReArm:` (`_arm_with_enabled_guard` re-checks enabled + project generation after the arm); disable disarms only when the cue is idle — guarded by the `_playing` lifecycle flag (set by `go()`, cleared by `disarm()`/`stop_all_cues()`; `_go_generation` is increment-only and NOT a playing signal). Handlers themselves only flip the flag. Without this, runtime-enabled cues always hit the go()-time fallback re-arm (inline load at GO). CueList targets react on their first enabled child; note CueList children have **no** go()-fallback of their own (run_cueList bypasses `go()`). - **FadeCue duration must be > 0** — invariant enforced at the top of `_build_fade_payload` (`ActionHandler.py`): duration `None`/zero/non-numeric raises `ValueError` → clean `failed` action result at reveal, **before** any OSC dispatch, `record_value` mirror write, or `_start_mtc`/`_end_mtc` stamping. Rationale: parser-built FadeCues bypass the cuemsutils setter, and gradient-motiond silently drops `dur <= 0` on its UDP input — without the guard a zero fade reported "applied" and poisoned the next fade's `start_value` via the mirror. XML load stays lenient on purpose (legacy projects with a zero still load; they fail loudly only at reveal). The editor rejects such durations at save time (cuems-editor `validate_fade_durations_in_contents`). diff --git a/debian/changelog b/debian/changelog index 99232b25..0573aca3 100644 --- a/debian/changelog +++ b/debian/changelog @@ -1,3 +1,32 @@ +cuems-engine (0.1.0rc6-3) bookworm; urgency=medium + + * Merge rc_1 into debian/bookworm: + - 869fa89uh (#23): a play-once video cue no longer wraps to frame 0 at + its end; videocomposer wraparound is enabled only for cues that + repeat. + - 869fc8ytz (#25): an Auto follow into a cue on another node starts + it; the controller relays the follow to the owning node. Every GO + value is now a dict carrying run_seq: the WHOLE CLUSTER must run + this engine (controller and every node). + - 869fbyjzx, 869fcvz85 (#27): an audio player is wired to the mixer + only once it reports RUNNING, so RtAudio's auto-connect to + system:playback_* is always removed (no more doubled audio outside + mixer volume); the GO-time check repairs the wiring edge by edge; + arm-wait log lines say whether a GO waited or fell back. + - 869fedahu (#28): the controller broadcasts each cue's name on the + :9190 channel after every load (/engine/status/cue_name/) and + replays it to late clients. Additive; older UIs ignore it. + - 869evtdf7 (#29): orphan sweeps never abort a project load. An + orphaned player the node could not kill (EPERM) used to abort the + load after the old project was torn down; both sweeps and the zombie + JACK client cleanup now log and go on, match only own-user players + by argv[0], and warn at start about unknown player binary names. A + failing command callback is logged with its traceback. + - #30: AudioMixer wait tests count only the test thread's sleeps + (test-only). + + -- Ion Reguera Thu, 08 Oct 2026 21:12:33 +0200 + cuems-engine (0.1.0rc6-2) bookworm; urgency=medium * Merge rc_1 into debian/bookworm (PR #22): diff --git a/src/cuemsengine/ControllerEngine.py b/src/cuemsengine/ControllerEngine.py index 5e8dd149..7ce48ad8 100644 --- a/src/cuemsengine/ControllerEngine.py +++ b/src/cuemsengine/ControllerEngine.py @@ -78,6 +78,12 @@ def __init__(self, **kwargs): # so no lock is needed — keep it that way. self.mixer_status: dict[str, float] = {} + # Per-cue names of the loaded script, {uuid: name}. Rebuilt at every + # load and broadcast AFTER the load status, replayed to late joiners, + # emptied on unload. The late-join dump reads it before the first load, + # so it must exist from __init__. + self.cue_names: dict[str, str] = {} + # Cluster-state tracking. Populated at load time by # _resolve_cluster_state # (chunk 3); used to gate the armed=yes flip on all required nodes @@ -101,6 +107,17 @@ def __init__(self, **kwargs): # nodes. Does NOT force armed=yes — operator decides. self._arm_watchdog: threading.Timer | None = None + # Run counter for cross-node Auto follows (869fc8ytz). Every GO ships + # it; STOP, load and unload bump it BEFORE they forward anything; a + # node's follow message is relayed only if it carries the current + # value. Started from the clock so a restarted controller never + # reuses a value a node still holds. The lock makes "bump" and + # "check, then forward a follow" atomic, so a relayed follow is + # always queued to the nodes ahead of the STOP that ends its run. + # Never held across a wait or the cluster probe. + self._run_seq: int = time.time_ns() // 1_000_000 + self._run_seq_lock = threading.Lock() + super().__init__(**kwargs) self.set_editor_request("") self.set_node_operation_callback() @@ -615,9 +632,56 @@ def status_operation_callback(self, operation: NodeOperation): ) updated += 1 Logger.info(f"Mixer status from {node_uuid}: {updated} channel(s) updated") + elif operation.target == "follow": + self._relay_follow(operation) else: Logger.debug(f"Unknown status target: {operation.target}") + def _bump_run_seq(self, why: str) -> None: + """A run ends here (STOP, load, unload): follow messages sent for it + are no longer relayed. Call BEFORE forwarding the command.""" + with self._run_seq_lock: + self._run_seq += 1 + seq = self._run_seq + Logger.debug(f"run_seq -> {seq} ({why})") + + def _relay_follow(self, operation: NodeOperation) -> None: + """Relay a cross-node Auto follow message (announce or cancel) to + every node (869fc8ytz). The controller keeps no follow state: the + node that owns the source decides, the others act. Dropped when the + sender is not adopted, a cue is not in the loaded project, the show + is not running, or the message belongs to an earlier run.""" + data = operation.data if isinstance(operation.data, dict) else None + if data is None: + Logger.warning(f"Follow message without data from {operation.sender}") + return + what = ( + f"follow {data.get('op')} {data.get('source')} -> {data.get('target')}" + f" at {data.get('seed_ms')} from {operation.sender}" + ) + if operation.sender not in self._adopted_nodes: + Logger.warning(f"Dropping {what}: sender is not an adopted node") + return + if ( + data.get("source") not in self.cue_status + or data.get("target") not in self.cue_status + ): + Logger.warning(f"Dropping {what}: cue not in the loaded project") + return + with self._run_seq_lock: + if ( + self.get_status("running") != "yes" + or data.get("run_seq") != self._run_seq + ): + Logger.info( + f"Dropping {what}: not part of the current run " + f"(run_seq {data.get('run_seq')}, current {self._run_seq}, " + f"running={self.get_status('running')})" + ) + return + self._forward_command_to_nodes("/engine/command/follow", data) + Logger.info(f"Relayed {what}") + ######################### # Editor commands ######################### @@ -806,6 +870,28 @@ def _collect_cue_ids(self, cuelist) -> list[str]: ids.extend(self._collect_cue_ids(item)) return ids + def _collect_cue_names(self, cuelist) -> dict[str, str]: + """Recursively collect cue names from a cuelist, same walk as + _collect_cue_ids (nested CueLists included, as items and recursed). + + Reads the name as a dict item, not through the Cue.name property: the + property raises KeyError on a cue that has no name key. None becomes + "" and anything else is str()-ed as is (never `or ""`, so a name an + old cuems-utils coerced to 0/False still prints). + """ + from cuemsutils.cues import CueList + + names = {} + if hasattr(cuelist, "contents") and cuelist.contents: + for item in cuelist.contents: + if item is None: + continue + name = item.get("name") + names[item.id] = "" if name is None else str(name) + if isinstance(item, CueList): + names.update(self._collect_cue_names(item)) + return names + def _collect_cue_enabled(self, cuelist) -> dict[str, bool]: """Recursively collect cue enabled states from a cuelist.""" from cuemsutils.cues import CueList @@ -820,6 +906,20 @@ def _collect_cue_enabled(self, cuelist) -> dict[str, bool]: result.update(self._collect_cue_enabled(item)) return result + def _broadcast_cue_name(self, cue_id: str, name: str) -> None: + """ + Broadcast a cue's name to UI at /engine/status/cue_name/{uuid}. + Sent once per load (no throttle), like cue_enabled. + """ + if ( + hasattr(self, "communications_thread") + and self.communications_thread + and hasattr(self.communications_thread, "broadcast_osc") + ): + self.communications_thread.broadcast_osc( + f"/engine/status/cue_name/{cue_id}", name + ) + def _broadcast_cue_enabled(self, cue_id: str, enabled: bool) -> None: """ Broadcast per-cue enabled status to UI at @@ -903,6 +1003,12 @@ async def _on_ws_client_connect(self, websocket) -> None: if data: await websocket.send(data) + # Per-cue names (after `load` above, like the live burst) + for cid, name in self.cue_names.items(): + data = build_osc_message(f"/engine/status/cue_name/{cid}", name) + if data: + await websocket.send(data) + # Per-mixer-channel volume status. # Scale note: each entry is one ~80-byte WS message. Acceptable up to # ~500 entries (~40 KB / ~500 ms over LAN). If a deployment ever @@ -970,6 +1076,7 @@ def load_project(self, project_name, context=None, deploy_only=False): return False Logger.info(f"Loading project {project_name}") + self._bump_run_seq("load") self._clear_playback_state() self.reset_script() @@ -1032,6 +1139,15 @@ def load_project(self, project_name, context=None, deploy_only=False): # UI contract) self.set_status("load", project_name) + # Per-cue names, deliberately AFTER the load status (unlike cue_status + # and cue_enabled above): duplicated projects share cue uuids, so a + # client treats a change of `load` as "new table" and refills it from + # this burst. Keep this order. + self.cue_names = self._collect_cue_names(self.script.cuelist) + for cid, name in self.cue_names.items(): + self._broadcast_cue_name(cid, name) + Logger.info(f"Cue names initialised for {len(self.cue_names)} cues") + # Probe cluster, derive _required_nodes for GO gating, refresh # in network_map. Done BEFORE _forward_load_to_nodes so the gating set # is in place by the time nodes start sending armed_ready. @@ -1085,10 +1201,13 @@ def go_script(self, value, context=None): # every node fire 4.48s late on test2 (2026-09-25). Without a live # reading, send the GO without an anchor -- each node falls back to # its own MTC, exactly as before this fix. - go_value = value + # Always a dict (869fc8ytz): it carries the run counter that + # cross-node follow messages are checked against. Nodes read nothing + # else from the GO value, so the caller's own `value` is not passed on. + go_value = {"run_seq": self._run_seq} if self.mtc_listener is not None: if self.mtc_listener.is_receiving(): - go_value = {"go_mtc_ms": self.mtc_listener.main_tc.milliseconds_exact} + go_value["go_mtc_ms"] = self.mtc_listener.main_tc.milliseconds_exact else: Logger.error( "GO: controller MTC listener is not receiving -- sending GO " @@ -1376,6 +1495,7 @@ def stop_script(self, value): Logger.info("Script not running, nothing to stop.") return + self._bump_run_seq("stop") self.go_offset = None self.set_status("running", "no") self._clear_playback_state() @@ -1402,10 +1522,12 @@ def unload_project(self, value, context=None): """Unload the current project. Rejects if playback is running.""" if self.get_status("running") == "yes": raise RuntimeError("Cannot unload while running. Stop playback first.") + self._bump_run_seq("unload") self._clear_playback_state() self.reset_script() self.cue_status = {} self.cue_enabled_status = {} + self.cue_names = {} self.set_status("load", "") # No project loaded → no required/adopted snapshot. Without this, a # late armed_ready from a slow node could flip armed=yes on an diff --git a/src/cuemsengine/NodeEngine.py b/src/cuemsengine/NodeEngine.py index 61d2997d..6ca296a8 100644 --- a/src/cuemsengine/NodeEngine.py +++ b/src/cuemsengine/NodeEngine.py @@ -15,9 +15,14 @@ from .core.BaseEngine import BaseEngine from .cues.CueHandler import CUE_HANDLER, _ArmWalk +from .cues.FollowRelay import FollowRelay from .osc.helpers import add_prefix_to_all from .players import AudioClient, DmxClient, VideoClient -from .players.PlayerHandler import PLAYER_HANDLER, _positive_int +from .players.PlayerHandler import ( + PLAYER_HANDLER, + _positive_int, + check_orphan_binary_names, +) from .tools.CuemsDeploy import CuemsDeploy from .tools.display_conf import read_display_conf from .tools.PortHandler import PORT_HANDLER @@ -97,6 +102,10 @@ class NodeEngine(BaseEngine): """ + # Set in _setup_nng_command_callback; None until then (and in unit tests + # that build the engine without its comms). + _follow_relay = None + # GO anchor tolerance (Badajoz 2026-09-25 fix): how far the controller's # shipped GO instant may disagree with this node's own MTC before # _resolve_go_anchor distrusts it and falls back to a live local read. @@ -171,6 +180,21 @@ def _setup_nng_command_callback(self): self._handle_nng_command ) Logger.info("NNG command callback registered for NodeEngine") + # Cross-node Auto follow (869fc8ytz): announce this node's + # follows, apply the ones relayed from other nodes, in bus order. + self._follow_relay = FollowRelay( + CUE_HANDLER, + node_id=self.cm.node_uuid, + send=self._send_follow, + get_script=lambda: self.script, + get_mtc=lambda: getattr(self, "mtc_listener", None), + get_project_gen=lambda: self._project_generation, + first_local=self._first_local_enabled_in_go_chain, + ) + CUE_HANDLER._follow = self._follow_relay + CUE_HANDLER.communications_thread.set_receive_hook( + self._on_command_received + ) else: Logger.warning( "CUE_HANDLER communications thread: " @@ -182,6 +206,46 @@ def _setup_nng_command_callback(self): ACTION_HANDLER.finalize_node_layer_bindings() ACTION_HANDLER.set_result_sink(self._action_result_sink) + def _on_command_received(self, command_name: str, value) -> bool: + """Receive hook: runs for every command in BUS order, before its + command thread races the others for the command lock (869fc8ytz). + + A follow message is applied here and consumed. GO records the + controller's run counter, STOP and load clear it and every pending + follow -- here, so a follow relayed before a STOP can never be applied + after it. Must not block.""" + relay = self._follow_relay + if relay is None: + return False + if command_name == "follow": + try: + relay.on_message(value) + except Exception as e: + # Consumed anyway: a follow message must never reach the + # command lock. + Logger.error(f"Follow message failed: {e}") + return True + if command_name == "go": + relay.begin_run(value) + elif command_name in ("stop", "load"): + relay.end_run(command_name) + return False + + def _send_follow(self, data: dict) -> None: + """Queue a follow message (announce or cancel) to the controller, + which relays it to every node. Never waits.""" + from .comms.NodesHub import ActionType, NodeOperation, OperationType + + CUE_HANDLER.communications_thread.send_operation_nowait( + NodeOperation( + type=OperationType.STATUS, + action=ActionType.UPDATE, + sender=self.cm.node_uuid, + target="follow", + data=data, + ) + ) + def _handle_nng_command(self, command_name: str, value, address: str = None): """Handle a command received via NNG from ControllerEngine. @@ -432,7 +496,14 @@ def run_command(self, command, value): if command in self.commands_dict.keys(): handler = self.commands_dict[command] if handler is not None: - handler(value) + try: + handler(value) + finally: + if command in ("stop", "load") and self._follow_relay: + # The receive hook counted it received; until + # here this node's epochs still belonged to the + # run it ends (869fc8ytz). + self._follow_relay.stop_applied() return True else: Logger.warning(f"Command {command} has no handler") @@ -445,6 +516,9 @@ def run_command(self, command, value): # Player logic ######################### def set_players(self): + # A player binary the orphan cleanups do not know by name escapes them + # all; say so at start (869evtdf7). + check_orphan_binary_names(self.cm.node_conf) self.set_video_players() self.set_audio_players() self.set_dmx_players() diff --git a/src/cuemsengine/comms/NodeCommunications.py b/src/cuemsengine/comms/NodeCommunications.py index cbc421b6..090d1a3b 100644 --- a/src/cuemsengine/comms/NodeCommunications.py +++ b/src/cuemsengine/comms/NodeCommunications.py @@ -1,6 +1,7 @@ # SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL # SPDX-License-Identifier: GPL-3.0-or-later # SPDX-FileContributor: Adrià Masip +# SPDX-FileContributor: Ion Reguera import asyncio from typing import Any, Callable, Optional @@ -37,6 +38,9 @@ def __init__( self.nng_hub = NodesHub(hub_address, mode=NodesHub.Mode.DIALER) self.node_id = node_id self._command_callback = command_callback + # Called synchronously, in bus order, before a command thread is + # started; returning True consumes the message (869fc8ytz). + self._receive_hook: Optional[Callable[[str, Any], bool]] = None self.nng_hub.set_receive_callbacks( { @@ -54,6 +58,17 @@ def set_command_callback(self, callback: Callable[[str, Any], None]) -> None: self._command_callback = callback Logger.debug("Command callback set in NodeCommunications") + def set_receive_hook(self, hook: Callable[[str, Any], bool]) -> None: + """Set a hook called for every command in BUS order, on the receiver, + before its command thread is started (869fc8ytz). + + The command threads then race for the engine's command lock, so only + here is the order the controller sent things in still known. The hook + must not block. Returning True consumes the message (no command + thread); an exception is logged and the command still runs. + """ + self._receive_hook = hook + def create_all_tasks(self): """Create async tasks for node communications.""" Logger.info("Starting all tasks in NodeCommunications") @@ -107,6 +122,14 @@ def _handle_command_operation(self, operation: NodeOperation) -> None: Logger.info(f"Received command via NNG: {command_name} = {repr(value)}") + if self._receive_hook is not None: + try: + if self._receive_hook(command_name, value): + return + except Exception as e: + # Never lose a GO, a STOP or a load to a bug in the hook. + Logger.error(f"Receive hook failed for {command_name}: {e}") + if self._command_callback: # Execute command in a separate thread to avoid blocking the NNG # receiver @@ -118,8 +141,12 @@ def run_command(): try: self._command_callback(command_name, value, address) except Exception as e: + # With the traceback: the message alone ("[Errno 1] + # Operation not permitted") does not say which step of + # the command failed (869evtdf7). Logger.error( - f"Error executing command callback for {command_name}: {e}" + f"Error executing command callback for {command_name}: {e}", + exc_info=True, ) thread = threading.Thread( @@ -145,6 +172,18 @@ def send_operation(self, operation: NodeOperation, timeout: Optional[float] = No """ return self.run_coroutine(self.nng_hub.send_operation, operation, timeout) + def send_operation_nowait(self, operation: NodeOperation) -> None: + """Queue a NodeOperation to the controller without waiting for it. + + For senders that must never block: a cue's own thread, or a caller + holding a lock. Raises if the comms loop is not running. + """ + if not self.event_loop: + raise AttributeError(f"{self.name} event loop is not initialized") + asyncio.run_coroutine_threadsafe( + self.nng_hub.send_operation(operation), self.event_loop + ) + def add_player(self, player_id: str, data: dict, timeout: Optional[float] = None): """ Add a player to the OSC hub (thread-safe). diff --git a/src/cuemsengine/cues/CueHandler.py b/src/cuemsengine/cues/CueHandler.py index e6d4db5b..623cf88c 100644 --- a/src/cuemsengine/cues/CueHandler.py +++ b/src/cuemsengine/cues/CueHandler.py @@ -6,6 +6,7 @@ from __future__ import annotations from dataclasses import dataclass, field +from functools import partial from threading import Event, Lock, Thread, current_thread from time import monotonic, sleep from typing import Callable @@ -59,6 +60,23 @@ class _ArmClaim: waiters: int = 0 +@dataclass +class _FollowOut: + """What one cue thread did about its cross-node Auto follow (869fc8ytz). + + `record` is the (instant_ms, run_seq) it announced; the cue carries the + same tuple as `_follow_out` until whoever takes it (the fire, the thread + leaving, or go() starting the cue again) compare-and-clears it, so one + announcement is followed by at most one cancel. + """ + + revealed: bool = False + record: tuple | None = None + fired: bool = False + yielded: bool = False + error: bool = False + + class CueHandler: """ Singleton class responsible for handling Cue objects. @@ -210,6 +228,10 @@ def remove_armed_cue(self, cue: Cue) -> bool: # whose epoch has moved is never published (see arm()). _disarm_epoch = 0 + # Cross-node Auto follow relay (cues.FollowRelay), attached by NodeEngine. + # None (unit tests, an engine without comms): nothing is announced. + _follow = None + def arm_epoch(self) -> int: """The current STOP/load epoch. Whoever requests an arm on one thread and performs it on another captures this at request time and passes @@ -494,9 +516,16 @@ def arm( init=False, walk: _ArmWalk | None = None, epoch: int | None = None, + wait_report: dict | None = None, ) -> bool: """Arms a cue by appending it to the armed_cues list. + wait_report: optional dict. When this call waits for another thread's + arm of the same cue, it sets wait_report["waited_s"] (total seconds + waited) and wait_report["holder"] (that thread's name), so a caller + can say what really happened instead of guessing from a check made + before the call (869fbyjzx). + walk: set only by a background _arm_ahead walk (NodeEngine's PreArm). Its excluded types and should_continue checkpoint also govern this call's own post_go / ActionCue-target recursion, and every cue this @@ -537,6 +566,7 @@ def arm( return False wait_deadline = None + waited_total = 0.0 while True: needs_disarm = False claim = None @@ -586,7 +616,12 @@ def arm( Logger.debug( f"Waiting for in-progress arm of {type(cue).__name__} {cue.id}" ) + wait_started = monotonic() woke = remaining > 0 and pending.event.wait(timeout=remaining) + waited_total += monotonic() - wait_started + if wait_report is not None: + wait_report["waited_s"] = waited_total + wait_report["holder"] = pending.holder with self._lock: pending.waiters -= 1 if not woke: @@ -751,6 +786,23 @@ def log_armed_inventory(self, where: str) -> None: except Exception as e: Logger.warning(f"Could not count the armed inventory ({where}): {e}") + @staticmethod + def _log_arm_wait( + cue: Cue, where: str, in_flight: str | None, wait_report: dict + ) -> None: + """Report what arm() did about an arm in flight (869fbyjzx).""" + waited = wait_report.get("waited_s") + if waited is not None: + Logger.info( + f"Cue {cue.id} waited {waited:.2f}s at {where} for the arm in " + f"progress (held by {wait_report.get('holder')})" + ) + elif in_flight is not None: + Logger.info( + f"Cue {cue.id}: the arm in progress at {where} had finished " + f"before this call looked; no wait" + ) + def describe_arm_in_flight(self, cue: Cue) -> str | None: """Who is arming this cue right now and for how long, as text for a log line; None when no arm of it is in flight.""" @@ -1165,6 +1217,7 @@ def go( stamp_skipped: list = None, require_stop_epoch: int = None, arm_epoch: int = None, + commit_gate: Callable[[Cue, int], bool] | None = None, ) -> Thread | None: """Starts a cue in a thread. @@ -1187,6 +1240,11 @@ def go( inherits its chain's. It goes into every arm this dispatch causes (the fallback re-arm, the lookahead, the cue's own thread), and a dispatch whose epoch has moved is refused. + commit_gate: called inside the commit section, after every other + refusal, with the cue and the generation about to be assigned; + False (or an exception) refuses the dispatch. A cross-node follow + uses it so that its cancel and its dispatch are decided in one + place (869fc8ytz). Returns: Thread running the cue, or None if the cue is disabled, not local @@ -1222,18 +1280,43 @@ def go( chain_epoch = self._chain_epoch if not hasattr(cue, "loaded") or not cue.loaded: - Logger.warning( - f"Cue {cue.id} not loaded at go() time — this should not" - f"happen, " - f"pre-arm may have failed. Re-arming as fallback." - ) + # 869fbyjzx: say which case this is. An arm still in flight (a + # pre-arm, an audio player still starting) is not a failure; the + # old "pre-arm may have failed" said it was. Best-effort: the arm + # can start or finish between this look and arm() below, so the + # wait itself is reported from what arm() actually did. True + # fallbacks keep "not loaded at go() time" and "Re-arming as + # fallback": the harnesses count them. + # An arm in flight that a GO waits for is still a LATE cue when the + # arm is slower than the GO gap (an audio arm is ~0.47 s cold): + # arming before the hand-off ("Part B") is the only cure and is + # not built; see AudioMixer.connect_player_to_outputs (869fbyjzx). + in_flight = self.describe_arm_in_flight(cue) + if is_continuation: + Logger.info( + f"Cue {cue.id} not armed yet at go() time — dispatching; " + f"its own thread arms it or waits for the arm in progress" + ) + elif in_flight is not None: + Logger.info( + f"Cue {cue.id} is still being armed ({in_flight}) at go() " + f"time — waiting for the arm in progress" + ) + else: + Logger.warning( + f"Cue {cue.id} not loaded at go() time — no arm in flight " + f"(never armed, or an earlier arm failed or was " + f"abandoned). Re-arming as fallback." + ) # A continuation does NOT arm here: dispatch now happens at chain # entry, so this call runs on the PREVIOUS cue's thread, and an # audio arm can block ~15s on its JACK ports — delaying or killing # that cue's own reveal. go_threaded arms the cue on its own # thread instead, overlapping its own prewait. if not is_continuation: - self.arm(cue, init=True, epoch=arm_epoch) + wait_report = {} + self.arm(cue, init=True, epoch=arm_epoch, wait_report=wait_report) + self._log_arm_wait(cue, "go() time", in_flight, wait_report) if not hasattr(cue, "loaded") or not cue.loaded: if arm_epoch != self._disarm_epoch: # Not an arm failure: the operator's STOP (or a load) @@ -1298,6 +1381,23 @@ def go( ) return None + go_gen = getattr(cue, "_go_generation", 0) + 1 + if commit_gate is not None: + try: + allowed = commit_gate(cue, go_gen) + except Exception as e: + Logger.error(f"Commit gate for cue {cue.id} failed: {e}") + allowed = False + if not allowed: + Logger.info( + f"Refusing dispatch of cue {cue.id}: its cross-node " + "follow was cancelled or replaced" + ) + return None + # Only past every refusal: a dispatch that is refused must not + # cancel the follow of the pass still playing. + self._take_follow_on_restart_locked(cue) + cue._go_epoch = chain_epoch # Recorded here, not in the spawned thread: a disable arriving in # between has to find this cue's anchor to stamp a rejoin with, and @@ -1306,12 +1406,14 @@ def go( # thread", which is not an anchor a rejoin can be pinned to. cue._dispatch_arrival_ms = frozen_mtc_ms cue._stop_requested = False - go_gen = getattr(cue, "_go_generation", 0) + 1 cue._go_generation = go_gen # Output-commit flag: True once this cue has produced output # (reveal, or the DMX scene send). The stop walk cancels only # cues that have NOT committed — a playing cue is never cut. cue._revealed = False + # When this pass produced output (monotonic); set by go_threaded. + # A late cross-node follow cancel reads it (869fc8ytz). + cue._revealed_at = None # Lifecycle flag: True while a GO owns this cue; cleared by # disarm() and stop_all_cues(). Unlike _go_generation # (increment-only), this is a sound "currently playing" signal — @@ -1350,7 +1452,13 @@ def go( return thread def go_from( - self, start_cue: Cue, mtc: MtcListener, seed_ms: float = None + self, + start_cue: Cue, + mtc: MtcListener, + seed_ms: float = None, + arm_epoch: int = None, + require_stop_epoch: int = None, + commit_gate: Callable[[Cue, int], bool] | None = None, ) -> Thread | None: """Re-enter a post_go='go' chain from start_cue (inclusive), firing THIS node's first local+enabled cue at seed_ms + Σ(chain advance of the @@ -1364,7 +1472,20 @@ def go_from( than the play target: a loop-back 'play' aimed at node01's cue would never re-fire the controller's own cues. Walking here makes each engine re-enter its own local segment, exactly as it does on a GO. + + arm_epoch / require_stop_epoch / commit_gate are passed to go() when + set: a cross-node follow dispatches on another thread than the one + that received it, and a STOP or a cancel in between must win. """ + guards = { + k: v + for k, v in ( + ("arm_epoch", arm_epoch), + ("require_stop_epoch", require_stop_epoch), + ("commit_gate", commit_gate), + ) + if v is not None + } if seed_ms is None: seed_ms = mtc.main_tc.milliseconds_exact cue = start_cue @@ -1395,8 +1516,14 @@ def go_from( self.stamp_pass(skipped_disabled, seed_ms) return None if skipped_disabled: - return self.go(cue, mtc, seed_ms + sigma_ms, stamp_skipped=skipped_disabled) - return self.go(cue, mtc, seed_ms + sigma_ms) + return self.go( + cue, + mtc, + seed_ms + sigma_ms, + stamp_skipped=skipped_disabled, + **guards, + ) + return self.go(cue, mtc, seed_ms + sigma_ms, **guards) def _reveal_wait(self, cue: Cue, mtc: MtcListener, go_gen: int = 0) -> str: """Block until live MTC reaches cue._start_mtc; return 'reached' or 'stopped'. @@ -1506,6 +1633,37 @@ def go_threaded( go_at_end lookahead) and the continuation it dispatches belong to it, so none of them survives a STOP. """ + follow = _FollowOut() + try: + self._run_cue_pass( + cue, + mtc, + frozen_mtc_ms, + go_gen, + chain_epoch, + unroll, + arm_epoch, + follow, + ) + except Exception: + follow.error = True + raise + finally: + self._leave_follow(cue, follow, arm_epoch) + + def _run_cue_pass( + self, + cue: Cue, + mtc: MtcListener, + frozen_mtc_ms: float, + go_gen: int, + chain_epoch: int, + unroll: bool, + arm_epoch: int | None, + follow: _FollowOut, + ): + """The body of go_threaded; `follow` records what this pass did about + its cross-node Auto follow, for go_threaded's exit (869fc8ytz).""" # frozen_mtc_ms is this cue's ARRIVAL on the MTC timeline: # GO_mtc + Σ(effective durations of preceding cues in the chain). # None → manual GO / go_at_end: arrival = live MTC now (so those paths @@ -1579,11 +1737,22 @@ def go_threaded( # its reveal). It arms here instead, on its own thread, overlapping # its own prewait. if not getattr(cue, "loaded", False): - Logger.warning( - f"Cue {cue.id} not loaded at dispatch — arming on its own " - f"thread before its slot." - ) - self.arm(cue, init=True, epoch=arm_epoch) + # 869fbyjzx: an arm in flight is waited for, not a fallback. + in_flight = self.describe_arm_in_flight(cue) + if in_flight is not None: + Logger.info( + f"Cue {cue.id} is still being armed ({in_flight}) at " + f"dispatch — waiting for the arm in progress" + ) + else: + Logger.warning( + f"Cue {cue.id} not loaded at dispatch — no arm in " + f"flight; arming on its own thread before its slot. " + f"Re-arming as fallback." + ) + wait_report = {} + self.arm(cue, init=True, epoch=arm_epoch, wait_report=wait_report) + self._log_arm_wait(cue, "dispatch", in_flight, wait_report) if arm_epoch is not None and arm_epoch != self._disarm_epoch: # arm() refused or abandoned the arm: a STOP or a load # landed since this cue was dispatched. Said here, before @@ -1656,6 +1825,7 @@ def go_threaded( # as still cancellable. with self._lock: cue._revealed = True + cue._revealed_at = monotonic() # MTC-gated reveal: wait until live MTC reaches start_ms, then reveal # (video /visible; audio /mtcfollow; action EXECUTE; dmx no-op). This @@ -1671,8 +1841,13 @@ def go_threaded( ) if do_reveal: cue._revealed = True + # Same section: a cross-node follow cancel deciding + # "not started yet" must never see _revealed set + # without its stamp. + cue._revealed_at = monotonic() if do_reveal: - revealed_at = monotonic() + revealed_at = cue._revealed_at + follow.revealed = True reveal_cue(cue, mtc, start_ms) armed_at = getattr(cue, "_armed_at", None) if armed_at is not None: @@ -1714,11 +1889,26 @@ def go_threaded( # in parallel with the media. go() also calls _arm_ahead but # that fires before run_cue — this call catches cues that were # disarmed between go() and here (loop passes). + # Cross-node Auto follow (869fc8ytz): tell the other nodes the follow + # instant as soon as it is final -- now, or at the start of the last + # loop -- and before the lookahead below, which can take seconds. + on_last_loop = None + if follow.revealed and self._follows_out(cue): + if cue.loop == 1: + self._announce_follow(cue, go_gen, start_ms, follow) + elif cue.loop > 1: + on_last_loop = partial( + self._announce_follow, cue, go_gen, start_ms, follow + ) + if cue.post_go == "go_at_end": self._arm_ahead(cue, arm_epoch=arm_epoch) Logger.info(f"Going to loop for {cue.__class__.__name__}:{cue.id}") - loop_cue(cue, mtc) + if on_last_loop is None: + loop_cue(cue, mtc) + else: + loop_cue(cue, mtc, on_last_loop=on_last_loop) if getattr(cue, "_go_generation", 0) != go_gen: Logger.info( @@ -1735,11 +1925,7 @@ def go_threaded( # setup; CueList) — and guard against a stale _end_mtc left by a # previous GO of this object. (FadeCue DOES set a real _end_mtc via # _handle_fade_action — used as-is.) - end_attr = getattr(cue, "_end_mtc", None) - base_end_ms = end_attr.milliseconds_exact if end_attr is not None else start_ms - if base_end_ms < start_ms: - base_end_ms = start_ms # stale from a previous run - fire_seed_ms = base_end_ms + cue.postwait.milliseconds_exact + fire_seed_ms = self._follow_instant_ms(cue, start_ms) tail = ( cue.post_go in ("pause", "go_at_end") @@ -1805,12 +1991,14 @@ def go_threaded( # arrival on the shared timeline; go_threaded adds the target's own # prewait on top. The target_gen0 compare makes this auto-fire YIELD # if a manual GO already started the target during the tail. - go_at_end_thread = self.go_from(cue._target_object, mtc, fire_seed_ms) + if self._follow_fired(cue, follow, fire_seed_ms, go_gen): + go_at_end_thread = self.go_from(cue._target_object, mtc, fire_seed_ms) elif ( cue.post_go == "go_at_end" and cue._target_object and not cue._stop_requested ): + follow.yielded = True Logger.info( f"go_at_end fire for {cue.id} yielded: " "target already started by a newer GO" @@ -1825,6 +2013,263 @@ def go_threaded( if post_go_thread: self.wait_for_cue(post_go_thread) + # --------------------------- + # Cross-node Auto follow (869fc8ytz) + # --------------------------- + + @staticmethod + def _follow_instant_ms(cue: Cue, start_ms: float) -> float: + """When an Auto follow fires its target: the body's end on the MTC + timeline plus the postwait. The one expression both the fire and the + announcement use. Fallbacks for cues that never set _end_mtc (plain + ActionCue body=0; aborted A/V setup; CueList) and a stale _end_mtc + left by a previous GO of this object. (FadeCue DOES set a real + _end_mtc via _handle_fade_action -- used as-is.)""" + end_attr = getattr(cue, "_end_mtc", None) + base_end_ms = end_attr.milliseconds_exact if end_attr is not None else start_ms + if base_end_ms < start_ms: + base_end_ms = start_ms # stale from a previous run + return base_end_ms + cue.postwait.milliseconds_exact + + @staticmethod + def _follows_out(cue: Cue) -> bool: + """An Auto follow whose source plays only where it has an output. + + ActionCue, FadeCue, CueList and DmxCue are local on every node, so + every node fires their follow itself; only AudioCue and VideoCue need + the other nodes told.""" + return ( + isinstance(cue, (AudioCue, VideoCue)) + and getattr(cue, "_local", False) + and getattr(cue, "post_go", None) == "go_at_end" + and getattr(cue, "_target_object", None) is not None + ) + + def _announce_follow( + self, cue: Cue, go_gen: int, start_ms: float, follow: _FollowOut + ) -> None: + """Announce this pass's follow instant to the other nodes, once. + + Decided, recorded and queued in one lock section, so the messages + leave in the order the decisions were taken; only the pass that still + owns the cue announces. Never raises: it runs on the cue's thread.""" + relay = self._follow + if relay is None or follow.record is not None: + return + try: + with self._lock: + if getattr(cue, "_go_generation", 0) != go_gen or getattr( + cue, "_stop_requested", False + ): + return + if relay.stop_pending: + # A STOP or a load was received and has not run yet: this + # pass is about to be stopped. + return + run_seq = relay.run_seq + if run_seq is None: + relay.warn_no_run() + return + record = (self._follow_instant_ms(cue, start_ms), run_seq) + cue._follow_out = record + follow.record = record + relay.announce(cue, record[0], run_seq) + except Exception as e: + Logger.error(f"Could not announce the follow of cue {cue.id}: {e}") + + def _take_follow_record_locked(self, cue: Cue, record: tuple) -> bool: + """Compare-and-clear the cue's outstanding announcement. Caller holds + self._lock. True if `record` was still the outstanding one.""" + if getattr(cue, "_follow_out", None) == record: + cue._follow_out = None + return True + return False + + def _take_follow_on_restart_locked(self, cue: Cue) -> None: + """go() is starting a cue whose earlier pass announced a follow: that + follow will not happen. Caller holds self._lock (go()'s commit + section, after every refusal). The earlier pass's thread may only + notice at the new pass's end, so the cancel goes out here.""" + record = getattr(cue, "_follow_out", None) + if record is None: + return + cue._follow_out = None + relay = self._follow + if relay is None or record[1] != relay.run_seq: + return + try: + relay.cancel(cue, record[0], record[1], "restart") + except Exception as e: + Logger.error(f"Could not cancel the follow of cue {cue.id}: {e}") + + def _follow_fired( + self, cue: Cue, follow: _FollowOut, fire_ms: float, go_gen: int + ) -> bool: + """The pass is about to fire its follow: nothing to cancel any more. + + Returns False -- do not fire -- when this pass announced its follow + and has been replaced since (the cue was started again): go() already + cancelled the announcement on the other nodes, so firing here would + play only half of the target. An unannounced follow fires as before.""" + if follow.record is None: + follow.fired = True + return True + with self._lock: + if getattr(cue, "_go_generation", 0) != go_gen: + Logger.info( + f"Cue {cue.id} was started again before its follow fired; " + "the new pass owns the follow" + ) + return False + follow.fired = True + self._take_follow_record_locked(cue, follow.record) + if abs(fire_ms - follow.record[0]) > 1.0: + Logger.error( + f"Cue {cue.id} fires its follow at {fire_ms:.0f}ms but " + f"announced {follow.record[0]:.0f}ms to the other nodes" + ) + return True + + def _leave_follow( + self, cue: Cue, follow: _FollowOut, arm_epoch: int | None + ) -> None: + """go_threaded's exit: a pass that announced and did not fire cancels, + unless every node already knows (a STOP or a load, the yield) or go() + took the announcement (the cue was started again). Never raises.""" + record = follow.record + if record is None or follow.fired: + return + try: + with self._lock: + if not self._take_follow_record_locked(cue, record): + return + if arm_epoch is not None and arm_epoch != self._disarm_epoch: + return + if follow.error: + reason = "error" + elif follow.yielded: + return + elif getattr(cue, "_stop_requested", False): + reason = "stop" + else: + Logger.warning( + f"Cue {cue.id} ended without firing its follow for no " + "known reason; cancelling it on the other nodes" + ) + reason = "error" + relay = self._follow + if relay is not None: + relay.cancel(cue, record[0], record[1], reason) + except Exception as e: + Logger.error(f"Could not cancel the follow of cue {cue.id}: {e}") + + def stop_dispatched_follow( + self, + cue: Cue, + gen: int, + disarm_epoch: int, + armed_at: float | None, + may_cut: bool, + grace_s: float, + started_before: float | None = None, + ) -> tuple[str, float | None]: + """Stop a cue a cross-node follow dispatched, after the owner + cancelled that follow (869fc8ytz). Returns (outcome, age): + + - "owned": a newer GO or a STOP has the cue (generation or epoch + moved); nothing is touched; + - "stopped": it had not started, or started less than `grace_s` ago + and `may_cut` (the source was stopped or started again); + - "left": it started too long ago, or the cancel came from an error + -- a cue on stage is never cut for an internal reason. + + `age` is seconds since the cue produced output, None if it had not. + `started_before` is when the cue went on stage in a pass that was + still playing when the follow dispatched it again (recorded by the + follow's commit gate): its output counts as started. + The decision and the stop flags are one lock section; the disarm is + guarded again (disarm_if_unchanged).""" + with self._lock: + if ( + getattr(cue, "_go_generation", 0) != gen + or self._disarm_epoch != disarm_epoch + ): + return "owned", None + started = getattr(cue, "_revealed_at", None) + if started is None and getattr(cue, "_revealed", False): + started = monotonic() + if started is None: + started = started_before + age = None if started is None else monotonic() - started + if age is not None and (age >= grace_s or not may_cut): + return "left", age + cue._stop_requested = True + new_gen = gen + 1 + cue._go_generation = new_gen + cue._playing = False + self.cancel_pending_descendants(cue) + self._end_illumination(cue) + # Let the cue's own loop see the flag and leave (polls every 20 ms), + # as the stop action does. + sleep(0.1) + self.disarm_if_unchanged( + cue, new_gen, disarm_epoch, armed_at, reason="follow_cancelled" + ) + return "stopped", age + + def disarm_if_unchanged( + self, + cue: Cue, + gen: int, + disarm_epoch: int, + armed_at: float | None, + reason: str, + ) -> bool: + """Disarm a cue only if nothing took it since the caller decided to. + + In one lock section: the generation, the STOP/load epoch and the arm + stamp must be the caller's, the cue still loaded and no arm of it in + flight; then this thread takes the cue's arm claim and unpublishes it + (unloaded, out of the armed list). Its player and layers are released + outside the lock while the claim is held, so no arm of the same cue + can run meanwhile; the claim is released in a finally (a leaked one + would make the cue unarmable until the engine restarts). Returns True + if it disarmed.""" + with self._lock: + registry = self._arming_registry() + if ( + getattr(cue, "_go_generation", 0) != gen + or self._disarm_epoch != disarm_epoch + or not getattr(cue, "loaded", False) + or getattr(cue, "_armed_at", None) != armed_at + or registry.get(cue.id) is not None + ): + return False + claim = _ArmClaim(holder=current_thread().name, started=monotonic()) + registry[cue.id] = claim + cue.loaded = False + cue._playing = False + if cue.id in self._armed_cues_set: + self._armed_cues.remove(cue) + self._armed_cues_set.discard(cue.id) + try: + Logger.info(f"Disarming cue {cue.id} ({reason})") + try: + if isinstance(cue, AudioCue): + self.communications_thread.remove_player( + f"audioplayer_{cue.id}", timeout=0.1 + ) + self.communications_thread.remove_cue(cue.id, timeout=0.1) + except Exception: + pass + self._release_cue_resources(cue, reason) + finally: + with self._lock: + if registry.get(cue.id) is claim: + del registry[cue.id] + claim.event.set() + return True + def wait_for_cue(self, thread: Thread) -> None: """Waits for a cue to finish.""" Logger.info(f"Waiting for {thread.name} to finish") diff --git a/src/cuemsengine/cues/FollowRelay.py b/src/cuemsengine/cues/FollowRelay.py new file mode 100644 index 00000000..e6159b14 --- /dev/null +++ b/src/cuemsengine/cues/FollowRelay.py @@ -0,0 +1,563 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera +"""Cross-node Auto follow (ClickUp 869fc8ytz). + +An Auto follow (post_go='go_at_end') fires its target when the cue ends. Only +the nodes where the cue is local run it, so only they used to fire the follow: +a target that plays on another node never started, silently. + +Now the node that owns the source ANNOUNCES the follow instant when the cue +starts (CueHandler, through `announce`), the controller relays it to every +node, and every other node pre-arms what it would start, waits for that +instant on MTC and dispatches it then, as the owner does for its own cues. +If the follow does not happen (the source was stopped, paused, faded out or +started again), the owner sends a CANCEL for the instant it announced. + +This class is both halves of the node's side: +- owner: `announce` / `cancel` queue the message to the controller; +- receiver: `on_message` applies a relayed message. It is called from the + bus receive hook, in bus order, and never waits: the pre-arm, the wait for + the instant and the stop of a target that must not play run on their own + threads. + +One entry per source cue, in a table with its own lock. Nothing calls into +CueHandler while holding that lock; the only nesting is CueHandler._lock then +the table lock, inside the commit gate `go()` evaluates (`_gate`). + +`run_seq` (the controller's run counter) is set from every GO and cleared at +STOP and load, at receipt; a message of another run is refused, and every +dispatch carries the STOP/load epochs read when its announcement arrived. + +Design: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md. +""" + +from __future__ import annotations + +import threading +from dataclasses import dataclass, field +from time import sleep +from typing import Any, Callable + +from cuemsutils.cues import ActionCue, DmxCue +from cuemsutils.log import Logger + +from .CueHandler import _ArmWalk + +# A cancel that reaches a target which has already started stops it only if it +# started less than this ago, and only when the source was stopped or started +# again. The saved test2 runs showed commands delayed 700-800 ms on a loaded +# node, so the limit sits well above that. Ion, 2026-10-05 (D2). +FOLLOW_CANCEL_GRACE_S = 2.0 +# Two announcements of the same source within this are the same follow (two +# owners of one cue announce the same instant). +FOLLOW_INSTANT_MATCH_MS = 1.0 +# An announcement this late is still honoured (D7), but as an ERROR. +FOLLOW_LATE_ERROR_MS = 10_000.0 +# How often the pre-arm re-checks what it would start until the instant. The +# plan said 0.5 s; test2 (2026-10-06) showed a target still playing its earlier +# pass until 0.3 s before the instant fall back to an arm at dispatch, so it +# checks faster. A round that finds everything loaded costs one chain walk. +FOLLOW_PREARM_PERIOD_S = 0.1 +# Waiter MTC poll, as _wait_mtc. +FOLLOW_POLL_S = 0.02 + +_LIVE = ("waiting", "dispatching", "dispatched") + + +@dataclass(eq=False) +class _Entry: + source_id: str + target_id: str + instant: float + run_seq: int + origins: set + # Read once no STOP or load is pending on this node (None until then). + arm_epoch: int | None + stop_epoch: int | None + project_gen: Any + # waiting -> dispatching -> dispatched | done; any live state -> cancelled + state: str = "waiting" + cue: Any = None + # When the cue went on stage in a pass still playing when the follow + # dispatched it again (MINOR-3 of the code review). + started_before: float | None = None + gen: int | None = None + disarm_epoch: int | None = None + armed_at: float | None = None + lookahead_done: set = field(default_factory=set) + + +class FollowRelay: + def __init__( + self, + cue_handler, + node_id: str, + send: Callable[[dict], None], + get_script: Callable[[], Any], + get_mtc: Callable[[], Any], + get_project_gen: Callable[[], Any], + first_local: Callable[[Any], Any], + spawn: Callable[..., None] | None = None, + sleep: Callable[[float], None] = sleep, + ): + self._ch = cue_handler + self.node_id = node_id + self._send = send + self._get_script = get_script + self._get_mtc = get_mtc + self._get_project_gen = get_project_gen + self._first_local = first_local + self._spawn = spawn or self._spawn_thread + self._sleep = sleep + self._prearm_sleep = sleep + self._lock = threading.Lock() + self._table: dict[str, _Entry] = {} + self._run_seq: int | None = None + self._no_run_logged = False + # STOP/load commands received (receive hook) and applied (after the + # node ran them). In between, this node's epochs still belong to the + # run that is ending: nothing is announced and no epoch is read. + self._stops_received = 0 + self._stops_applied = 0 + + # ------------------------------------------------------------------ + # The run + # ------------------------------------------------------------------ + + @property + def run_seq(self) -> int | None: + return self._run_seq + + @property + def stop_pending(self) -> bool: + """A STOP or a load was received and has not run yet on this node.""" + return self._stops_received > self._stops_applied + + def stop_applied(self) -> None: + """The node has run a STOP or a load (or refused it).""" + with self._lock: + self._stops_applied += 1 + + def begin_run(self, value) -> None: + """At a GO's receipt. Same run: keep the table. New run: empty it. + A GO without an integer run_seq comes from a controller that does + not relay follows: nothing is announced until one that does.""" + seq = value.get("run_seq") if isinstance(value, dict) else None + if type(seq) is not int: + seq = None + with self._lock: + if seq == self._run_seq: + return + self._run_seq = seq + dropped = len(self._table) + self._table.clear() + if seq is None: + Logger.debug("GO carries no run_seq: cross-node follows are off") + else: + Logger.debug(f"Follow run {seq} (dropped {dropped} pending)") + + def end_run(self, why: str) -> None: + """At a STOP's or a load's receipt: every pending follow is gone.""" + with self._lock: + self._stops_received += 1 + self._run_seq = None + dropped = sum(e.state in _LIVE for e in self._table.values()) + self._table.clear() + if dropped: + Logger.info(f"Follow: {why} dropped {dropped} pending follow(s)") + + # ------------------------------------------------------------------ + # Owner: queue the message (never waits) + # ------------------------------------------------------------------ + + def announce(self, cue, instant_ms: float, run_seq: int) -> None: + self._emit("announce", cue, instant_ms, run_seq) + + def cancel(self, cue, instant_ms: float, run_seq: int, reason: str) -> None: + self._emit("cancel", cue, instant_ms, run_seq, reason) + + def _emit(self, op, cue, instant_ms, run_seq, reason=None) -> None: + target = getattr(cue, "_target_object", None) + data = { + "op": op, + "origin": self.node_id, + "run_seq": run_seq, + "source": str(cue.id), + "target": str(getattr(target, "id", "")), + "seed_ms": float(instant_ms), + } + if reason is not None: + data["reason"] = reason + try: + self._send(data) + except Exception as e: + Logger.error( + f"Follow: could not send {op} for {data['source']} -> " + f"{data['target']} at {instant_ms:.0f}ms: {e}" + ) + return + Logger.info( + f"Follow: {op} queued for {data['source']} -> {data['target']} at " + f"{instant_ms:.0f}ms" + (f" ({reason})" if reason else "") + ) + + def warn_no_run(self) -> None: + """The owner had a follow to announce but no run_seq: the controller + does not relay follows (older engine). Said once.""" + if not self._no_run_logged: + self._no_run_logged = True + Logger.info( + "Follow: the controller sent no run_seq with its GO; Auto " + "follows into cues on other nodes are not announced" + ) + + # ------------------------------------------------------------------ + # Receiver: apply a relayed message (receive hook; never waits) + # ------------------------------------------------------------------ + + def on_message(self, data) -> None: + if not isinstance(data, dict): + Logger.warning(f"Follow: ignoring a malformed message {data!r}") + return + op = data.get("op") + if op == "announce": + self._on_announce(data) + elif op == "cancel": + self._on_cancel(data) + else: + Logger.warning(f"Follow: ignoring a message with op {op!r}") + + def _on_announce(self, data: dict) -> None: + source_id = str(data.get("source")) + target_id = str(data.get("target")) + origin = data.get("origin") + what = f"{source_id} -> {target_id} from {origin}" + if origin == self.node_id: + return + script = self._get_script() + mtc = self._get_mtc() + source = script.find(source_id) if script is not None else None + target = script.find(target_id) if script is not None else None + if source is not None and getattr(source, "_local", False): + Logger.debug(f"Follow: {what} ignored, the source is local here") + return + try: + instant = float(data.get("seed_ms")) + except (TypeError, ValueError): + instant = None + refuse = None + if script is None or mtc is None: + refuse = "no project or no timecode on this node" + elif source is None or target is None: + refuse = "cue not in the loaded project" + elif instant is None: + refuse = "no instant" + elif self._run_seq is None or data.get("run_seq") != self._run_seq: + refuse = ( + f"not part of this node's run (run_seq {data.get('run_seq')}, " + f"here {self._run_seq})" + ) + if refuse: + Logger.warning(f"Follow: refusing announce {what}: {refuse}") + return + + # Read before taking the table lock: nothing calls into CueHandler or + # the engine while holding it. While a STOP or a load is pending here + # the epochs still belong to the run that is ending: read them later. + arm_epoch = stop_epoch = None + if not self.stop_pending: + arm_epoch = self._ch.arm_epoch() + stop_epoch = self._ch._last_stop_chain_epoch + project_gen = self._get_project_gen() + with self._lock: + old = self._table.get(source_id) + if ( + old is not None + and old.state in _LIVE + and old.run_seq == self._run_seq + and abs(old.instant - instant) <= FOLLOW_INSTANT_MATCH_MS + ): + old.origins.add(origin) + return + entry = _Entry( + source_id=source_id, + target_id=target_id, + instant=instant, + run_seq=self._run_seq, + origins={origin}, + arm_epoch=arm_epoch, + stop_epoch=stop_epoch, + project_gen=project_gen, + ) + self._table[source_id] = entry + + now = mtc.main_tc.milliseconds_exact + late = now - instant + if late > FOLLOW_LATE_ERROR_MS: + Logger.error( + f"Follow: announce {what} arrived {late:.0f}ms after its " + "instant; starting it anyway, in sync with its beginning cut" + ) + elif late > 0: + Logger.warning( + f"Follow: announce {what} arrived {late:.0f}ms after its " + "instant; starting it at once" + ) + Logger.info(f"Follow: received announce {what} at {instant:.0f}ms") + self._spawn(f"FollowPreArm:{source_id}", self._prearm, entry) + self._spawn(f"FollowWait:{source_id}", self._wait_and_dispatch, entry) + + def _on_cancel(self, data: dict) -> None: + source_id = str(data.get("source")) + origin = data.get("origin") + reason = data.get("reason") + if origin == self.node_id: + return + try: + instant = float(data.get("seed_ms")) + except (TypeError, ValueError): + instant = None + what = f"{source_id} at {instant} from {origin} ({reason})" + with self._lock: + e = self._table.get(source_id) + if ( + e is None + or instant is None + or abs(e.instant - instant) > FOLLOW_INSTANT_MATCH_MS + or e.state not in _LIVE + or data.get("run_seq") != e.run_seq + ): + Logger.debug(f"Follow: cancel {what}: nothing pending") + return + if reason == "error" and origin in e.origins and len(e.origins) > 1: + e.origins.discard(origin) + Logger.info(f"Follow: cancel {what}: other owners remain") + return + state = e.state + e.state = "cancelled" + dispatched = (e.cue, e.gen, e.disarm_epoch, e.armed_at, e.started_before) + if state != "dispatched": + Logger.info(f"Follow: cancel {what} applied before the dispatch") + return + self._spawn( + f"FollowStop:{source_id}", self._stop_dispatched, what, reason, *dispatched + ) + + # ------------------------------------------------------------------ + # Receiver threads + # ------------------------------------------------------------------ + + def _is_current(self, e: _Entry) -> bool: + return ( + self._table.get(e.source_id) is e + and e.state in _LIVE + and self._run_seq == e.run_seq + ) + + def _current(self, e: _Entry) -> bool: + with self._lock: + return self._is_current(e) + + def _epochs_ready(self, e: _Entry) -> bool: + """Read the STOP/load epochs for an entry that arrived while a STOP or + a load was pending, once it has run. False while still pending.""" + if e.arm_epoch is not None: + return True + if self.stop_pending: + return False + arm_epoch = self._ch.arm_epoch() + stop_epoch = self._ch._last_stop_chain_epoch + with self._lock: + if e.arm_epoch is None: + e.arm_epoch, e.stop_epoch = arm_epoch, stop_epoch + return True + + def _prearm(self, e: _Entry) -> None: + """Until the instant, arm what this node would start, every + FOLLOW_PREARM_PERIOD_S: `arm()` skips what is loaded, so each round + only arms what became unloaded since -- a cue whose earlier pass has + just ended, or a target enabled meanwhile.""" + + def should_continue(): + return ( + self._current(e) + and self._get_project_gen() == e.project_gen + and self._ch.arm_epoch() == e.arm_epoch + ) + + mtc = self._get_mtc() + try: + while self._current(e) and not self._epochs_ready(e): + if mtc is None or mtc.main_tc.milliseconds_exact >= e.instant: + return + self._prearm_sleep(FOLLOW_PREARM_PERIOD_S) + while should_continue(): + script = self._get_script() + target = script.find(e.target_id) if script is not None else None + cue = self._first_local(target) if target is not None else None + if cue is not None: + self._arm_round(e, cue, should_continue) + if mtc is None or mtc.main_tc.milliseconds_exact >= e.instant: + return + self._prearm_sleep(FOLLOW_PREARM_PERIOD_S) + except Exception as ex: + Logger.error(f"Follow: pre-arm for {e.source_id} failed: {ex}") + + def _arm_round(self, e: _Entry, cue, should_continue) -> None: + walk = _ArmWalk(should_continue=should_continue, epoch=e.arm_epoch) + if not getattr(cue, "loaded", False): + self._ch.arm(cue, init=True, walk=walk) + # arm() reaches an action's target only when it arms the action itself, + # and arm() on a loaded, disabled cue disarms it even while it plays. + if isinstance(cue, ActionCue) and cue.action_type in ("play", "fade_action"): + at = getattr(cue, "_action_target_object", None) + if ( + at is not None + and getattr(at, "enabled", False) + and getattr(at, "_local", False) + and not getattr(at, "loaded", False) + ): + self._ch.arm(at, init=True, walk=walk) + # The lookahead once per cue, so its depth WARNING is not repeated. + if id(cue) not in e.lookahead_done and getattr(cue, "loaded", False): + e.lookahead_done.add(id(cue)) + self._ch._arm_ahead( + cue, should_continue=should_continue, arm_epoch=e.arm_epoch + ) + + def _wait_and_dispatch(self, e: _Entry) -> None: + mtc = self._get_mtc() + script = self._get_script() + if mtc is None or script is None: + return + source = script.find(e.source_id) + target = script.find(e.target_id) + post_ms = 0.0 + try: + post_ms = source.postwait.milliseconds_exact + except Exception: + pass + check_ms = e.instant - post_ms + snapshot = None + while True: + if not self._current(e): + return + now = mtc.main_tc.milliseconds_exact + if post_ms > 0 and snapshot is None and now >= check_ms: + c = self._first_local(target) + snapshot = (c, getattr(c, "_go_generation", 0)) + if now >= e.instant and self._epochs_ready(e): + break + self._sleep(FOLLOW_POLL_S) + + # The yield: a manual GO of the target during the source's postwait + # already started it; the owner does not fire it again either. + if snapshot is not None and snapshot[0] is not None: + c = self._first_local(target) + if c is snapshot[0] and getattr(c, "_go_generation", 0) != snapshot[1]: + Logger.info( + f"Follow: {e.source_id} -> {e.target_id} yielded: " + f"{c.id} was started by a newer GO" + ) + self._set_state(e, "done") + return + + with self._lock: + if not self._is_current(e): + return + e.state = "dispatching" + try: + thread = self._ch.go_from( + target, + mtc, + e.instant, + arm_epoch=e.arm_epoch, + require_stop_epoch=e.stop_epoch, + commit_gate=lambda cue, gen: self._gate(e, cue, gen), + ) + except Exception as ex: + Logger.error( + f"Follow: dispatch of {e.source_id} -> {e.target_id} failed: {ex}" + ) + self._set_state(e, "done", only_from="dispatching") + return + with self._lock: + if e.state == "dispatching": + e.state = "done" + Logger.info( + f"Follow: {e.source_id} -> {e.target_id}: not dispatched " + "here (nothing local to start, or refused for a STOP)" + ) + elif e.state == "dispatched": + Logger.info( + f"Follow: dispatched {getattr(e.cue, 'id', '?')} for " + f"{e.source_id} at {e.instant:.0f}ms" + + ("" if thread is not None else " (refused)") + ) + + def _gate(self, e: _Entry, cue, gen: int) -> bool: + """Evaluated by go() inside its commit section (CueHandler._lock held). + Refuses an entry that was cancelled, replaced or dropped (a STOP or a + load emptied the table), or that belongs to another run.""" + with self._lock: + if not self._is_current(e) or e.state != "dispatching": + return False + e.cue = cue + e.gen = gen + e.disarm_epoch = self._ch._disarm_epoch + e.armed_at = getattr(cue, "_armed_at", None) + if getattr(cue, "_playing", False) and getattr(cue, "_revealed", False): + # Still on stage from an earlier pass: a cancel must treat it + # as started (go() is about to reset its reveal stamp). + e.started_before = getattr(cue, "_revealed_at", None) + e.state = "dispatched" + return True + + def _set_state(self, e: _Entry, state: str, only_from: str | None = None): + with self._lock: + if only_from is None or e.state == only_from: + e.state = state + + def _stop_dispatched( + self, what, reason, cue, gen, disarm_epoch, armed_at, started_before + ): + may_cut = reason in ("stop", "restart") + try: + outcome, age = self._ch.stop_dispatched_follow( + cue, + gen, + disarm_epoch, + armed_at, + may_cut=may_cut, + grace_s=FOLLOW_CANCEL_GRACE_S, + started_before=started_before, + ) + except Exception as ex: + Logger.error(f"Follow: cancel {what}: stopping {cue.id} failed: {ex}") + return + acted = isinstance(cue, (ActionCue, DmxCue)) and age is not None + if outcome == "owned": + Logger.info(f"Follow: cancel {what}: {cue.id} belongs to a newer GO") + elif outcome == "stopped" and age is None: + Logger.info(f"Follow: cancel {what}: stopped {cue.id} before it started") + elif outcome == "stopped": + Logger.warning( + f"Follow: cancel {what}: stopped {cue.id} {age:.2f}s after it " + "started" + ) + else: + Logger.error( + f"Follow: cancel {what} arrived " + + (f"{age:.2f}s " if age is not None else "") + + f"after {cue.id} started; it was left playing" + ) + if acted and outcome != "owned": + Logger.error( + f"Follow: {type(cue).__name__} {cue.id} had already acted (a DMX " + "scene sent, an action executed); that cannot be undone" + ) + + @staticmethod + def _spawn_thread(name: str, fn, *args) -> None: + threading.Thread(target=fn, args=args, name=name, daemon=True).start() diff --git a/src/cuemsengine/cues/loop_cue.py b/src/cuemsengine/cues/loop_cue.py index bb96021d..90cf07c1 100644 --- a/src/cuemsengine/cues/loop_cue.py +++ b/src/cuemsengine/cues/loop_cue.py @@ -25,6 +25,16 @@ CUE_STATUS_UPDATE_HZ = 2 +def _start_of_last_loop(cue, loop_counter: int, on_last_loop) -> None: + """Call on_last_loop at the start of the last of several loops: the + previous iteration has re-based _end_mtc to the final end by now.""" + if on_last_loop is not None and cue.loop > 1 and loop_counter == cue.loop - 1: + try: + on_last_loop() + except Exception as e: + Logger.error(f"Last-loop callback of cue {cue.id} failed: {e}") + + @singledispatch def loop_cue(cue: Cue, mtc: MtcListener): """ @@ -92,7 +102,7 @@ def loop_fadeCue(cue: FadeCue, mtc: MtcListener): @loop_cue.register -def loop_audioCue(cue: AudioCue, mtc: MtcListener): +def loop_audioCue(cue: AudioCue, mtc: MtcListener, on_last_loop=None): """Handle the audio media playback loop. This method manages the playback loop for audio media, including handling @@ -101,6 +111,9 @@ def loop_audioCue(cue: AudioCue, mtc: MtcListener): Args: ossia: The OSC communication interface. mtc: The MIDI Time Code interface. + on_last_loop: called once, at the start of the last of several loops, + when the cue's final end is known (cross-node Auto follow, + 869fc8ytz). Never for a single or an endless loop. """ Logger.info( f"Running audio cue loop {cue.id}, cue.loop={cue.loop}" @@ -122,6 +135,7 @@ def loop_audioCue(cue: AudioCue, mtc: MtcListener): if cue._stop_requested: Logger.info(f"Audio loop {cue.id} cancelled by stop request") return + _start_of_last_loop(cue, loop_counter, on_last_loop) Logger.info( f"Audio loop iteration starting: loop_counter={loop_counter}," f"cue.loop={cue.loop}" @@ -260,11 +274,12 @@ def loop_dmxCue(cue: DmxCue, mtc: MtcListener): @loop_cue.register -def loop_videoCue(cue: VideoCue, mtc: MtcListener): +def loop_videoCue(cue: VideoCue, mtc: MtcListener, on_last_loop=None): """Handle the video media playback loop. Manages looping behavior for all layers in cue._layer_ids, updating offset via the single VideoClient in cue._osc. + on_last_loop: as for loop_audioCue. """ Logger.info( f"Running video cue loop {cue.id}, cue.loop={cue.loop}" @@ -287,19 +302,24 @@ def loop_videoCue(cue: VideoCue, mtc: MtcListener): layer_ids = getattr(cue, "_layer_ids", []) - # Tell the videocomposer this is a looping cue so it wraps frames at - # the - # loop boundary (instead of clamping to the last frame). - for layer_id in layer_ids: - try: - cue._osc.set_value(f"/videocomposer/layer/{layer_id}/loop", 1) - except Exception as e: - Logger.error(f"Loop enable failed for layer {layer_id}: {e}") + # Tell the videocomposer to wrap frames at the loop boundary (instead + # of clamping to the last frame) ONLY for a cue that really repeats. + # A play-once cue must clamp: the videocomposer runs its display + # latency (33 ms) ahead of MTC, so with wraparound on it reaches end + # of file before the engine hides the layer and shows frame 0 again + # (869fa89uh). + if cue.loop != 1: + for layer_id in layer_ids: + try: + cue._osc.set_value(f"/videocomposer/layer/{layer_id}/loop", 1) + except Exception as e: + Logger.error(f"Loop enable failed for layer {layer_id}: {e}") while cue.loop < 1 or loop_counter < cue.loop: if cue._stop_requested: Logger.info(f"Video loop {cue.id} cancelled by stop request") return + _start_of_last_loop(cue, loop_counter, on_last_loop) # Future: uncomment to enable percentage progress updates. # last_status_update = 0.0 while mtc.main_tc.milliseconds_rounded < cue._end_mtc.milliseconds_rounded: @@ -353,6 +373,20 @@ def loop_videoCue(cue: VideoCue, mtc: MtcListener): except Exception as e: Logger.error(f"Offset send failed for layer {layer_id}: {e}") + # Last pass of a counted loop: stop wrapping (after the new + # offset, so the layer never clamps mid-boundary) so the end + # of this pass holds the last frame like a play-once cue. + if cue.loop >= 1 and loop_counter + 1 >= cue.loop: + for layer_id in layer_ids: + try: + cue._osc.set_value( + f"/videocomposer/layer/{layer_id}/loop", 0 + ) + except Exception as e: + Logger.error( + f"Loop disable failed for layer {layer_id}: {e}" + ) + Logger.info(f"Loop FINISHED: loop_counter={loop_counter}, cue.loop={cue.loop}") except AttributeError: diff --git a/src/cuemsengine/cues/run_cue.py b/src/cuemsengine/cues/run_cue.py index d1c7368e..fb7dff3e 100644 --- a/src/cuemsengine/cues/run_cue.py +++ b/src/cuemsengine/cues/run_cue.py @@ -137,6 +137,50 @@ def run_actionCue(cue: ActionCue, mtc: MtcListener, frozen_mtc_ms: float = None) return +def _verify_audio_wiring_at_go(cue, mixer, player_name: str, selected_outputs: list): + """Check a player's mixer wiring at GO and fix it edge by edge. + + Never a full rewire (869fbyjzx): a GO can reach this while the cue is + audible (a fresh GO, or a 'play' action, on a cue that is still + playing), and connect_player_to_outputs disconnects every edge first — + it would cut the healthy channels too. Strays (RtAudio's auto-connect to + system:playback that an early arm-time wiring missed, 869fcvz85) are + removed one by one; missing mixer edges are added one by one. + """ + diff = mixer.player_connection_diff( + player_name=player_name, + player_output_prefix="outport", + selected_outputs=selected_outputs, + ) + if diff is None: + Logger.error( + f"Audio cue {cue.id}: no mixer input for its outputs at GO " + f"({selected_outputs}) — cue will be SILENT despite showing " + f"armed (mixer inputs unavailable)." + ) + return + missing, stray = diff + if not missing and not stray: + Logger.debug(f"Audio cue {cue.id}: graph already wired, skipping connect") + return + Logger.warning( + f"Audio cue {cue.id}: graph not wired correctly at GO " + f"(missing: {missing}; stray: {stray}); repairing edge by edge" + ) + connected_ok, strays_left = mixer.repair_player_connections(missing, stray) + if not connected_ok: + Logger.error( + f"Audio cue {cue.id}: mixer repair failed at GO — cue will be " + f"SILENT despite showing armed (a mixer connection could not be " + f"made)." + ) + if strays_left: + Logger.error( + f"Audio cue {cue.id}: stray edge(s) still connected after repair: " + f"{strays_left} — the cue may sound doubled and outside the mixer." + ) + + @run_cue.register def run_audioCue(cue: AudioCue, mtc, frozen_mtc_ms: float = None): """ @@ -222,30 +266,7 @@ def run_audioCue(cue: AudioCue, mtc, frozen_mtc_ms: float = None): ) return - if mixer.player_connections_correct( - player_name=player_name, - player_output_prefix="outport", - selected_outputs=selected_outputs, - ): - Logger.debug( - f"Audio cue {cue.id}: graph already wired, skipping connect" - ) - else: - Logger.warning( - f"Audio cue {cue.id}: graph not wired correctly at GO; " - f"repairing via connect_player_to_outputs" - ) - repaired = mixer.connect_player_to_outputs( - player_name=player_name, - player_output_prefix="outport", - selected_outputs=selected_outputs, - ) - if repaired is False: - Logger.error( - f"Audio cue {cue.id}: mixer repair failed at GO — " - f"cue will be SILENT despite showing armed (player " - f"ports missing or mixer inputs unavailable)." - ) + _verify_audio_wiring_at_go(cue, mixer, player_name, selected_outputs) except Exception as e: Logger.warning(f"Could not validate/connect player to mixer: {e}") diff --git a/src/cuemsengine/players/AudioMixer.py b/src/cuemsengine/players/AudioMixer.py index fa1ee30c..81a57d32 100644 --- a/src/cuemsengine/players/AudioMixer.py +++ b/src/cuemsengine/players/AudioMixer.py @@ -3,6 +3,7 @@ # SPDX-FileContributor: Adrià Masip # SPDX-FileContributor: Ion Reguera +import math from time import sleep from cuemsutils.log import Logger, logged @@ -242,6 +243,7 @@ def connect_player_to_outputs( max_retries: int = 30, retry_delay: float = 0.5, should_abort=None, + ready=None, ): """ Connect a player to specific system outputs based on cue configuration. @@ -266,6 +268,33 @@ def connect_player_to_outputs( caller passes "the player process has exited": its ports can never register then (869f9wqpn -- a STOP/load kills the player mid-wait). It does NOT shorten the wait for a live process. + ready: optional threading.Event the player sets once it reports + itself started (Player.ready, its "[OK] RUNNING!" line). When + given, the wiring waits for it before looking at the ports: the + ports exist before the player has finished starting, and RtAudio + auto-connects them to system:playback only when its stream starts. + Wiring earlier finds nothing to disconnect, and the auto-connect + lands afterwards and stays - the cue then sounds through the mixer + AND straight to the outputs (869fbyjzx / 869fcvz85). The ready wait + and the port wait share one budget, today's port-wait ceiling. + A player that never reports ready is wired on port presence, with + a WARNING. + + KNOWN LIMIT (869fbyjzx): this makes an audio arm correct and as fast as the + player allows, about 0.47 s cold (0.35 s warm), most of it the player's + own start-up. A GO that reaches a cue less than that after its arm + started still waits for the arm and fires LATE by the difference. On + test2 (a node audio cue behind another node's pause, second GO after + the hand-off): 0.3 s -> ~0.2 s late; 0.5 s and later -> on time. + Only arming BEFORE the hand-off removes it. PLAN B, not built because + no real show hits it today (sala1's node segments are video only; the + cost is players and layers held for the whole pause): arm the first + local segment at load even behind another node's pause, and the next + one after each GO ("Part B", Plans/2026-10-01-engine-prearm-past- + pauses-and-inventory.md; measured cost ~15 MB per held audio player, + ~40 MB GPU per held 1080p video layer). A cheaper variant is to + pre-launch players. Revisit if a venue reports a late node audio cue + after a fast double GO. Returns: True if every required player→mixer connection was made, False if @@ -286,12 +315,6 @@ def connect_player_to_outputs( channel_0_output = f"{player_name}:{player_output_prefix} 0" channel_1_output = f"{player_name}:{player_output_prefix} 1" - # Build output→input mapping from the configured audio_outputs list - output_to_input = { - name: f"{self.client_name}:input_{i+1}" - for i, name in enumerate(self.audio_outputs) - } - # Fail fast when there is no JACK client at all. The retry loop below # exists for a TRANSIENT race (player ports registering a beat after # the process spawns); a missing JACK server is PERMANENT for this arm @@ -311,6 +334,55 @@ def connect_player_to_outputs( ) return False + # Wait for the player to report itself started (869fbyjzx). AFTER the + # no-JACK fail-fast above: a JACK-stubbed host (the test2 controller) + # must still return at once. Counted slices, not a monotonic deadline, + # bound the wait, so a test can patch ready.wait. Whatever this phase + # uses comes off the port wait below: one budget for both. + port_attempts = max_retries + if ready is not None: + ready_slice = 0.05 + # Today's port wait sleeps between its checks, (max_retries - 1) + # times: that total (14.5 s by default) is the whole budget. + budget_s = max(0, max_retries - 1) * retry_delay + ready_slices = max(1, int(round(budget_s / ready_slice))) + ready_started = monotonic() + slices_used = 0 + got_ready = False + for _ in range(ready_slices): + if ready.wait(ready_slice): + got_ready = True + break + slices_used += 1 + if should_abort is not None and should_abort(): + Logger.warning( + f"Player process for {player_name} exited before " + f"reporting RUNNING (waited " + f"{monotonic() - ready_started:.3f}s) - killed by a " + "STOP/load, or crashed. Not waiting any longer." + ) + return False + if got_ready: + Logger.info( + f"Audio player {player_name} reported RUNNING after " + f"{monotonic() - ready_started:.3f}s" + ) + else: + Logger.warning( + f"Audio player {player_name} never reported RUNNING in " + f"{monotonic() - ready_started:.1f}s - wiring on port " + "presence (old or unusual player build)" + ) + if retry_delay > 0: + # Round UP (to 6 places first, against float noise): the ready + # wait may never leave the port wait more than the budget. + spent_attempts = math.ceil( + round(slices_used * ready_slice / retry_delay, 6) + ) + port_attempts = max(1, max_retries - spent_attempts) + else: + port_attempts = 1 + # Wait for player JACK ports to be available. # NOTE: gate ONLY on port_exists(); get_connections() returns [] (not # None) for a missing port, so the old 'connections is not None' guard @@ -328,12 +400,12 @@ def connect_player_to_outputs( # already cost a real show. Log the success path so the fleet's own # journals can answer that instead of another guess. wait_started = monotonic() - for attempt in range(max_retries): + for attempt in range(port_attempts): if self.conn_man.port_exists(channel_0_output): Logger.info( f"JACK port {channel_0_output} registered after " f"{monotonic() - wait_started:.3f}s (attempt {attempt + 1}" - f"/{max_retries})" + f"/{port_attempts})" ) break if should_abort is not None and should_abort(): @@ -344,20 +416,20 @@ def connect_player_to_outputs( f"Player process for {player_name} exited before " f"registering its JACK ports (waited " f"{monotonic() - wait_started:.3f}s, attempt {attempt + 1}" - f"/{max_retries}) - killed by a STOP/load, or crashed. " + f"/{port_attempts}) - killed by a STOP/load, or crashed. " "Not waiting any longer." ) return False - if attempt < max_retries - 1: + if attempt < port_attempts - 1: Logger.debug( f"Waiting for JACK port {channel_0_output} (attempt" - f"{attempt + 1}/{max_retries})" + f"{attempt + 1}/{port_attempts})" ) sleep(retry_delay) else: Logger.warning( f"JACK port {channel_0_output} not available after" - f"{max_retries} attempts" + f"{port_attempts} attempts" ) return False @@ -388,41 +460,26 @@ def connect_player_to_outputs( for connection in channel_1_connections: self.conn_man.disconnect_by_name(channel_1_output, connection) - # Determine which mixer inputs to connect to - target_inputs = [] - for output in selected_outputs: - if output in output_to_input: - mixer_input = output_to_input[output] - if self.conn_man.port_exists(mixer_input): - target_inputs.append(mixer_input) - else: - Logger.warning(f"Mixer input {mixer_input} does not exist") - - if not target_inputs: + expected = self._expected_edges( + player_name, + player_output_prefix, + selected_outputs, + is_stereo, + log_missing_inputs=True, + ) + if not expected: Logger.error(f"No valid mixer inputs found for outputs: {selected_outputs}") return False Logger.info( f"Connecting {player_name} to outputs:" - f"{selected_outputs} -> {target_inputs}" + f"{selected_outputs} -> {[dst for _src, dst in expected]}" ) - # Fan-out routing: treat target_inputs as alternating L/R pairs. - # Even-indexed targets (0, 2, 4 …) receive outport 0 (L channel). - # Odd-indexed targets (1, 3, 5 …) receive outport 1 (R channel) - # or outport 0 again when the player is mono. - # This covers 1, 2 or any number of outputs uniformly. all_connected = True - for i, mixer_input in enumerate(target_inputs): - if i % 2 == 0: - Logger.debug(f"L → {mixer_input}") - ok = self.conn_man.connect_by_name(channel_0_output, mixer_input) - elif is_stereo: - Logger.debug(f"R → {mixer_input}") - ok = self.conn_man.connect_by_name(channel_1_output, mixer_input) - else: - Logger.debug(f"Mono → {mixer_input}") - ok = self.conn_man.connect_by_name(channel_0_output, mixer_input) + for src, dst in expected: + Logger.debug(f"{src} → {dst}") + ok = self.conn_man.connect_by_name(src, dst) all_connected = all_connected and ok if not all_connected: @@ -432,59 +489,140 @@ def connect_player_to_outputs( ) return all_connected - def player_connections_correct( + def _expected_edges( self, player_name: str, - player_output_prefix: str = "outport", - selected_outputs: list = None, - ) -> bool: - """ - Verify the player's outputs are wired exactly as - connect_player_to_outputs would wire them. - - Mirrors the routing in connect_player_to_outputs: same output_to_input - mapping (built from audio_outputs), same alternating L/R fan-out walk, - same mono branch (outport 0 → both pair members when channel_1 absent). - - Returns False if any expected edge is missing, points elsewhere, or if - outport 0 itself does not exist (subprocess gone). Caller decides - whether to repair via connect_player_to_outputs or abort the cue. + player_output_prefix: str, + selected_outputs: list, + is_stereo: bool, + log_missing_inputs: bool = False, + ) -> list: + """The (player outport, mixer input) edges a player should have. + + The ONE copy of the routing, used by the arm-time wiring + (connect_player_to_outputs), the GO-time check + (player_connection_diff) and the tests, so they cannot drift apart + (869fbyjzx). Selected outputs map to mixer inputs through + audio_outputs; inputs that do not exist are dropped, which shifts the + L/R pairing exactly as the wiring does. The targets are treated as + alternating L/R pairs: even-indexed targets (0, 2, 4 ...) get outport + 0, odd-indexed ones outport 1, or outport 0 again on a mono player. + This covers 1, 2 or any number of outputs uniformly. + + Returns [] when no mixer input resolves. """ if not selected_outputs: selected_outputs = ["system:playback_1", "system:playback_2"] - channel_0_output = f"{player_name}:{player_output_prefix} 0" channel_1_output = f"{player_name}:{player_output_prefix} 1" - - if not self.conn_man.port_exists(channel_0_output): - return False - - is_stereo = self.conn_man.port_exists(channel_1_output) - output_to_input = { - name: f"{self.client_name}:input_{i+1}" + name: f"{self.client_name}:input_{i + 1}" for i, name in enumerate(self.audio_outputs) } - target_inputs = [] for output in selected_outputs: if output in output_to_input: mixer_input = output_to_input[output] if self.conn_man.port_exists(mixer_input): target_inputs.append(mixer_input) - - if not target_inputs: - return False - + elif log_missing_inputs: + Logger.warning(f"Mixer input {mixer_input} does not exist") + edges = [] for i, mixer_input in enumerate(target_inputs): if i % 2 == 0 or not is_stereo: - expected_src = channel_0_output + edges.append((channel_0_output, mixer_input)) else: - expected_src = channel_1_output - if not self.conn_man.is_connected(expected_src, mixer_input): - return False + edges.append((channel_1_output, mixer_input)) + return edges - return True + def player_connection_diff( + self, + player_name: str, + player_output_prefix: str = "outport", + selected_outputs: list = None, + ): + """Compare a player's outport edges with the expected wiring. + + Returns (missing, stray), two lists of (source, destination) edges: + missing = expected edges that are not connected; stray = edges on the + player's outports that are not expected (e.g. RtAudio's own + auto-connect to system:playback, 869fcvz85). An edge is never in + both. Returns None when the graph cannot be wired at all: outport 0 + does not exist (the subprocess is gone) or no mixer input resolves — + callers must treat None as a silent cue, never as "correct". + + One get_connections per outport (outport 1 only on a stereo player): + this runs on the GO path before /offset. + """ + channel_0_output = f"{player_name}:{player_output_prefix} 0" + channel_1_output = f"{player_name}:{player_output_prefix} 1" + if not self.conn_man.port_exists(channel_0_output): + return None + is_stereo = self.conn_man.port_exists(channel_1_output) + expected = self._expected_edges( + player_name, player_output_prefix, selected_outputs, is_stereo + ) + if not expected: + return None + ports = [channel_0_output] + ([channel_1_output] if is_stereo else []) + present = {port: list(self.conn_man.get_connections(port)) for port in ports} + missing = [(src, dst) for src, dst in expected if dst not in present[src]] + wanted = set(expected) + stray = [ + (port, dst) + for port in ports + for dst in present[port] + if (port, dst) not in wanted + ] + return missing, stray + + def player_connections_correct( + self, + player_name: str, + player_output_prefix: str = "outport", + selected_outputs: list = None, + ) -> bool: + """True when the player is wired exactly as connect_player_to_outputs + wires it: every expected edge present and nothing else on its + outports. False on a missing edge, a stray edge, a missing outport 0 + (subprocess gone) or no mixer input. See player_connection_diff. + """ + diff = self.player_connection_diff( + player_name, player_output_prefix, selected_outputs + ) + return diff is not None and not diff[0] and not diff[1] + + def repair_player_connections(self, missing: list, stray: list): + """Fix a player's wiring edge by edge, never by a full rewire. + + A GO can reach this while the cue is audible (a fresh GO or a 'play' + action on a playing cue), so a working mixer edge is never + disconnected: strays are disconnected one by one, missing edges + connected one by one (869fbyjzx). + + Each stray is re-checked just before its disconnect: one already gone + (a stale diff, a re-arm wiring the same player) is skipped, because a + failed disconnect resets the SHARED JACK client under any arm wiring + at the same moment (JackConnectionManager.disconnect_by_name). + + Returns (connected_ok, strays_left): whether every missing edge got + connected, and the strays whose disconnect failed. + """ + strays_left = [] + for src, dst in stray: + if not self.conn_man.is_connected(src, dst): + continue + if not self.conn_man.disconnect_by_name(src, dst): + # Another thread (a re-arm wiring the same player) may have + # removed it between our check and our disconnect: then it is + # gone, not a survivor. + if self.conn_man.is_connected(src, dst): + strays_left.append((src, dst)) + connected_ok = True + for src, dst in missing: + ok = self.conn_man.connect_by_name(src, dst) + connected_ok = connected_ok and ok + return connected_ok, strays_left @logged def disconnect_player( diff --git a/src/cuemsengine/players/Player.py b/src/cuemsengine/players/Player.py index f20604b4..e45148e9 100644 --- a/src/cuemsengine/players/Player.py +++ b/src/cuemsengine/players/Player.py @@ -1,14 +1,22 @@ # SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL # SPDX-License-Identifier: GPL-3.0-or-later # SPDX-FileContributor: Adrià Masip +# SPDX-FileContributor: Ion Reguera import os from subprocess import PIPE, STDOUT, Popen -from threading import Thread +from threading import Event, Thread from time import sleep from cuemsutils.log import Logger, logged +# The line a CUEMS player prints on stdout once it is fully started (the +# cuems-audioplayer calls its SIGUSR1 handler from main() right after the +# AudioPlayer object is built and its stream runs: "to let everyone know that +# we are running"). Matched as a substring: the line starts with the player's +# logger slug, e.g. b"[Cuems:d] [OK] RUNNING!\n". +READY_LINE = b"[OK] RUNNING!" + class Player(Thread): """Base class for all players in the system. @@ -36,6 +44,15 @@ def __init__(self, daemon: bool = True): self.started = False self.status = "starting" # 'starting', 'running', 'failed' self.error = None + # Set when the subprocess prints READY_LINE. An audio arm waits on it + # before wiring the player to the mixer: the player's JACK ports exist + # before it has finished starting, and wiring them that early leaves + # RtAudio's own auto-connect to system:playback in place (869fbyjzx). + # Known limit: waiting for it makes an audio arm ~0.47 s cold, so a GO + # that comes sooner after the arm began is still late. Plan B (arm + # before the hand-off) is described in AudioMixer.connect_player_to_ + # outputs and the 869fbyjzx plan; it is not built. + self.ready = Event() def run(self): raise NotImplementedError @@ -48,6 +65,9 @@ def call_subprocess(self, call_args): Sets status to 'running' on success, 'failed' on error. """ try: + # This run starts not ready: an Event left set by an earlier run of + # the same Player object would pass the audio wiring's gate at once. + self.ready.clear() my_env = os.environ.copy() my_env["DISPLAY"] = ":0" self.p = Popen(call_args, stdout=PIPE, stderr=STDOUT, env=my_env) @@ -57,6 +77,8 @@ def call_subprocess(self, call_args): while self.p.poll() is None: for line in stdout_lines_iterator: Logger.debug(f"Subprocess output: {line}") + if READY_LINE in line: + self.ready.set() # Prevent CPU spinning when subprocess has no output sleep(0.01) diff --git a/src/cuemsengine/players/PlayerHandler.py b/src/cuemsengine/players/PlayerHandler.py index 4ea1974e..075c98e7 100644 --- a/src/cuemsengine/players/PlayerHandler.py +++ b/src/cuemsengine/players/PlayerHandler.py @@ -4,7 +4,9 @@ # SPDX-FileContributor: Ion Reguera import os +import pwd import shutil +import signal import subprocess from functools import partial from threading import RLock @@ -42,6 +44,139 @@ def _positive_int(value) -> bool: return isinstance(value, int) and not isinstance(value, bool) and value > 0 +# --------------------------- +# Orphan sweeps (869evtdf7) +# --------------------------- +# Killing the players a previous engine left behind is hygiene, not a +# precondition: nothing here may raise into the caller. An exception from the +# audioplayer sweep used to abort a project load half-way through its teardown +# (old project torn down, new one never armed), and one from the mixer sweep +# left the node without a mixer. + +# +# The sweeps list only processes of the engine's own user (as the node-engine +# unit's own `pkill -u cuems` does): JACK is a per-user server, so another +# user's process cannot hold a client name on ours, and killing it would only +# get EPERM. The audioplayer pattern is a POSIX ERE (pgrep -f matches it +# against the space-joined cmdline) anchored on argv[0], whose basename must +# be exactly the binary: the engine spawns players with argv[0] = the +# configured path, and a `tail -f …/cuems-audioplayer.log` must not be killed. +# The mixer pattern was already narrowed (869cwpkz4); its install name varies. +AUDIOPLAYER_ORPHAN_PATTERN = r"^([^ ]*/)?cuems-audioplayer( |$)" +MIXER_ORPHAN_PATTERN = "jack-volume -c" + +# Basenames the orphan cleanups (these sweeps and the node-engine unit's +# ExecStartPre/ExecStopPost pkill, cuems-common) recognise, per settings.xml +# key. A configured binary with any other name escapes every cleanup. +ORPHAN_BINARY_NAMES = { + "audioplayer": ("cuems-audioplayer",), + "audiomixer": ("jack-volume", "cuems-jack-volume"), + "dmxplayer": ("cuems-dmxplayer",), +} + + +def check_orphan_binary_names(node_conf: dict) -> list[str]: + """Warn about configured player binaries the orphan cleanups cannot see. + + Returns the settings keys whose path basename is not a known name. A + missing key is skipped: not every node configures every player. + """ + unknown = [] + for key, names in ORPHAN_BINARY_NAMES.items(): + entry = node_conf.get(key) if isinstance(node_conf, dict) else None + path = entry.get("path") if isinstance(entry, dict) else None + if not path: + continue + base = os.path.basename(str(path)) + if base not in names: + unknown.append(key) + Logger.warning( + f"{key}.path basename '{base}' is not one the orphan cleanup " + f"knows ({', '.join(names)}): orphaned {key} processes from an " + f"earlier engine run will not be cleaned up" + ) + return unknown + + +def _orphan_pids(pattern: str, label: str) -> list[int]: + """PIDs of our own user whose command line matches `pattern` + (pgrep -u -f). Never raises. + + pgrep exits 1 when nothing matches: the normal case, silent. Any other + non-zero exit (bad option or pattern, fatal error) is logged, so a sweep + that stops working says so instead of going inert. + """ + try: + result = subprocess.run( + ["pgrep", "-u", str(os.geteuid()), "-f", pattern], + capture_output=True, + text=True, + ) + except Exception as e: + Logger.warning(f"Orphan {label} sweep skipped: cannot run pgrep: {e!r}") + return [] + if result.returncode == 1: + return [] + if result.returncode != 0: + Logger.warning( + f"Orphan {label} sweep skipped: pgrep failed with rc " + f"{result.returncode}: {(result.stderr or '').strip()}" + ) + return [] + pids = [] + for line in (result.stdout or "").split("\n"): + line = line.strip() + if not line: + continue + try: + pids.append(int(line)) + except ValueError: + Logger.warning(f"Orphan {label} sweep: ignoring pgrep line {line!r}") + return pids + + +def _pid_owner(pid: int) -> str: + """Owner of `pid` as "name(uid)", plus the effective user when it + differs; "?" when it cannot be read (the process may be gone).""" + + def name(uid: int) -> str: + try: + return f"{pwd.getpwuid(uid).pw_name}({uid})" + except Exception: + return f"({uid})" + + try: + with open(f"/proc/{pid}/status") as status: + for line in status: + if line.startswith("Uid:"): + real, effective = (int(x) for x in line.split()[1:3]) + owner = name(real) + if effective != real: + owner += f", euid {name(effective)}" + return owner + except Exception: + pass + return "?" + + +def _kill_orphan(pid: int, label: str) -> None: + """SIGKILL an orphaned `label` process. Never raises: an orphan the + engine cannot signal is reported and left alone.""" + Logger.warning(f"Killing orphaned {label} process {pid}") + try: + os.kill(pid, signal.SIGKILL) + except ProcessLookupError: + pass # already gone + except PermissionError: + Logger.warning( + f"Cannot kill orphaned {label} process {pid} (owner " + f"{_pid_owner(pid)}): not permitted. Leaving it; if it holds a " + f"JACK client name, a cue may stay silent" + ) + except Exception as e: + Logger.warning(f"Cannot kill orphaned {label} process {pid}: {e!r}") + + class PlayerHandler: """ This class is responsible for handling and generating player objects. @@ -335,7 +470,10 @@ def cleanup_zombie_jack_clients(self) -> int: with tracked players in _audio_players_by_id. Unmatched ports are zombies left by crashed processes — disconnect them from the mixer. - Called on project load to clear stale state from previous runs. + Called on project load to clear stale state from previous runs. Like + the orphan sweeps it is hygiene, so it never raises into the load + (869evtdf7): a JACK error skips the cleanup with a warning, and audio + cues then fail loudly at their own arm. Returns: Number of zombie clients found and cleaned up. @@ -343,9 +481,15 @@ def cleanup_zombie_jack_clients(self) -> int: if self._audio_mixer is None: return 0 - all_ports = self._audio_mixer.conn_man.get_ports( - pattern="Audio_Player-.*", is_audio=True, is_output=True - ) + try: + all_ports = self._audio_mixer.conn_man.get_ports( + pattern="Audio_Player-.*", is_audio=True, is_output=True + ) + except Exception as e: + Logger.warning( + f"JACK not reachable, zombie JACK client cleanup skipped: {e!r}" + ) + return 0 if not all_ports: return 0 @@ -383,16 +527,11 @@ def kill_orphaned_audio_processes(self): On engine restart, previously spawned audioplayer processes survive because they are independent subprocesses. The new engine has no reference to them, so they steal JACK client names and cause silence. - """ - import os - import signal - result = subprocess.run( - ["pgrep", "-f", "cuems-audioplayer"], - capture_output=True, - text=True, - ) - if result.returncode != 0: + Runs in the middle of a project load, so it never raises (869evtdf7). + """ + pids = _orphan_pids(AUDIOPLAYER_ORPHAN_PATTERN, "audioplayer") + if not pids: return tracked_pids = set() @@ -401,16 +540,9 @@ def kill_orphaned_audio_processes(self): if player and player.p: tracked_pids.add(player.p.pid) - for pid_str in result.stdout.strip().split("\n"): - if not pid_str: - continue - pid = int(pid_str) + for pid in pids: if pid not in tracked_pids: - Logger.warning(f"Killing orphaned audioplayer process {pid}") - try: - os.kill(pid, signal.SIGKILL) - except ProcessLookupError: - pass + _kill_orphan(pid, "audioplayer") def kill_orphaned_mixer_processes(self): """Kill jack-volume mixer processes not tracked by this engine. @@ -427,32 +559,21 @@ def kill_orphaned_mixer_processes(self): rather than the bare word, so an operator's `tail -f .../jack-volume.log` or a grep isn't caught and killed. Covers both the plain and "cuems-jack-volume" install names. - """ - import os - import signal - result = subprocess.run( - ["pgrep", "-f", "jack-volume -c"], - capture_output=True, - text=True, - ) - if result.returncode != 0: + Never raises (869evtdf7): an orphan it cannot kill used to stop the + mixer from starting, leaving every audio cue on the node silent. + """ + pids = _orphan_pids(MIXER_ORPHAN_PATTERN, "jack-volume mixer") + if not pids: return tracked_pid = None if self._audio_mixer is not None and getattr(self._audio_mixer, "p", None): tracked_pid = self._audio_mixer.p.pid - for pid_str in result.stdout.strip().split("\n"): - if not pid_str: - continue - pid = int(pid_str) + for pid in pids: if pid != tracked_pid: - Logger.warning(f"Killing orphaned jack-volume mixer process {pid}") - try: - os.kill(pid, signal.SIGKILL) - except ProcessLookupError: - pass + _kill_orphan(pid, "jack-volume mixer") # --------------------------- # Audio Cue Management @@ -546,6 +667,15 @@ def new_audio_output(self, cue: AudioCue) -> None: ) else: Logger.info(f"Connecting {player_name} to outputs: {selected_outputs}") + ready = getattr(player, "ready", None) + if ready is None: + # Every Player has one. Without it the wiring would fall + # back to port presence and the doubled-audio race (869fcvz85) + # would come back unnoticed. + Logger.warning( + f"Audio player {player_name} has no ready event - wiring " + "on port presence (the auto-connect race is possible)" + ) connected = self._audio_mixer.connect_player_to_outputs( player_name=player_name, player_output_prefix="outport", @@ -555,6 +685,10 @@ def new_audio_output(self, cue: AudioCue) -> None: # soon as the process is gone instead of holding this # cue's arm for the full ~15 s (869f9wqpn). should_abort=lambda: _process_exited(player), + # Wire only once the player reports itself started: its + # ports exist earlier, before RtAudio's auto-connect, + # which an earlier wiring would leave in place (869fbyjzx). + ready=ready, ) if connected is False: # Route to the mixer failed: the cue would show armed/green diff --git a/tests/fixtures.py b/tests/fixtures.py index 9762609c..112fb89f 100644 --- a/tests/fixtures.py +++ b/tests/fixtures.py @@ -1,6 +1,7 @@ # SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL # SPDX-License-Identifier: GPL-3.0-or-later # SPDX-FileContributor: Adrià Masip +# SPDX-FileContributor: Ion Reguera from pathlib import Path from unittest.mock import PropertyMock, patch @@ -289,6 +290,8 @@ def mock_call_subprocess(self, call_args): self.pid = id(self) self.status = "running" self.error = None + # A real player reports itself started on stdout (Player.ready). + self.ready.set() with patch( "cuemsengine.players.Player.Player.call_subprocess", @@ -406,6 +409,8 @@ def mock_call_subprocess(self, call_args): self.pid = id(self) self.status = "running" self.error = None + # A real player reports itself started on stdout (Player.ready). + self.ready.set() # Patch all PlayerClient subclasses AND Player.call_subprocess with ( diff --git a/tests/test_arm_publish_gate.py b/tests/test_arm_publish_gate.py index c03e116b..a981f517 100644 --- a/tests/test_arm_publish_gate.py +++ b/tests/test_arm_publish_gate.py @@ -696,7 +696,7 @@ def test_go_hands_its_epoch_to_the_fallback_arm_and_the_lookahead(self): ch._arm_ahead = MagicMock() epoch = ch._disarm_epoch - def arm(c, init=False, walk=None, epoch=None): + def arm(c, init=False, walk=None, epoch=None, wait_report=None): c.loaded = True ch.arm = MagicMock(side_effect=arm) @@ -713,7 +713,7 @@ def test_a_stop_during_the_fallback_arm_returns_none_instead_of_raising(self): cue = _cue() cue._stop_requested = True - def arm(c, init=False, walk=None, epoch=None): + def arm(c, init=False, walk=None, epoch=None, wait_report=None): ch.stop_all_cues() # and the arm, stale now, loads nothing ch.arm = MagicMock(side_effect=arm) diff --git a/tests/test_arm_wait_messages.py b/tests/test_arm_wait_messages.py new file mode 100644 index 00000000..0e7b843a --- /dev/null +++ b/tests/test_arm_wait_messages.py @@ -0,0 +1,224 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera +"""869fbyjzx: honest log lines when a cue is not armed at GO. + +A GO that finds its cue still being armed (a pre-arm, an audio player still +starting) used to log "this should not happen, pre-arm may have failed. +Re-arming as fallback." It had not failed: it was in flight, and the GO waited +for it. The two sites — go() and the cue's own thread (go_threaded) — now say +which case it is, and report the wait from what arm() actually did. + +True fallbacks keep "not loaded at go() time" / "not loaded at dispatch" and +"Re-arming as fallback": the harnesses and an acceptance criterion count them. +""" + +import logging +import sys +from threading import Lock +from types import SimpleNamespace +from unittest.mock import MagicMock, Mock, patch + +sys.modules.setdefault("cuemsutils.tools.Osc_nodes_hub", Mock()) + +from cuemsutils.tools.CTimecode import CTimecode # noqa: E402 + +from cuemsengine.cues.CueHandler import CueHandler # noqa: E402 + +HELD = "held by PreArm:abc for 0.3s" + + +def _cue(cid="c1"): + return SimpleNamespace( + id=cid, + _local=True, + enabled=True, + loaded=False, + post_go="pause", + _go_generation=1, + ) + + +def _arm_that(waited_s=None, holder="PreArm:abc"): + """An arm() stand-in that loads the cue and, when waited_s is given, + reports a wait the way the real arm() does.""" + + def arm(cue, init=False, walk=None, epoch=None, wait_report=None): + if waited_s is not None and wait_report is not None: + wait_report["waited_s"] = waited_s + wait_report["holder"] = holder + cue.loaded = True + return True + + return MagicMock(side_effect=arm) + + +def _go_handler(in_flight, arm): + ch = object.__new__(CueHandler) + ch._lock = Lock() + ch._disarm_epoch = 0 + ch._chain_epoch = 0 + ch._last_stop_chain_epoch = 0 + ch._stamp_skipped_locked = MagicMock() + ch._arm_ahead = MagicMock() + ch.go_threaded = MagicMock() + ch.describe_arm_in_flight = MagicMock(return_value=in_flight) + ch.arm = arm + return ch + + +def _go(ch, cue, chain_epoch=None): + with patch("cuemsengine.cues.CueHandler.Thread") as thread: + ch.go(cue, MagicMock(), 0.0, chain_epoch=chain_epoch) + return thread + + +class TestGoSite: + def test_a_fresh_go_on_an_arm_in_flight_waits_and_says_so(self, caplog): + cue = _cue() + ch = _go_handler(HELD, _arm_that(waited_s=0.41)) + with caplog.at_level(logging.INFO): + _go(ch, cue) + text = caplog.text + assert f"is still being armed ({HELD}) at go() time" in text + assert "waiting for the arm in progress" in text + assert "waited 0.41s at go() time" in text + assert "Re-arming as fallback" not in text + assert "pre-arm may have failed" not in text + + def test_a_fresh_go_with_nothing_in_flight_is_a_fallback(self, caplog): + cue = _cue() + ch = _go_handler(None, _arm_that()) + with caplog.at_level(logging.INFO): + _go(ch, cue) + warnings = [r for r in caplog.records if r.levelno == logging.WARNING] + assert any( + "not loaded at go() time — no arm in flight" in r.getMessage() + and "Re-arming as fallback" in r.getMessage() + for r in warnings + ), caplog.text + assert "pre-arm may have failed" not in caplog.text + + def test_a_continuation_dispatches_and_does_not_claim_to_wait(self, caplog): + cue = _cue() + arm = _arm_that() + ch = _go_handler(HELD, arm) + with caplog.at_level(logging.INFO): + _go(ch, cue, chain_epoch=1) + assert "not armed yet at go() time — dispatching" in caplog.text + assert "waited" not in caplog.text + assert "Re-arming as fallback" not in caplog.text + arm.assert_not_called() # a continuation never arms in go() + + def test_the_arm_finished_before_this_go_looked(self, caplog): + # in flight at the first look, but arm() found it loaded: no wait. + cue = _cue() + ch = _go_handler(HELD, _arm_that(waited_s=None)) + with caplog.at_level(logging.INFO): + _go(ch, cue) + assert "had finished before this call looked; no wait" in caplog.text + + def test_a_wait_the_first_look_missed_is_still_reported(self, caplog): + # Nothing in flight at the first look (the WARNING), but arm() then + # waited on an arm that started in between: the wait is reported. + cue = _cue() + ch = _go_handler(None, _arm_that(waited_s=0.2)) + with caplog.at_level(logging.INFO): + _go(ch, cue) + assert "Re-arming as fallback" in caplog.text + assert "waited 0.20s at go() time" in caplog.text + + def test_the_same_arm_call_as_before(self): + cue = _cue() + arm = _arm_that() + ch = _go_handler(None, arm) + _go(ch, cue) + arm.assert_called_once() + args, kwargs = arm.call_args + assert args == (cue,) + assert kwargs["init"] is True and kwargs["epoch"] == 0 + assert isinstance(kwargs["wait_report"], dict) + + +class _FakeMtc: + """MTC whose timeline advances by the duration of each patched sleep (as in + test_dispatch_reorder.py), so go_threaded's waits terminate.""" + + def __init__(self, ms=0.0): + self.main_tc = SimpleNamespace( + milliseconds_exact=float(ms), + milliseconds_rounded=int(ms), + framerate=25.0, + frames=0, + ) + + def advance(self, seconds): + ms = float(seconds) * 1000.0 + self.main_tc.milliseconds_exact += ms + self.main_tc.milliseconds_rounded = int(self.main_tc.milliseconds_exact) + self.main_tc.frames = int(self.main_tc.milliseconds_exact / 1000 * 25) + + +def _chain_cue(cid): + """A continuation cue shaped like test_dispatch_reorder.py's _cue().""" + return SimpleNamespace( + id=cid, + _local=True, + enabled=True, + loaded=False, + post_go="go", + prewait=CTimecode(start_seconds=0), + postwait=CTimecode(start_seconds=0), + _target_object=None, + _stop_requested=False, + _go_generation=1, + _revealed=False, + _start_mtc=None, + ) + + +def _dispatch_handler(in_flight, arm): + """go_threaded on a continuation cue, as test_dispatch_reorder drives it.""" + ch = object.__new__(CueHandler) + ch._lock = Lock() + ch._armed_cues = [] + ch._armed_cues_set = set() + ch._disarm_epoch = 0 + ch.communications_thread = MagicMock() + ch.disarm = MagicMock() + ch._arm_ahead = MagicMock() + ch.go = MagicMock(return_value=None) + ch._next_local_fire = MagicMock(return_value=(None, 0.0)) + ch.describe_arm_in_flight = MagicMock(return_value=in_flight) + ch.arm = arm + return ch + + +class TestDispatchSite: + @staticmethod + def _dispatch(ch, cue): + mtc = _FakeMtc(0) + c = _chain_cue(cue.id) + with ( + patch("cuemsengine.cues.CueHandler.run_cue"), + patch("cuemsengine.cues.CueHandler.reveal_cue"), + patch("cuemsengine.cues.CueHandler.loop_cue"), + patch("cuemsengine.cues.CueHandler.sleep", side_effect=mtc.advance), + ): + ch.go_threaded(c, mtc, 0.0, c._go_generation, 1) + return c + + def test_an_arm_in_flight_is_waited_for(self, caplog): + ch = _dispatch_handler(HELD, _arm_that(waited_s=0.36)) + with caplog.at_level(logging.INFO): + self._dispatch(ch, _cue()) + assert f"is still being armed ({HELD}) at dispatch" in caplog.text + assert "waited 0.36s at dispatch" in caplog.text + assert "Re-arming as fallback" not in caplog.text + + def test_nothing_in_flight_is_a_fallback(self, caplog): + ch = _dispatch_handler(None, _arm_that()) + with caplog.at_level(logging.INFO): + self._dispatch(ch, _cue()) + assert "not loaded at dispatch — no arm in flight" in caplog.text + assert "Re-arming as fallback" in caplog.text diff --git a/tests/test_chain_epoch.py b/tests/test_chain_epoch.py index d83973e3..969edfa5 100644 --- a/tests/test_chain_epoch.py +++ b/tests/test_chain_epoch.py @@ -155,7 +155,7 @@ def test_stop_during_the_rearm_refuses_the_dispatch(self): ch = _ch() cue = _cue(loaded=False, _stop_requested=False) - def slow_arm(target, init=False, epoch=None): + def slow_arm(target, init=False, epoch=None, wait_report=None): # the operator hits STOP while the JACK ports are being waited on ch.stop_all_cues() target.loaded = True diff --git a/tests/test_controller_commands.py b/tests/test_controller_commands.py index 89344055..070484ef 100644 --- a/tests/test_controller_commands.py +++ b/tests/test_controller_commands.py @@ -333,26 +333,36 @@ def test_forwards_go_mtc_ms_when_mtc_present(self, controller): with patch.object(controller, "_forward_command_to_nodes") as mock_fwd: controller.go_script(None) mock_fwd.assert_called_once_with( - "/engine/command/go", {"go_mtc_ms": 79240.0} + "/engine/command/go", + {"go_mtc_ms": 79240.0, "run_seq": controller._run_seq}, ) - def test_forwards_original_string_value_when_mtc_listener_is_none(self, controller): + def test_forwards_only_run_seq_when_mtc_listener_is_none(self, controller): """The `controller` fixture builds with_mtc=False -- mtc_listener is None, the only reachable no-MTC case in production (go_script already refuses unless armed=="yes", and MTC runs by the time a project can be - armed).""" + armed). + + The GO value is always a dict now (869fc8ytz): it carries the run + counter that cross-node follows are checked against. The caller's + own value is dropped -- nodes never read it; they only read the + anchor, and fall back to their own MTC when it is absent.""" self._armed(controller) assert controller.mtc_listener is None with patch.object(controller, "_forward_command_to_nodes") as mock_fwd: controller.go_script("complex_test") - mock_fwd.assert_called_once_with("/engine/command/go", "complex_test") + mock_fwd.assert_called_once_with( + "/engine/command/go", {"run_seq": controller._run_seq} + ) - def test_forwards_none_value_unchanged_when_mtc_listener_is_none(self, controller): + def test_forwards_only_run_seq_for_none_value_without_mtc(self, controller): self._armed(controller) assert controller.mtc_listener is None with patch.object(controller, "_forward_command_to_nodes") as mock_fwd: controller.go_script(None) - mock_fwd.assert_called_once_with("/engine/command/go", None) + mock_fwd.assert_called_once_with( + "/engine/command/go", {"run_seq": controller._run_seq} + ) def test_forwards_original_value_when_controller_mtc_is_dead(self, controller): """test2, 2026-09-25: the controller's listener never opened a port @@ -360,11 +370,13 @@ def test_forwards_original_value_when_controller_mtc_is_dead(self, controller): node accepted 0.0 as the anchor -- 4.48s late. A listener that is present but not receiving must not be trusted: send the GO without an anchor, so each node falls back to its own MTC (pre-fix - behaviour).""" + behaviour). The run counter still goes out (869fc8ytz).""" self._armed(controller) controller.mtc_listener = Mock() controller.mtc_listener.main_tc.milliseconds_exact = 0.0 controller.mtc_listener.is_receiving.return_value = False with patch.object(controller, "_forward_command_to_nodes") as mock_fwd: controller.go_script(None) - mock_fwd.assert_called_once_with("/engine/command/go", None) + mock_fwd.assert_called_once_with( + "/engine/command/go", {"run_seq": controller._run_seq} + ) diff --git a/tests/test_controller_cue_names.py b/tests/test_controller_cue_names.py new file mode 100644 index 00000000..cf4207e4 --- /dev/null +++ b/tests/test_controller_cue_names.py @@ -0,0 +1,323 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera + +"""Cue names on the :9190 status channel (869fedahu). + +The UI names the engine's next cue from a uuid -> name table. The engine only +ever sent the uuid, so a tab that had not opened the engine's own project +showed a raw uuid. Now the controller broadcasts one +``/engine/status/cue_name/`` per cue at load and replays them to late +joiners, like ``cue/`` and ``cue_enabled/``. + +Pinned here, in order of importance: + +* names are sent AFTER ``/engine/status/load ``: duplicated projects + share cue uuids, so a client must be able to treat a change of ``load`` as + "new table" and refill it from the burst that follows; +* a second load with no unload in between replaces the map, and the shared + uuid ends up with the new project's name; +* the late-join dump carries them, after ``cue_enabled`` and before ``mixer``; +* unload empties the map; +* the existing ``cue/`` and ``cue_enabled/`` bursts are untouched. + +Pure unit tests: no MTC master, no NNG, no sockets, no subprocess. Safe to run +on a live rig. +""" + +import asyncio +import uuid +from os import environ +from pathlib import Path +from unittest.mock import Mock, patch + +import pytest +from cuemsutils.cues import ActionCue, AudioCue, CueList, DmxCue, VideoCue + +from cuemsengine.osc.WebSocketOscHandler import build_osc_message + +CUE_NAME = "/engine/status/cue_name/" +CUE_STATUS = "/engine/status/cue/" +CUE_ENABLED = "/engine/status/cue_enabled/" +MIXER = "/engine/status/audio/mixer/" +LOAD = "/engine/status/load" + + +@pytest.fixture(autouse=True) +def set_config_path(): + """Point CUEMS_CONF_PATH at test XML files.""" + test_conf_path = Path(__file__).parent / ".." / "dev" / "test_xml_files" + environ["CUEMS_CONF_PATH"] = str(test_conf_path) + + +@pytest.fixture +def controller(): + """A minimal ControllerEngine with the heavy dependencies mocked out.""" + with ( + patch("cuemsengine.core.BaseEngine.ConfigManager") as MockCM, + patch( + "cuemsengine.core.BaseEngine.BaseEngine.get_controller_ip", + return_value="localhost", + ), + ): + mock_cm_instance = MockCM.return_value + mock_cm_instance.node_conf = { + "uuid": "test-controller-uuid", + "mtc_port": "MTC_MIDI_PORT", + } + mock_cm_instance.library_path = str( + Path(__file__).parent / ".." / "dev" / "test_xml_files" + ) + mock_cm_instance.tmp_path = "/tmp" + + from cuemsengine.ControllerEngine import ControllerEngine + + engine = ControllerEngine(with_mtc=False) + + engine.communications_thread = Mock() + engine.communications_thread.broadcast_osc = Mock() + engine.communications_thread.nng_hub = Mock() + + engine.set_status("running", "no") + engine.set_status("load", "") + + yield engine + + engine.stop() + + +def _uuid() -> str: + return str(uuid.uuid4()) + + +def _cue(cls, **fields): + """A cue built the way the XML reader builds them (init_dict path).""" + init = {"id": fields.pop("id", _uuid())} + init.update(fields) + return cls(init) + + +def _script(cuelist): + script = Mock() + script.cuelist = cuelist + script.id = _uuid() + return script + + +def _load(controller, project_name, cuelist): + """Drive load_project up to and past the status bursts, nothing further. + + Everything after set_status("load") that needs a cluster, MTC or the lock + file is stubbed; the bursts and the status messages are real. + """ + + def fake_read_script(name): + controller.script = _script(cuelist) + + with ( + patch.object(controller, "read_script", side_effect=fake_read_script), + patch.object(controller, "_resolve_cluster_state"), + patch.object(controller, "_forward_load_to_nodes"), + patch.object(controller, "start_timecode"), + patch.object(controller, "set_show_lock_file"), + ): + assert controller.load_project(project_name) is True + + +def _sent(controller): + """(address, value) pairs in broadcast order.""" + return [ + (c.args[0], c.args[1]) + for c in controller.communications_thread.broadcast_osc.call_args_list + ] + + +def _index_of_load(sent, project_name): + """Index of the LAST `load ` message.""" + idx = [i for i, (a, v) in enumerate(sent) if a == LOAD and v == project_name] + assert idx, f"no {LOAD} {project_name!r} in {sent}" + return idx[-1] + + +# ─── _collect_cue_names ────────────────────────────────────────────────── + + +class TestCollectCueNames: + def test_walks_nested_lists_and_keeps_every_id(self, controller): + inner = _cue(DmxCue, name="Luz 3") + nested = _cue(CueList, name="Bloque 2", contents=[inner]) + audio = _cue(AudioCue, name="Canción ñ · 2ª") + video = _cue(VideoCue) # no name given: init_dict fills 'empty' + action = _cue(ActionCue, name=None) + top = CueList({"id": _uuid(), "contents": [audio, video, action, nested]}) + + names = controller._collect_cue_names(top) + + assert {str(k): v for k, v in names.items()} == { + str(audio.id): "Canción ñ · 2ª", + str(video.id): "empty", + str(action.id): "", + str(nested.id): "Bloque 2", + str(inner.id): "Luz 3", + } + + def test_mirrors_collect_cue_ids(self, controller): + """Same walk as the status map: a cue with a name but no status, or + the reverse, would be a UI that cannot pair them.""" + inner = _cue(AudioCue, name="a") + nested = _cue(CueList, name="l", contents=[inner, None]) + top = CueList({"id": _uuid(), "contents": [None, nested, _cue(VideoCue)]}) + + ids = {str(i) for i in controller._collect_cue_ids(top)} + names = {str(k) for k in controller._collect_cue_names(top)} + assert names == ids + + +# ─── the load burst ────────────────────────────────────────────────────── + + +class TestLoadBurst: + def test_one_name_per_cue_after_the_load_status(self, controller): + a = _cue(AudioCue, name="Intro") + b = _cue(VideoCue, name="Vídeo 1") + _load(controller, "show_x", CueList({"id": _uuid(), "contents": [a, b]})) + + sent = _sent(controller) + load_at = _index_of_load(sent, "show_x") + names = [ + (i, a_, v) for i, (a_, v) in enumerate(sent) if a_.startswith(CUE_NAME) + ] + + assert {a_[len(CUE_NAME) :]: v for _, a_, v in names} == { + str(a.id): "Intro", + str(b.id): "Vídeo 1", + } + assert all( + i > load_at for i, _, _ in names + ), "names must follow `load ` so a client can clear on load change" + assert {str(k): v for k, v in controller.cue_names.items()} == { + str(a.id): "Intro", + str(b.id): "Vídeo 1", + } + + def test_status_and_enabled_bursts_are_untouched(self, controller): + """Regression guard: the two existing bursts keep their count and + their place before `load`; the new one is appended, not interleaved.""" + cues = [_cue(AudioCue, name=f"c{i}") for i in range(3)] + _load(controller, "show_x", CueList({"id": _uuid(), "contents": cues})) + + sent = _sent(controller) + load_at = _index_of_load(sent, "show_x") + status = [i for i, (a, _) in enumerate(sent) if a.startswith(CUE_STATUS)] + enabled = [i for i, (a, _) in enumerate(sent) if a.startswith(CUE_ENABLED)] + names = [i for i, (a, _) in enumerate(sent) if a.startswith(CUE_NAME)] + + assert len(status) == len(enabled) == len(names) == 3 + assert max(status) < min(enabled) < load_at < min(names) + + def test_second_load_without_unload_replaces_the_map(self, controller): + """Duplicated projects share cue uuids. After X then Y, the shared + uuid must carry Y's name and nothing of X must survive in the map.""" + shared = _uuid() + only_x = _cue(AudioCue, name="Sólo X") + _load( + controller, + "show_x", + CueList( + { + "id": _uuid(), + "contents": [_cue(AudioCue, id=shared, name="Intro"), only_x], + } + ), + ) + only_y = _cue(VideoCue, name="Sólo Y") + _load( + controller, + "show_y", + CueList( + { + "id": _uuid(), + "contents": [_cue(AudioCue, id=shared, name="Intro v2"), only_y], + } + ), + ) + + assert {str(k): v for k, v in controller.cue_names.items()} == { + shared: "Intro v2", + str(only_y.id): "Sólo Y", + } + sent = _sent(controller) + load_y = _index_of_load(sent, "show_y") + after = [(a, v) for a, v in sent[load_y + 1 :] if a.startswith(CUE_NAME)] + assert (CUE_NAME + shared, "Intro v2") in after + assert (CUE_NAME + shared, "Intro") not in after + + def test_a_utf8_name_survives_the_osc_round_trip(self): + from pythonosc.osc_message import OscMessage + + name = "Canción ñ · 2ª — «fin»" + data = build_osc_message(CUE_NAME + _uuid(), name) + assert data is not None + assert OscMessage(data).params == [name] + + +# ─── late join ─────────────────────────────────────────────────────────── + + +class TestLateJoin: + def _dump(self, controller): + ws = Mock() + sent = [] + + async def fake_send(data): + sent.append(data) + + ws.send = fake_send + asyncio.run(controller._on_ws_client_connect(ws)) + return sent + + def test_readable_before_any_load(self, controller): + """__init__ must define it: a browser connecting before the first load + of a freshly restarted engine reaches _on_ws_client_connect.""" + assert controller.cue_names == {} + sent = self._dump(controller) + assert not any(CUE_NAME.encode() in d for d in sent) + + def test_names_are_replayed_after_enabled_and_before_mixer(self, controller): + cid = _uuid() + controller.cue_status = {cid: 0} + controller.cue_enabled_status = {cid: True} + controller.cue_names = {cid: "Intro"} + controller.mixer_status = {"node/0/master": 0.5} + + sent = self._dump(controller) + + def first(prefix): + hits = [i for i, d in enumerate(sent) if prefix.encode() in d] + assert hits, f"{prefix} missing from the dump" + return hits[0] + + assert first(CUE_ENABLED) < first(CUE_NAME) < first(MIXER) + name_frames = [d for d in sent if (CUE_NAME + cid).encode() in d] + assert len(name_frames) == 1 + assert "Intro".encode() in name_frames[0] + + +# ─── unload ────────────────────────────────────────────────────────────── + + +class TestUnload: + def test_unload_empties_the_map(self, controller): + _load( + controller, + "show_x", + CueList({"id": _uuid(), "contents": [_cue(AudioCue, name="Intro")]}), + ) + assert controller.cue_names + + with patch.object(controller, "_forward_command_to_nodes"): + assert controller.unload_project(None) is True + + assert controller.cue_names == {} + assert controller.cue_status == {} + assert controller.cue_enabled_status == {} diff --git a/tests/test_cross_node_follow_controller.py b/tests/test_cross_node_follow_controller.py new file mode 100644 index 00000000..969ab8a0 --- /dev/null +++ b/tests/test_cross_node_follow_controller.py @@ -0,0 +1,228 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera +"""Cross-node Auto follow, controller side (ClickUp 869fc8ytz). + +The controller only relays: a node that owns an Auto follow's source announces +the follow instant (or cancels it), and the controller forwards that to every +node. What it adds is the run counter, `run_seq`: + +- it starts from the clock, so a restarted controller never reuses a value a + node still holds; +- STOP, load and unload bump it BEFORE they forward anything to the nodes; +- every GO carries it, so every node knows the run it belongs to; +- a follow message is relayed only while the show runs and only if it carries + the current value. The check and the forward share one lock with the bump, + so a relayed follow can never be queued behind a STOP it predates. + +Design: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md §3.3-3.4. +""" + +import time +from os import environ +from pathlib import Path +from unittest.mock import MagicMock, Mock, patch + +import pytest + +from cuemsengine.comms.NodesHub import ActionType, NodeOperation, OperationType + + +@pytest.fixture(autouse=True) +def set_config_path(): + test_conf_path = Path(__file__).parent / ".." / "dev" / "test_xml_files" + environ["CUEMS_CONF_PATH"] = str(test_conf_path) + + +@pytest.fixture +def controller(): + with ( + patch("cuemsengine.core.BaseEngine.ConfigManager") as MockCM, + patch( + "cuemsengine.core.BaseEngine.BaseEngine.get_controller_ip", + return_value="localhost", + ), + ): + mock_cm_instance = MockCM.return_value + mock_cm_instance.node_conf = { + "uuid": "test-controller-uuid", + "mtc_port": "MTC_MIDI_PORT", + } + mock_cm_instance.library_path = str( + Path(__file__).parent / ".." / "dev" / "test_xml_files" + ) + mock_cm_instance.tmp_path = "/tmp" + + from cuemsengine.ControllerEngine import ControllerEngine + + engine = ControllerEngine(with_mtc=False) + engine.communications_thread = Mock() + engine.communications_thread.broadcast_osc = Mock() + engine.communications_thread.nng_hub = Mock() + yield engine + engine.stop() + + +def _seq_at_forward(controller, address): + """Patch _forward_command_to_nodes and record run_seq at the moment the + given address is forwarded.""" + seen = [] + + def fwd(addr, value): + if addr == address: + seen.append(controller._run_seq) + + return seen, patch.object(controller, "_forward_command_to_nodes", side_effect=fwd) + + +class TestRunSeq: + def test_starts_from_the_clock(self, controller): + now_ms = time.time_ns() // 1_000_000 + assert isinstance(controller._run_seq, int) + assert now_ms - 60_000 <= controller._run_seq <= now_ms + + def test_stop_bumps_it_before_forwarding(self, controller): + controller.set_status("running", "yes") + before = controller._run_seq + seen, p = _seq_at_forward(controller, "/engine/command/stop") + with p: + controller.stop_script(None) + assert seen == [before + 1] + + def test_stop_while_not_running_leaves_it(self, controller): + controller.set_status("running", "no") + before = controller._run_seq + with patch.object(controller, "_forward_command_to_nodes"): + controller.stop_script(None) + assert controller._run_seq == before + + def test_unload_bumps_it_before_forwarding(self, controller): + controller.set_status("running", "no") + before = controller._run_seq + seen, p = _seq_at_forward(controller, "/engine/command/stop") + with p, patch.object(controller, "reset_script"): + controller.unload_project(None) + assert seen == [before + 1] + + def test_load_bumps_it_before_forwarding(self, controller): + controller.set_status("running", "no") + before = controller._run_seq + seen, p = _seq_at_forward(controller, "/engine/command/load") + + def read_script(name): + controller.script = MagicMock() + + with ( + p, + patch.object(controller, "reset_script"), + patch.object(controller, "read_script", side_effect=read_script), + patch.object(controller, "_collect_cue_ids", return_value=[]), + patch.object(controller, "_collect_cue_enabled", return_value={}), + patch.object(controller, "_resolve_cluster_state"), + patch.object(controller, "start_timecode"), + patch.object(controller, "set_show_lock_file"), + ): + assert controller.load_project("p") is True + assert seen == [before + 1] + + def test_every_go_carries_the_current_value(self, controller): + controller.set_status("armed", "yes") + controller.script = Mock() + with patch.object(controller, "_forward_command_to_nodes") as fwd: + controller.go_script(None) + controller.go_script(None) + values = [c.args[1] for c in fwd.call_args_list] + assert [v["run_seq"] for v in values] == [controller._run_seq] * 2 + + +def _follow(sender="node-a", **data): + payload = { + "op": "announce", + "origin": sender, + "source": "src", + "target": "tgt", + "seed_ms": 1000.0, + } + payload.update(data) + return NodeOperation( + type=OperationType.STATUS, + action=ActionType.UPDATE, + sender=sender, + target="follow", + data=payload, + ) + + +class TestFollowRelay: + @pytest.fixture + def running(self, controller): + controller.set_status("running", "yes") + controller._adopted_nodes = {"node-a", "node-b"} + controller.cue_status = {"src": 1, "tgt": 0} + return controller + + def test_forwards_a_current_message_to_every_node(self, running): + op = _follow(run_seq=running._run_seq) + with patch.object(running, "_forward_command_to_nodes") as fwd: + running.status_operation_callback(op) + fwd.assert_called_once_with("/engine/command/follow", op.data) + + def test_forwards_a_cancel_too(self, running): + op = _follow(op="cancel", reason="stop", run_seq=running._run_seq) + with patch.object(running, "_forward_command_to_nodes") as fwd: + running.status_operation_callback(op) + fwd.assert_called_once_with("/engine/command/follow", op.data) + + def test_drops_a_stale_run_seq(self, running): + op = _follow(run_seq=running._run_seq - 1) + with ( + patch.object(running, "_forward_command_to_nodes") as fwd, + patch("cuemsengine.ControllerEngine.Logger") as log, + ): + running.status_operation_callback(op) + fwd.assert_not_called() + assert log.info.called + + def test_drops_when_not_running(self, running): + running.set_status("running", "no") + op = _follow(run_seq=running._run_seq) + with patch.object(running, "_forward_command_to_nodes") as fwd: + running.status_operation_callback(op) + fwd.assert_not_called() + + def test_drops_a_message_sent_before_a_stop(self, running): + """The node's run_seq predates the STOP: it must not reach the nodes + after the STOP, whatever the order the two arrive in.""" + op = _follow(run_seq=running._run_seq) + with patch.object(running, "_forward_command_to_nodes") as fwd: + running.stop_script(None) + running.set_status("running", "yes") # even a new GO's state + running.status_operation_callback(op) + assert all(c.args[0] != "/engine/command/follow" for c in fwd.call_args_list) + + def test_drops_a_non_adopted_sender_with_a_warning(self, running): + op = _follow(sender="stranger", run_seq=running._run_seq) + with ( + patch.object(running, "_forward_command_to_nodes") as fwd, + patch("cuemsengine.ControllerEngine.Logger") as log, + ): + running.status_operation_callback(op) + fwd.assert_not_called() + assert log.warning.called + + def test_drops_an_unknown_cue_with_a_warning(self, running): + op = _follow(target="not-in-project", run_seq=running._run_seq) + with ( + patch.object(running, "_forward_command_to_nodes") as fwd, + patch("cuemsengine.ControllerEngine.Logger") as log, + ): + running.status_operation_callback(op) + fwd.assert_not_called() + assert log.warning.called + + def test_tolerates_a_message_without_data(self, running): + op = _follow(run_seq=running._run_seq) + op.data = None + with patch.object(running, "_forward_command_to_nodes") as fwd: + running.status_operation_callback(op) + fwd.assert_not_called() diff --git a/tests/test_cross_node_follow_hook.py b/tests/test_cross_node_follow_hook.py new file mode 100644 index 00000000..3ac1d740 --- /dev/null +++ b/tests/test_cross_node_follow_hook.py @@ -0,0 +1,164 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera +"""Cross-node Auto follow: the node's receive hook (ClickUp 869fc8ytz). + +NodeCommunications receives one bus message at a time, in order, and then runs +each command on its own thread, where the command lock decides the order. +The follow messages and the run counter must follow the BUS order, so they are +applied in a synchronous hook, before any command thread is started: + +- a 'follow' message is applied there and never reaches the command lock; +- GO records the run counter, STOP and load clear it, there; +- the hook can never stop a GO, a STOP or a load from running: an exception + in it is logged and the command thread still starts. + +Design: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md §3.5. +""" + +import threading +from unittest.mock import AsyncMock, MagicMock, patch + +import pytest + +from cuemsengine.comms.NodeCommunications import NodeCommunications +from cuemsengine.comms.NodesHub import ActionType, NodeOperation, OperationType + +NODE_UUID = "aaaaaaaa-1111-2222-3333-444444444444" +CONTROLLER_UUID = "bbbbbbbb-1111-2222-3333-444444444444" + + +@pytest.fixture +def comms(monkeypatch): + monkeypatch.setattr("cuemsengine.comms.NodeCommunications.NodesHub", MagicMock()) + obj = NodeCommunications(hub_address="tcp://127.0.0.1:0", node_id=NODE_UUID) + obj.nng_hub.send_operation = AsyncMock() + obj._command_callback = MagicMock() + return obj + + +def _op(name, value): + return NodeOperation( + type=OperationType.COMMAND, + action=ActionType.UPDATE, + sender=CONTROLLER_UUID, + target=name, + data={"value": value, "address": f"/engine/command/{name}"}, + ) + + +def _threads_started(comms, op): + started = [] + real = threading.Thread + + def fake_thread(*a, **k): + t = real(*a, **k) + started.append(k.get("name")) + return t + + with patch("threading.Thread", side_effect=fake_thread): + comms._handle_command_operation(op) + return started + + +class TestReceiveHook: + def test_a_consumed_message_starts_no_command_thread(self, comms): + comms.set_receive_hook(MagicMock(return_value=True)) + assert _threads_started(comms, _op("follow", {"op": "announce"})) == [] + comms._command_callback.assert_not_called() + + def test_the_hook_sees_name_and_value_before_the_thread(self, comms): + hook = MagicMock(return_value=False) + comms.set_receive_hook(hook) + started = _threads_started(comms, _op("go", {"run_seq": 7})) + hook.assert_called_once_with("go", {"run_seq": 7}) + assert started == ["NNG-Command-go"] + + def test_a_hook_that_raises_never_loses_the_command(self, comms): + comms.set_receive_hook(MagicMock(side_effect=RuntimeError("boom"))) + with patch("cuemsengine.comms.NodeCommunications.Logger") as log: + started = _threads_started(comms, _op("stop", None)) + assert started == ["NNG-Command-stop"] + assert log.error.called + + def test_no_hook_keeps_todays_behaviour(self, comms): + assert _threads_started(comms, _op("go", None)) == ["NNG-Command-go"] + + +class _Relay: + def __init__(self): + self.calls = [] + + def begin_run(self, value): + self.calls.append(("begin_run", value)) + + def end_run(self, why): + self.calls.append(("end_run", why)) + + def on_message(self, value): + self.calls.append(("on_message", value)) + + +class TestNodeEngineHook: + """NodeEngine._on_command_received, called from the hook.""" + + def _node(self): + from cuemsengine.NodeEngine import NodeEngine + + node = object.__new__(NodeEngine) + node._follow_relay = _Relay() + return node + + def test_follow_is_consumed(self): + node = self._node() + assert node._on_command_received("follow", {"op": "cancel"}) is True + assert node._follow_relay.calls == [("on_message", {"op": "cancel"})] + + @pytest.mark.parametrize("value", [{"run_seq": 5, "go_mtc_ms": 1.0}, None, "x"]) + def test_go_records_the_run_and_still_runs(self, value): + node = self._node() + assert node._on_command_received("go", value) is False + assert node._follow_relay.calls == [("begin_run", value)] + + @pytest.mark.parametrize("name", ["stop", "load"]) + def test_stop_and_load_end_the_run_and_still_run(self, name): + node = self._node() + assert node._on_command_received(name, None) is False + assert node._follow_relay.calls == [("end_run", name)] + + @pytest.mark.parametrize("name", ["setnextcue", "cue_enabled", "deploy"]) + def test_other_commands_are_untouched(self, name): + node = self._node() + assert node._on_command_received(name, "v") is False + assert node._follow_relay.calls == [] + + def test_without_a_relay_nothing_is_consumed(self): + node = self._node() + node._follow_relay = None + assert node._on_command_received("follow", {}) is False + + +class TestReviewFixes: + def test_a_follow_handler_that_raises_is_still_consumed(self): + """MINOR-6: never let a follow message reach the command lock.""" + from cuemsengine.NodeEngine import NodeEngine + + node = object.__new__(NodeEngine) + node._follow_relay = MagicMock() + node._follow_relay.on_message.side_effect = RuntimeError("bug") + with patch("cuemsengine.NodeEngine.Logger") as log: + assert node._on_command_received("follow", {}) is True + assert log.error.called + + @pytest.mark.parametrize("name", ["stop", "load"]) + def test_stop_and_load_are_marked_applied_after_they_run(self, name): + """MINOR-4: the node's own STOP/load has run (or was refused).""" + from cuemsengine.NodeEngine import NodeEngine + + node = object.__new__(NodeEngine) + node._command_lock = threading.Lock() + node._follow_relay = MagicMock() + node.commands_dict = {name: MagicMock(side_effect=RuntimeError("x"))} + with pytest.raises(RuntimeError): + node.run_command(name, None) + node._follow_relay.stop_applied.assert_called_once() diff --git a/tests/test_cross_node_follow_owner.py b/tests/test_cross_node_follow_owner.py new file mode 100644 index 00000000..1772d0df --- /dev/null +++ b/tests/test_cross_node_follow_owner.py @@ -0,0 +1,638 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera +"""Cross-node Auto follow, owning side and CueHandler hooks (ClickUp 869fc8ytz). + +The node where an AudioCue or VideoCue with Auto follow is local announces the +follow instant when the cue starts (or at the start of its last loop), so the +other nodes can start their part of the target on time. The instant comes +from the same helper the cue's own fire uses. Leaving without firing sends a +cancel, except when every node already knows (a STOP, a load, the yield) or +when go() already sent it (the cue was started again). Only the current pass +announces, and the outstanding record is compare-and-cleared, so exactly one +cancel can follow one announcement. + +Also here: go()'s commit gate, the restart cancel's place in the commit +section, go_from passing the dispatch guards through, the guarded stop of a +follow target and its guarded disarm. + +Design: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md +§3.2, §3.5. +""" + +import sys +from threading import Lock +from types import SimpleNamespace +from unittest.mock import MagicMock, Mock, patch +from uuid import uuid4 + +import pytest + +sys.modules.setdefault("cuemsutils.tools.Osc_nodes_hub", Mock()) + +from cuemsutils.cues import DmxCue, VideoCue # noqa: E402 +from cuemsutils.tools.CTimecode import CTimecode # noqa: E402 + +from cuemsengine.cues.CueHandler import CueHandler # noqa: E402 + + +class _FakeMtc: + def __init__(self, ms=0.0): + self.main_tc = SimpleNamespace( + milliseconds_exact=float(ms), + milliseconds_rounded=int(ms), + framerate=25.0, + frames=0, + ) + + def advance(self, seconds): + self.main_tc.milliseconds_exact += float(seconds) * 1000.0 + self.main_tc.milliseconds_rounded = int(self.main_tc.milliseconds_exact) + + +def _tc(ms): + return CTimecode(start_seconds=ms / 1000.0) + + +def _video(post_go="go_at_end", target="default", loop=1, postwait=0, cls=VideoCue): + cue = cls.__new__(cls) + cue.id = str(uuid4()) + cue.enabled = True + cue.post_go = post_go + cue.prewait = CTimecode(start_seconds=0) + cue.postwait = CTimecode(start_seconds=postwait) + cue.loop = loop + cue._local = True + cue.loaded = True + cue._stop_requested = False + cue._go_generation = 1 + cue._revealed = False + cue._start_mtc = None + cue._end_mtc = None + if target == "default": + target = SimpleNamespace(id=str(uuid4()), _go_generation=0) + cue._target_object = target + return cue + + +def _relay(run_seq=7): + relay = MagicMock() + relay.run_seq = run_seq + relay.stop_pending = False + return relay + + +def _ch(relay=None): + ch = object.__new__(CueHandler) + ch._lock = Lock() + ch._armed_cues = [] + ch._armed_cues_set = set() + ch.communications_thread = MagicMock() + ch.disarm = MagicMock() + ch.arm = MagicMock() + ch._arm_ahead = MagicMock() + ch.go = MagicMock(return_value=None) + ch.go_from = MagicMock(return_value=None) + ch._next_local_fire = MagicMock(return_value=(None, 0.0)) + ch._follow = relay + return ch + + +def _run( + ch, + cue, + mtc, + body_ms=2000, + loop_effect=None, + order=None, + reveal_effect=None, + blank_effect=None, + **kw, +): + """Drive go_threaded with the players patched out. run_cue sets the + cue's start and end as the real one does (start = arrival + prewait).""" + calls = order if order is not None else [] + + def run_cue(c, m, start_ms): + calls.append("run_cue") + c._start_mtc = _tc(start_ms) + c._end_mtc = _tc(start_ms + body_ms) + + def loop_cue(c, m, on_last_loop=None): + calls.append("loop") + if loop_effect: + loop_effect(c, m, on_last_loop) + m.main_tc.milliseconds_exact = c._end_mtc.milliseconds_exact + + kw.setdefault("go_gen", cue._go_generation) + kw.setdefault("arm_epoch", ch._disarm_epoch) + ch._arm_ahead.side_effect = lambda *a, **k: calls.append("arm_ahead") + ch._follow and setattr( + ch._follow.announce, "side_effect", lambda *a: calls.append("announce") + ) + with ( + patch("cuemsengine.cues.CueHandler.run_cue", side_effect=run_cue), + patch( + "cuemsengine.cues.CueHandler.reveal_cue", + side_effect=lambda *a: ( + calls.append("reveal"), + reveal_effect and reveal_effect(), + ), + ), + patch("cuemsengine.cues.CueHandler.loop_cue", side_effect=loop_cue), + patch( + "cuemsengine.cues.CueHandler.blank_cue", + side_effect=lambda *a: blank_effect and blank_effect(), + ), + patch( + "cuemsengine.cues.CueHandler.sleep", side_effect=lambda s: mtc.advance(s) + ), + ): + ch.go_threaded(cue, mtc, 1000.0, **kw) + return calls + + +# ── announce ────────────────────────────────────────────────────────────── + + +class TestAnnounce: + def test_announces_the_fire_instant_after_the_reveal_before_the_arm_ahead(self): + relay = _relay() + ch, cue = _ch(relay), _video(postwait=0.5) + order = _run(ch, cue, _FakeMtc(1000), body_ms=2000) + relay.announce.assert_called_once_with(cue, 3500.0, 7) + assert order.index("reveal") < order.index("announce") + assert order.index("announce") < order.index("arm_ahead") + + def test_the_cue_fires_at_the_announced_instant(self): + relay = _relay() + ch, cue = _ch(relay), _video(postwait=0.5) + _run(ch, cue, _FakeMtc(1000), body_ms=2000) + args = ch.go_from.call_args.args + assert args[0] is cue._target_object and args[2] == 3500.0 + relay.cancel.assert_not_called() + assert getattr(cue, "_follow_out", None) is None + + @pytest.mark.parametrize( + "why", ["pause", "no_target", "infinite_loop", "dmx", "no_relay", "no_run"] + ) + def test_does_not_announce(self, why): + relay = _relay(run_seq=None if why == "no_run" else 7) + kw = {} + if why == "pause": + kw["post_go"] = "pause" + elif why == "no_target": + kw["target"] = None + elif why == "infinite_loop": + kw["loop"] = 0 + elif why == "dmx": + kw["cls"] = DmxCue + ch = _ch(None if why == "no_relay" else relay) + cue = _video(**kw) + _run(ch, cue, _FakeMtc(1000)) + relay.announce.assert_not_called() + + def test_a_cue_that_never_reveals_does_not_announce(self): + relay = _relay() + ch, cue = _ch(relay), _video() + + with patch.object(ch, "_reveal_wait", return_value="stopped"): + _run(ch, cue, _FakeMtc(1000), order=[]) + relay.announce.assert_not_called() + + def test_a_replaced_pass_does_not_announce(self): + """A newer go() took the cue between the reveal and the announce.""" + relay = _relay() + ch, cue = _ch(relay), _video() + _run( + ch, + cue, + _FakeMtc(1000), + reveal_effect=lambda: setattr(cue, "_go_generation", 2), + ) + relay.announce.assert_not_called() + + def test_a_looping_cue_announces_once_at_its_last_loop(self): + relay = _relay() + ch, cue = _ch(relay), _video(loop=3) + + def loops(c, m, on_last_loop): + assert on_last_loop is not None + relay.announce.assert_not_called() # not at the reveal + c._end_mtc = _tc(7000) # the last loop's end, rebased + on_last_loop() + + _run(ch, cue, _FakeMtc(1000), body_ms=2000, loop_effect=loops) + relay.announce.assert_called_once_with(cue, 7000.0, 7) + + def test_a_looping_cue_without_follow_gets_no_callback(self): + ch, cue = _ch(_relay()), _video(loop=3, post_go="pause") + seen = [] + _run(ch, cue, _FakeMtc(1000), loop_effect=lambda c, m, cb: seen.append(cb)) + assert seen == [None] + + def test_an_instant_that_moved_is_an_error(self): + relay = _relay() + ch, cue = _ch(relay), _video() + + def stretch(c, m, cb): + c._end_mtc = _tc(c._end_mtc.milliseconds_exact + 500) + + with patch("cuemsengine.cues.CueHandler.Logger") as log: + _run(ch, cue, _FakeMtc(1000), loop_effect=stretch) + assert any("announced" in str(c) for c in log.error.call_args_list) + + +# ── leaving without firing ──────────────────────────────────────────────── + + +class TestLeave: + def test_a_stop_action_cancels_with_reason_stop(self): + relay = _relay() + ch, cue = _ch(relay), _video() + + def stop_action(c, m, cb): + c._stop_requested = True + c._go_generation += 1 + + _run(ch, cue, _FakeMtc(1000), body_ms=2000, loop_effect=stop_action) + relay.cancel.assert_called_once_with(cue, 3000.0, 7, "stop") + ch.go_from.assert_not_called() + + def test_a_pause_cancels_with_reason_stop(self): + relay = _relay() + ch, cue = _ch(relay), _video() + _run( + ch, + cue, + _FakeMtc(1000), + loop_effect=lambda c, m, cb: setattr(c, "_stop_requested", True), + ) + relay.cancel.assert_called_once_with(cue, 3000.0, 7, "stop") + + def test_a_stop_or_load_sends_nothing(self): + relay = _relay() + ch, cue = _ch(relay), _video() + + def stop(c, m, cb): + ch._disarm_epoch += 1 + c._stop_requested = True + c._go_generation += 1 + + _run(ch, cue, _FakeMtc(1000), loop_effect=stop) + relay.cancel.assert_not_called() + assert getattr(cue, "_follow_out", None) is None + + def test_a_restart_lets_go_send_the_cancel(self): + relay = _relay() + ch, cue = _ch(relay), _video() + + def restart(c, m, cb): + with ch._lock: + ch._take_follow_on_restart_locked(c) # what go() does + c._go_generation += 1 + + _run(ch, cue, _FakeMtc(1000), loop_effect=restart) + relay.cancel.assert_called_once_with(cue, 3000.0, 7, "restart") + + def test_an_exception_cancels_with_reason_error_and_still_raises(self): + relay = _relay() + ch, cue = _ch(relay), _video() + + def boom(c, m, cb): + raise RuntimeError("player died") + + with pytest.raises(RuntimeError): + _run(ch, cue, _FakeMtc(1000), loop_effect=boom) + relay.cancel.assert_called_once_with(cue, 3000.0, 7, "error") + + def test_the_yield_sends_nothing(self): + relay = _relay() + ch, cue = _ch(relay), _video(postwait=0.5) + + def manual_go_of_target(): # during the postwait tail + cue._target_object._go_generation += 1 + + _run(ch, cue, _FakeMtc(1000), blank_effect=manual_go_of_target) + ch.go_from.assert_not_called() + relay.cancel.assert_not_called() + + def test_an_error_in_the_own_fire_does_not_cancel(self): + relay = _relay() + ch, cue = _ch(relay), _video() + ch.go_from.side_effect = RuntimeError("fire failed") + with pytest.raises(RuntimeError): + _run(ch, cue, _FakeMtc(1000)) + relay.cancel.assert_not_called() + + +# ── go(): commit gate and restart cancel ───────────────────────────────── + + +def _plain(id="c", **kw): + c = SimpleNamespace(id=id, loaded=True, enabled=True, _local=True) + for k, v in kw.items(): + setattr(c, k, v) + return c + + +class TestGoCommit: + def _go(self, ch, cue, **kw): + with patch.object(CueHandler, "go_threaded"): + return ch.go(cue, _FakeMtc(), 0.0, **kw) + + def test_restart_sends_a_cancel_for_the_outstanding_announcement(self): + relay = _relay() + ch = _ch(relay) + del ch.go + cue = _plain(_follow_out=(5000.0, 7), _target_object=None) + assert self._go(ch, cue) is not None + relay.cancel.assert_called_once_with(cue, 5000.0, 7, "restart") + assert cue._follow_out is None + + def test_an_outstanding_announcement_of_an_old_run_is_dropped_silently(self): + relay = _relay() + ch = _ch(relay) + del ch.go + cue = _plain(_follow_out=(5000.0, 6)) + self._go(ch, cue) + relay.cancel.assert_not_called() + assert cue._follow_out is None + + def test_a_refused_dispatch_sends_nothing_and_keeps_the_record(self): + relay = _relay() + ch = _ch(relay) + del ch.go + ch._last_stop_chain_epoch = 1 + cue = _plain(_follow_out=(5000.0, 7)) + assert self._go(ch, cue, require_stop_epoch=0) is None + relay.cancel.assert_not_called() + assert cue._follow_out == (5000.0, 7) + + def test_the_gate_sees_the_generation_about_to_be_assigned(self): + ch = _ch() + del ch.go + cue = _plain(_go_generation=4) + gate = MagicMock(return_value=True) + self._go(ch, cue, commit_gate=gate) + gate.assert_called_once_with(cue, 5) + assert cue._go_generation == 5 + + def test_a_refusing_gate_commits_nothing(self): + relay = _relay() + ch = _ch(relay) + del ch.go + cue = _plain(_go_generation=4, _follow_out=(5000.0, 7), _playing=False) + assert self._go(ch, cue, commit_gate=MagicMock(return_value=False)) is None + assert cue._go_generation == 4 and cue._playing is False + relay.cancel.assert_not_called() + + def test_a_gate_that_raises_refuses(self): + ch = _ch() + del ch.go + cue = _plain(_go_generation=4) + with patch("cuemsengine.cues.CueHandler.Logger") as log: + out = self._go(ch, cue, commit_gate=MagicMock(side_effect=ValueError())) + assert out is None and log.error.called + + def test_go_clears_the_start_stamp(self): + ch = _ch() + del ch.go + cue = _plain(_revealed_at=123.0) + self._go(ch, cue) + assert cue._revealed_at is None + + +class TestGoFrom: + def test_passes_the_guards_only_when_set(self): + ch = _ch() + del ch.go_from + cue = _plain(post_go="pause") + ch.go_from(cue, _FakeMtc(), 10.0) + ch.go.assert_called_once_with(cue, ch.go.call_args.args[1], 10.0) + + def test_passes_the_guards_through(self): + ch = _ch() + del ch.go_from + cue = _plain(post_go="pause") + gate = MagicMock() + ch.go_from( + cue, _FakeMtc(), 10.0, arm_epoch=3, require_stop_epoch=2, commit_gate=gate + ) + assert ch.go.call_args.kwargs == { + "arm_epoch": 3, + "require_stop_epoch": 2, + "commit_gate": gate, + } + + +# ── the guarded stop and disarm of a follow target ─────────────────────── + + +class TestStopDispatchedFollow: + def _target(self, revealed_ago=None, gen=9): + from time import monotonic + + cue = _plain( + _go_generation=gen, + _stop_requested=False, + _playing=True, + _revealed_at=None if revealed_ago is None else monotonic() - revealed_ago, + _armed_at=42.0, + ) + return cue + + def _ch(self): + ch = _ch() + ch._disarm_epoch = 3 + ch.cancel_pending_descendants = MagicMock() + ch._end_illumination = MagicMock() + ch.disarm_if_unchanged = MagicMock(return_value=True) + return ch + + def _stop(self, ch, cue, may_cut=True): + with patch("cuemsengine.cues.CueHandler.sleep"): + return ch.stop_dispatched_follow( + cue, 9, 3, 42.0, may_cut=may_cut, grace_s=2.0 + ) + + def test_a_newer_go_owns_it(self): + ch, cue = self._ch(), self._target(gen=10) + assert self._stop(ch, cue)[0] == "owned" + assert cue._stop_requested is False + + def test_a_stop_owns_it(self): + ch, cue = self._ch(), self._target() + ch._disarm_epoch = 4 + assert self._stop(ch, cue)[0] == "owned" + + def test_not_started_is_stopped(self): + ch, cue = self._ch(), self._target() + assert self._stop(ch, cue)[0] == "stopped" + assert cue._stop_requested and cue._go_generation == 10 and not cue._playing + ch.cancel_pending_descendants.assert_called_once_with(cue) + ch.disarm_if_unchanged.assert_called_once_with( + cue, 10, 3, 42.0, reason="follow_cancelled" + ) + + def test_started_inside_the_grace_is_stopped_when_it_may_cut(self): + ch, cue = self._ch(), self._target(revealed_ago=0.5) + outcome, age = self._stop(ch, cue) + assert outcome == "stopped" and 0.4 < age < 1.0 + + def test_started_inside_the_grace_is_left_for_an_error(self): + ch, cue = self._ch(), self._target(revealed_ago=0.5) + assert self._stop(ch, cue, may_cut=False)[0] == "left" + assert cue._stop_requested is False + + def test_started_after_the_grace_is_left(self): + ch, cue = self._ch(), self._target(revealed_ago=3.0) + assert self._stop(ch, cue)[0] == "left" + ch.disarm_if_unchanged.assert_not_called() + + +class TestDisarmIfUnchanged: + def _setup(self): + ch = object.__new__(CueHandler) + ch._lock = Lock() + ch._disarm_epoch = 3 + ch.communications_thread = MagicMock() + cue = _plain(_go_generation=10, _armed_at=42.0, _playing=False) + ch._armed_cues = [cue] + ch._armed_cues_set = {cue.id} + return ch, cue + + def test_unpublishes_and_releases(self): + ch, cue = self._setup() + seen = [] + + def release(c, reason, what="Disarmed"): + seen.append(ch._arming_registry().get(c.id) is not None) + + with patch.object(ch, "_release_cue_resources", side_effect=release): + assert ch.disarm_if_unchanged(cue, 10, 3, 42.0, reason="x") is True + assert cue.loaded is False and ch._armed_cues == [] + assert seen == [True] # released while holding the cue's claim + assert ch._arming_registry() == {} + + @pytest.mark.parametrize("change", ["gen", "epoch", "rearmed", "unloaded"]) + def test_refuses_when_anything_moved(self, change): + ch, cue = self._setup() + if change == "gen": + cue._go_generation = 11 + elif change == "epoch": + ch._disarm_epoch = 4 + elif change == "rearmed": + cue._armed_at = 43.0 + else: + cue.loaded = False + with patch.object(ch, "_release_cue_resources") as rel: + assert ch.disarm_if_unchanged(cue, 10, 3, 42.0, reason="x") is False + rel.assert_not_called() + + def test_refuses_while_an_arm_is_in_flight(self): + ch, cue = self._setup() + ch._arming_registry()[cue.id] = object() + with patch.object(ch, "_release_cue_resources") as rel: + assert ch.disarm_if_unchanged(cue, 10, 3, 42.0, reason="x") is False + rel.assert_not_called() + + def test_the_claim_is_released_even_if_the_release_fails(self): + ch, cue = self._setup() + with patch.object(ch, "_release_cue_resources", side_effect=RuntimeError()): + with pytest.raises(RuntimeError): + ch.disarm_if_unchanged(cue, 10, 3, 42.0, reason="x") + assert ch._arming_registry() == {} + + +# ── code review of the implementation (2026-10-06) ─────────────────────── + + +class TestReviewFixes: + def test_the_start_stamp_is_set_with_the_reveal_decision(self): + """MINOR-1: a cancel taking the lock right after the reveal decision + must already see the cue as started.""" + relay = _relay() + ch, cue = _ch(relay), _video() + seen = [] + _run( + ch, + cue, + _FakeMtc(1000), + reveal_effect=lambda: seen.append(getattr(cue, "_revealed_at", None)), + ) + assert seen and seen[0] is not None + + def test_a_restart_just_before_the_fire_skips_the_fire(self): + """MINOR-2: go() took the announcement (restart) between the tail and + the fire; the replaced pass must not fire its follow.""" + relay = _relay() + ch, cue = _ch(relay), _video() + + def restart(*a, **k): + with ch._lock: + ch._take_follow_on_restart_locked(cue) + cue._go_generation += 1 + + ch.communications_thread.remove_cue.side_effect = restart + _run(ch, cue, _FakeMtc(1000)) + ch.go_from.assert_not_called() + relay.cancel.assert_called_once_with(cue, 3000.0, 7, "restart") + + def test_without_an_announcement_the_fire_is_unchanged(self): + """The generation re-check only applies to an announced follow; a + same-node or unannounced follow fires as before.""" + ch, cue = _ch(None), _video() + + def bump(*a, **k): + cue._go_generation += 1 + + ch.communications_thread.remove_cue.side_effect = bump + _run(ch, cue, _FakeMtc(1000)) + ch.go_from.assert_called_once() + + def test_no_announcement_while_a_stop_is_pending(self): + """MINOR-4: a STOP was received but not applied yet; this pass is + about to be stopped and must not announce into the next run.""" + relay = _relay() + relay.stop_pending = True + ch, cue = _ch(relay), _video() + _run(ch, cue, _FakeMtc(1000)) + relay.announce.assert_not_called() + + +class TestStopDispatchedFollowReview: + def _ch(self): + ch = _ch() + ch._disarm_epoch = 3 + ch.cancel_pending_descendants = MagicMock() + ch._end_illumination = MagicMock() + ch.disarm_if_unchanged = MagicMock(return_value=True) + return ch + + def test_revealed_without_a_stamp_counts_as_started(self): + ch = self._ch() + cue = _plain(_go_generation=9, _revealed=True, _revealed_at=None) + with patch("cuemsengine.cues.CueHandler.sleep"): + out = ch.stop_dispatched_follow(cue, 9, 3, 42.0, may_cut=False, grace_s=2.0) + assert out[0] == "left" + + def test_a_cue_already_on_stage_before_the_follow_counts_as_started(self): + """MINOR-3: the follow restarted a cue that was playing; its new pass + has not revealed yet, but its output has been on stage for minutes.""" + from time import monotonic + + ch = self._ch() + cue = _plain(_go_generation=9, _revealed=False, _revealed_at=None) + with patch("cuemsengine.cues.CueHandler.sleep"): + out = ch.stop_dispatched_follow( + cue, + 9, + 3, + 42.0, + may_cut=True, + grace_s=2.0, + started_before=monotonic() - 120.0, + ) + assert out[0] == "left" and out[1] > 100 + ch.disarm_if_unchanged.assert_not_called() diff --git a/tests/test_cross_node_follow_receiver.py b/tests/test_cross_node_follow_receiver.py new file mode 100644 index 00000000..9f9f747e --- /dev/null +++ b/tests/test_cross_node_follow_receiver.py @@ -0,0 +1,668 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera +"""Cross-node Auto follow, receiving side (ClickUp 869fc8ytz). + +A node that does NOT own an Auto follow's source learns the follow instant from +the owner's announcement, relayed by the controller. It keeps one entry per +source cue, pre-arms what it would start, waits for the instant on MTC and +dispatches then, through `go_from`, with a commit gate that `go()` evaluates +inside its own commit section. The owner's cancel is applied by the state of +the entry: + + waiting / dispatching -> cancelled (the waiter ends, or the gate refuses) + dispatched -> handed to CueHandler.stop_dispatched_follow, which + applies the 2 s rule under its own lock + +Messages are applied in bus order, in the receive hook; nothing here waits. + +Design: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md §3.5. +""" + +import sys +from types import SimpleNamespace +from unittest.mock import MagicMock, Mock, patch + +import pytest + +sys.modules.setdefault("cuemsutils.tools.Osc_nodes_hub", Mock()) + +from cuemsutils.tools.CTimecode import CTimecode # noqa: E402 + +from cuemsengine.core.BaseEngine import BaseEngine # noqa: E402 +from cuemsengine.cues.FollowRelay import FollowRelay # noqa: E402 + +ME, OWNER, OTHER = "node-me", "node-owner", "node-other" + + +class _Mtc: + def __init__(self, ms=0.0): + self.main_tc = SimpleNamespace(milliseconds_exact=float(ms)) + + def set(self, ms): + self.main_tc.milliseconds_exact = float(ms) + + +def _cue(id, local=False, post_go="pause", target=None, postwait=0, **kw): + c = SimpleNamespace( + id=id, + _local=local, + enabled=True, + loaded=False, + post_go=post_go, + postwait=CTimecode(start_seconds=postwait), + _target_object=target, + _go_generation=0, + ) + for k, v in kw.items(): + setattr(c, k, v) + return c + + +class _Script: + def __init__(self, *cues): + self.cues = {str(c.id): c for c in cues} + + def find(self, id): + return self.cues.get(str(id)) + + +class _Rig: + """A FollowRelay wired to fakes. Threads are not started: `spawned` + records them and the test runs them by hand.""" + + def __init__(self, script, ms=0.0, run_seq=7): + self.mtc = _Mtc(ms) + self.ch = MagicMock() + self.ch._disarm_epoch = 3 + self.ch._last_stop_chain_epoch = 2 + self.ch.arm_epoch.side_effect = lambda: self.ch._disarm_epoch + self.ch.go_from.return_value = None + self.ch.stop_dispatched_follow.return_value = ("stopped", None) + self.sent = [] + self.spawned = [] + self.gen = [1] + self.script = script + self.relay = FollowRelay( + self.ch, + node_id=ME, + send=self.sent.append, + get_script=lambda: self.script, + get_mtc=lambda: self.mtc, + get_project_gen=lambda: self.gen[0], + first_local=BaseEngine._first_local_enabled_in_go_chain, + spawn=lambda name, fn, *a: self.spawned.append((name, fn, a)), + sleep=lambda s: self.mtc.set(self.mtc.main_tc.milliseconds_exact + 20), + ) + if run_seq is not None: + self.relay.begin_run({"run_seq": run_seq}) + + def announce(self, source="S", target="T", seed=1000.0, origin=OWNER, run_seq=7): + self.relay.on_message( + { + "op": "announce", + "origin": origin, + "run_seq": run_seq, + "source": source, + "target": target, + "seed_ms": seed, + } + ) + + def cancel(self, source="S", target="T", seed=1000.0, origin=OWNER, reason="stop"): + self.relay.on_message( + { + "op": "cancel", + "origin": origin, + "run_seq": 7, + "source": source, + "target": target, + "seed_ms": seed, + "reason": reason, + } + ) + + def run(self, prefix): + """Run the spawned threads whose name starts with prefix.""" + for name, fn, a in list(self.spawned): + if name.startswith(prefix): + fn(*a) + + def entry(self, source="S"): + return self.relay._table.get(source) + + +@pytest.fixture +def basic(): + """S (video, on the owner) --Auto follow--> T (local here).""" + t = _cue("T", local=True) + s = _cue("S", local=False, post_go="go_at_end", target=t) + return _Rig(_Script(s, t)) + + +class TestAnnounce: + def test_creates_an_entry_and_starts_prearm_and_waiter(self, basic): + basic.announce() + e = basic.entry() + assert e.state == "waiting" and e.instant == 1000.0 and e.origins == {OWNER} + assert e.arm_epoch == 3 and e.stop_epoch == 2 + names = sorted(n.split(":")[0] for n, _, _ in basic.spawned) + assert names == ["FollowPreArm", "FollowWait"] + + def test_ignores_its_own_announcement(self, basic): + basic.announce(origin=ME) + assert basic.entry() is None and basic.spawned == [] + + def test_ignores_a_source_local_here(self): + t = _cue("T", local=True) + s = _cue("S", local=True, post_go="go_at_end", target=t) + rig = _Rig(_Script(s, t)) + rig.announce() + assert rig.entry() is None and rig.spawned == [] + + @pytest.mark.parametrize( + "why", ["no_script", "no_mtc", "unknown_cue", "stale_run", "no_run"] + ) + def test_refuses_with_a_warning(self, basic, why): + kw = {} + if why == "no_script": + basic.script = None + elif why == "no_mtc": + basic.mtc = None + elif why == "unknown_cue": + kw["target"] = "nope" + elif why == "stale_run": + kw["run_seq"] = 6 + elif why == "no_run": + basic.relay.end_run("stop") + with patch("cuemsengine.cues.FollowRelay.Logger") as log: + basic.announce(**kw) + assert basic.entry() is None and basic.spawned == [] + assert log.warning.called + + def test_tolerates_a_message_that_is_not_a_dict(self, basic): + with patch("cuemsengine.cues.FollowRelay.Logger") as log: + basic.relay.on_message("garbage") + basic.relay.on_message(None) + assert log.warning.call_count == 2 + + def test_same_instant_from_another_owner_joins_the_entry(self, basic): + basic.announce() + basic.announce(origin=OTHER, seed=1000.4) + assert basic.entry().origins == {OWNER, OTHER} + assert len(basic.spawned) == 2 + + def test_a_new_instant_replaces_the_entry(self, basic): + basic.announce() + old = basic.entry() + basic.announce(seed=5000.0) + assert basic.entry() is not old and basic.entry().instant == 5000.0 + assert not basic.relay._is_current(old) + assert len(basic.spawned) == 4 + + def test_a_late_announcement_is_logged(self, basic): + basic.mtc.set(1500.0) + with patch("cuemsengine.cues.FollowRelay.Logger") as log: + basic.announce() + assert log.warning.called and not log.error.called + assert basic.entry().state == "waiting" + + def test_a_very_late_announcement_is_an_error_but_still_kept(self, basic): + basic.mtc.set(1000.0 + 10_001.0) + with patch("cuemsengine.cues.FollowRelay.Logger") as log: + basic.announce() + assert log.error.called + assert basic.entry().state == "waiting" + + +class TestWaiter: + def test_dispatches_at_the_instant_with_the_stored_epochs_and_a_gate(self, basic): + basic.announce() + basic.mtc.set(1000.0) + basic.run("FollowWait") + args, kw = basic.ch.go_from.call_args + assert args[0].id == "T" and args[1] is basic.mtc and args[2] == 1000.0 + assert kw["arm_epoch"] == 3 and kw["require_stop_epoch"] == 2 + assert callable(kw["commit_gate"]) + + def test_the_gate_records_the_dispatch(self, basic): + def go_from(target, mtc, seed, **kw): + cue = basic.script.find("T") + cue._armed_at = 42.0 + assert kw["commit_gate"](cue, 9) is True + return "thread" + + basic.ch.go_from.side_effect = go_from + basic.announce() + basic.mtc.set(1000.0) + basic.run("FollowWait") + e = basic.entry() + assert e.state == "dispatched" and e.cue.id == "T" and e.gen == 9 + assert e.disarm_epoch == 3 and e.armed_at == 42.0 + + def test_waits_for_the_instant(self, basic): + basic.announce() + basic.mtc.set(900.0) + basic.run("FollowWait") # the fake sleep advances 20 ms per poll + assert basic.mtc.main_tc.milliseconds_exact >= 1000.0 + basic.ch.go_from.assert_called_once() + + def test_a_cancel_while_waiting_ends_the_waiter(self, basic): + basic.announce() + basic.cancel() + basic.mtc.set(1000.0) + basic.run("FollowWait") + basic.ch.go_from.assert_not_called() + + def test_a_stop_while_waiting_ends_the_waiter(self, basic): + basic.announce() + basic.relay.end_run("stop") + basic.mtc.set(1000.0) + basic.run("FollowWait") + basic.ch.go_from.assert_not_called() + + def test_nothing_local_to_start_marks_it_done(self, basic): + basic.announce() + basic.mtc.set(1000.0) + basic.run("FollowWait") + assert basic.entry().state == "done" + + def test_an_exception_in_the_dispatch_is_logged_and_done(self, basic): + basic.ch.go_from.side_effect = RuntimeError("re-arm failed") + basic.announce() + basic.mtc.set(1000.0) + with patch("cuemsengine.cues.FollowRelay.Logger") as log: + basic.run("FollowWait") + assert log.error.called and basic.entry().state == "done" + + def test_yields_to_a_manual_go_during_the_postwait(self): + t = _cue("T", local=True) + s = _cue("S", post_go="go_at_end", target=t, postwait=0.5) + rig = _Rig(_Script(s, t)) + rig.announce(seed=1000.0) + + def sleep(_): + ms = rig.mtc.main_tc.milliseconds_exact + 20 + rig.mtc.set(ms) + if ms >= 700: + t._go_generation = 5 # the operator started T at ~700 ms + + rig.relay._sleep = sleep + rig.mtc.set(400.0) + rig.run("FollowWait") + rig.ch.go_from.assert_not_called() + assert rig.entry().state == "done" + + def test_does_not_yield_without_a_manual_go(self): + t = _cue("T", local=True) + s = _cue("S", post_go="go_at_end", target=t, postwait=0.5) + rig = _Rig(_Script(s, t)) + rig.announce(seed=1000.0) + rig.mtc.set(400.0) + rig.run("FollowWait") + rig.ch.go_from.assert_called_once() + + +class TestGate: + def _gate(self, rig): + captured = {} + + def go_from(target, mtc, seed, **kw): + captured["gate"] = kw["commit_gate"] + + rig.ch.go_from.side_effect = go_from + rig.announce() + rig.mtc.set(1000.0) + rig.run("FollowWait") + rig.entry().state = "dispatching" # as during go() + return captured["gate"] + + def test_refuses_a_cancelled_entry(self, basic): + gate = self._gate(basic) + basic.cancel() + assert gate(basic.script.find("T"), 1) is False + + def test_refuses_a_replaced_entry(self, basic): + gate = self._gate(basic) + basic.announce(seed=9000.0) + assert gate(basic.script.find("T"), 1) is False + + def test_refuses_after_a_stop_emptied_the_table(self, basic): + gate = self._gate(basic) + basic.relay.end_run("stop") + assert gate(basic.script.find("T"), 1) is False + + def test_refuses_after_a_new_run(self, basic): + gate = self._gate(basic) + basic.relay.begin_run({"run_seq": 8}) + assert gate(basic.script.find("T"), 1) is False + + +class TestCancel: + def _dispatched(self, rig, gen=9): + def go_from(target, mtc, seed, **kw): + cue = rig.script.find("T") + kw["commit_gate"](cue, gen) + return "thread" + + rig.ch.go_from.side_effect = go_from + rig.announce() + rig.mtc.set(1000.0) + rig.run("FollowWait") + assert rig.entry().state == "dispatched" + + def test_without_an_entry_does_nothing(self, basic): + basic.cancel() + assert basic.spawned == [] + + def test_for_another_instant_does_nothing(self, basic): + basic.announce() + basic.cancel(seed=2000.0) + assert basic.entry().state == "waiting" + + def test_an_error_from_one_of_two_owners_only_removes_that_owner(self, basic): + basic.announce() + basic.announce(origin=OTHER) + basic.cancel(origin=OTHER, reason="error") + assert basic.entry().state == "waiting" and basic.entry().origins == {OWNER} + + def test_while_waiting_cancels_the_entry(self, basic): + basic.announce() + basic.cancel() + assert basic.entry().state == "cancelled" + + def test_a_dispatched_cue_goes_to_the_guarded_stop(self, basic): + self._dispatched(basic) + basic.cancel(reason="restart") + basic.run("FollowStop") + args, kw = basic.ch.stop_dispatched_follow.call_args + assert args[0].id == "T" and args[1:] == (9, 3, None) + assert kw["may_cut"] is True and kw["grace_s"] == 2.0 + assert basic.entry().state == "cancelled" + + def test_an_error_cancel_may_not_cut_a_started_cue(self, basic): + self._dispatched(basic) + basic.cancel(reason="error") + basic.run("FollowStop") + assert basic.ch.stop_dispatched_follow.call_args.kwargs["may_cut"] is False + + def test_a_second_cancel_is_a_no_op(self, basic): + self._dispatched(basic) + basic.cancel() + basic.cancel() + stops = [n for n, _, _ in basic.spawned if n.startswith("FollowStop")] + assert len(stops) == 1 + + def test_arrival_order_is_applied_order(self, basic): + """Announce then cancel, as the bus delivers them: never dispatched.""" + basic.announce() + basic.cancel() + basic.mtc.set(1000.0) + basic.run("FollowWait") + basic.ch.go_from.assert_not_called() + + +class TestRun: + def test_the_same_run_keeps_its_entries(self, basic): + basic.announce() + basic.relay.begin_run({"run_seq": 7, "go_mtc_ms": 5.0}) + assert basic.entry() is not None + + def test_a_new_run_empties_the_table(self, basic): + basic.announce() + basic.relay.begin_run({"run_seq": 8}) + assert basic.entry() is None and basic.relay.run_seq == 8 + + @pytest.mark.parametrize("value", [None, "complex_test", {"run_seq": True}, {}]) + def test_a_go_without_a_run_counter_means_no_relay(self, basic, value): + basic.relay.begin_run(value) + assert basic.relay.run_seq is None + + def test_end_run_empties_everything(self, basic): + basic.announce() + basic.relay.end_run("stop") + assert basic.relay.run_seq is None and basic.relay._table == {} + + +class TestPreArm: + def test_arms_the_first_local_cue_with_the_entry_epoch(self, basic): + basic.announce() + basic.ch.arm.side_effect = lambda c, init, walk: setattr(c, "loaded", True) + basic.run("FollowPreArm") + args, kw = basic.ch.arm.call_args + assert args[0].id == "T" and kw["walk"].epoch == 3 + basic.ch._arm_ahead.assert_called_once() + + def test_runs_until_the_instant_and_rearms_what_became_unloaded(self, basic): + basic.announce(seed=100.0) + t = basic.script.find("T") + t.loaded = True # still playing an earlier pass + basic.ch.arm.side_effect = lambda c, init, walk: setattr(c, "loaded", True) + rounds = [] + + def sleep(_): + rounds.append(1) + basic.mtc.set(basic.mtc.main_tc.milliseconds_exact + 50) + if len(rounds) == 1: + t.loaded = False # the earlier pass ended and disarmed + + basic.relay._prearm_sleep = sleep + basic.run("FollowPreArm") + assert [c.args[0].id for c in basic.ch.arm.call_args_list] == ["T"] + + def test_arms_an_enabled_play_target(self): + from uuid import uuid4 + + from cuemsutils.cues import ActionCue + + x = _cue("X", local=True) + p = ActionCue.__new__(ActionCue) + p.id = str(uuid4()) + p.enabled = True + p.post_go = "pause" + p.action_type = "play" + p._local = True + p.loaded = True + p._target_object = None + p._go_generation = 0 + p._action_target_object = x + s = _cue("S", post_go="go_at_end", target=p) + rig = _Rig(_Script(s, p, x)) + rig.announce(target=str(p.id)) + rig.run("FollowPreArm") + assert "X" in [c.args[0].id for c in rig.ch.arm.call_args_list] + + def test_skips_a_disabled_play_target(self): + from uuid import uuid4 + + from cuemsutils.cues import ActionCue + + x = _cue("X", local=True, enabled=False) + p = ActionCue.__new__(ActionCue) + p.id = str(uuid4()) + p.enabled = True + p.post_go = "pause" + p.action_type = "play" + p._local = True + p.loaded = True + p._target_object = None + p._go_generation = 0 + p._action_target_object = x + s = _cue("S", post_go="go_at_end", target=p) + rig = _Rig(_Script(s, p, x)) + rig.announce(target=str(p.id)) + rig.run("FollowPreArm") + assert "X" not in [c.args[0].id for c in rig.ch.arm.call_args_list] + + def test_stops_when_the_entry_is_cancelled(self, basic): + basic.announce(seed=10_000.0) + basic.cancel(seed=10_000.0) + basic.run("FollowPreArm") + basic.ch.arm.assert_not_called() + + +class TestOwnerSend: + def test_announce_sends_the_message(self, basic): + t = basic.script.find("T") + s = _cue("S2", local=True, post_go="go_at_end", target=t) + basic.relay.announce(s, 1234.5, 7) + assert basic.sent == [ + { + "op": "announce", + "origin": ME, + "run_seq": 7, + "source": "S2", + "target": "T", + "seed_ms": 1234.5, + } + ] + + def test_cancel_carries_its_reason(self, basic): + t = basic.script.find("T") + s = _cue("S2", local=True, post_go="go_at_end", target=t) + basic.relay.cancel(s, 1234.5, 7, "stop") + assert basic.sent[0]["op"] == "cancel" and basic.sent[0]["reason"] == "stop" + + def test_a_failed_send_is_an_error_not_an_exception(self, basic): + basic.relay._send = MagicMock(side_effect=RuntimeError("no loop")) + t = basic.script.find("T") + s = _cue("S2", local=True, post_go="go_at_end", target=t) + with patch("cuemsengine.cues.FollowRelay.Logger") as log: + basic.relay.announce(s, 1.0, 7) + assert log.error.called + + +class TestReviewFixes: + def test_a_cancelled_entry_does_not_swallow_a_new_announcement(self, basic): + """MINOR-5: cancel(restart, I) then announce(I) for the same instant: + the new pass must still play here.""" + basic.announce() + basic.cancel(reason="restart") + basic.announce() + assert basic.entry().state == "waiting" + assert len([n for n, _, _ in basic.spawned if n.startswith("FollowWait")]) == 2 + + def test_a_cancel_of_another_run_is_ignored(self, basic): + """MINOR-7.""" + basic.announce() + basic.relay.on_message( + { + "op": "cancel", + "origin": OWNER, + "run_seq": 6, + "source": "S", + "target": "T", + "seed_ms": 1000.0, + "reason": "stop", + } + ) + assert basic.entry().state == "waiting" + + def test_the_gate_records_a_cue_already_on_stage(self, basic): + """MINOR-3: the follow restarts a cue still playing an earlier pass.""" + from time import monotonic + + t = basic.script.find("T") + t._playing, t._revealed, t._revealed_at = True, True, monotonic() - 30 + + def go_from(target, mtc, seed, **kw): + kw["commit_gate"](t, 9) + + basic.ch.go_from.side_effect = go_from + basic.announce() + basic.mtc.set(1000.0) + basic.run("FollowWait") + assert basic.entry().started_before == t._revealed_at + basic.cancel(reason="error") + basic.run("FollowStop") + kw = basic.ch.stop_dispatched_follow.call_args.kwargs + assert kw["started_before"] == t._revealed_at + + def test_stop_pending_defers_the_epochs_and_the_dispatch(self, basic): + """MINOR-4: a STOP was received but has not run yet on this node: the + epochs are read only once it has, and nothing is dispatched before.""" + basic.relay.end_run("stop") # received + basic.relay.begin_run({"run_seq": 7}) # the next GO, received + assert basic.relay.stop_pending + basic.announce() + e = basic.entry() + assert e.arm_epoch is None + basic.mtc.set(1000.0) + polls = [] + + def sleep(_): + polls.append(1) + if len(polls) == 3: + basic.ch._disarm_epoch = 4 # the STOP runs ... + basic.ch._last_stop_chain_epoch = 5 + basic.relay.stop_applied() # ... and is applied + + basic.relay._sleep = sleep + basic.run("FollowWait") + kw = basic.ch.go_from.call_args.kwargs + assert kw["arm_epoch"] == 4 and kw["require_stop_epoch"] == 5 + + def test_stop_pending_blocks_the_prearm(self, basic): + basic.relay.end_run("stop") + basic.relay.begin_run({"run_seq": 7}) + basic.announce(seed=60.0) + basic.run("FollowPreArm") + basic.ch.arm.assert_not_called() + + +class TestRealGoAndGate: + """MINOR-8: the real go() evaluating the real gate, both locks nested.""" + + def _ch(self): + from threading import Lock + + from cuemsengine.cues.CueHandler import CueHandler + + ch = object.__new__(CueHandler) + ch._lock = Lock() + ch._armed_cues = [] + ch._armed_cues_set = set() + ch._arm_ahead = MagicMock() + ch.arm = MagicMock() + return ch + + def _rig(self, ch): + t = _cue("T", local=True, loaded=True) + s = _cue("S", post_go="go_at_end", target=t) + rig = _Rig(_Script(s, t)) + rig.relay._ch = ch + return rig, t + + def test_dispatches_through_the_gate(self): + from cuemsengine.cues.CueHandler import CueHandler + + ch = self._ch() + rig, t = self._rig(ch) + rig.announce() + rig.mtc.set(1000.0) + with patch.object(CueHandler, "go_threaded"): + rig.run("FollowWait") + e = rig.entry() + assert e.state == "dispatched" and e.cue is t and e.gen == t._go_generation + + def test_a_cancel_while_inside_go_refuses_the_commit(self): + """The cancel lands while go() is in its fallback arm: the gate, run + later inside go()'s commit section, refuses.""" + from cuemsengine.cues.CueHandler import CueHandler + + ch = self._ch() + rig, t = self._rig(ch) + t.loaded = False + + def arm_and_cancel(c, init=False, epoch=None, **kw): + rig.cancel() # arrives on the bus during the arm + c.loaded = True + return True + + ch.arm.side_effect = arm_and_cancel + rig.announce() + rig.mtc.set(1000.0) + with patch.object(CueHandler, "go_threaded") as gt: + rig.run("FollowWait") + gt.assert_not_called() + assert rig.entry().state == "cancelled" and t._go_generation == 0 diff --git a/tests/test_dispatch_reorder.py b/tests/test_dispatch_reorder.py index 39c79701..233b8bd7 100644 --- a/tests/test_dispatch_reorder.py +++ b/tests/test_dispatch_reorder.py @@ -345,7 +345,9 @@ def test_a_continuation_arms_on_its_own_thread(self): cue = _cue() cue.loaded = False ch.arm = MagicMock( - side_effect=lambda c, init=False, epoch=None: setattr(c, "loaded", True) + side_effect=lambda c, init=False, epoch=None, wait_report=None: setattr( + c, "loaded", True + ) ) mtc = _FakeMtc(0) with ( @@ -355,7 +357,7 @@ def test_a_continuation_arms_on_its_own_thread(self): patch("cuemsengine.cues.CueHandler.sleep", side_effect=mtc.advance), ): ch.go_threaded(cue, mtc, 0.0, cue._go_generation, 1) - ch.arm.assert_called_once_with(cue, init=True, epoch=None) + ch.arm.assert_called_once_with(cue, init=True, epoch=None, wait_report={}) rv.assert_called_once() def test_an_unarmable_cue_dies_alone(self): @@ -388,7 +390,7 @@ def test_an_arm_that_overruns_the_runway_warns_late(self): cue.loaded = False mtc = _FakeMtc(0) - def slow_arm(c, init=False, epoch=None): + def slow_arm(c, init=False, epoch=None, wait_report=None): mtc.advance(20) # 20s of JACK port waiting c.loaded = True diff --git a/tests/test_loop_video_wraparound.py b/tests/test_loop_video_wraparound.py new file mode 100644 index 00000000..5bcc5c79 --- /dev/null +++ b/tests/test_loop_video_wraparound.py @@ -0,0 +1,83 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera + +"""loop_videoCue must only enable videocomposer wraparound for cues that repeat. + +869fa89uh: `/loop 1` used to be sent for every video cue. The videocomposer +runs its display latency ahead of MTC, so a play-once cue reached end of file +before the engine hid the layer, wrapped, and showed its first frame again. +""" + +from __future__ import annotations + +from types import SimpleNamespace + +from cuemsutils.cues import VideoCue +from cuemsutils.tools.CTimecode import CTimecode + +from cuemsengine.cues.loop_cue import loop_cue + +LAYER = "cue_0" +LOOP_PATH = f"/videocomposer/layer/{LAYER}/loop" +OFFSET_PATH = f"/videocomposer/layer/{LAYER}/offset" + + +class _PastEndMtc: + """MTC that is always past any cue end, so every pass finishes at once.""" + + framerate = 25 + milliseconds_rounded = 10**12 + + @property + def main_tc(self): + return self + + +class _RecordingOsc: + def __init__(self, cue, stop_after=None): + self.calls = [] + self._cue = cue + self._stop_after = stop_after + + def set_value(self, path, value): + self.calls.append((path, value)) + if self._stop_after is not None and len(self.calls) >= self._stop_after: + self._cue._stop_requested = True + + +def _run(loop, stop_after=None): + cue = SimpleNamespace( + id="cue", + loop=loop, + media=SimpleNamespace(duration="00:00:10.000"), + _layer_ids=[LAYER], + _local=True, + _stop_requested=False, + _start_mtc=CTimecode(framerate=25, frames=1), + _end_mtc=CTimecode(framerate=25, frames=251), + ) + cue._osc = _RecordingOsc(cue, stop_after) + loop_cue.registry[VideoCue](cue, _PastEndMtc()) + return cue._osc.calls + + +def test_play_once_cue_never_enables_wraparound(): + assert _run(loop=1) == [] + + +def test_counted_loop_wraps_then_clamps_on_its_last_pass(): + calls = _run(loop=3) + assert calls[0] == (LOOP_PATH, 1) + assert [c for c in calls if c[0] == LOOP_PATH] == [(LOOP_PATH, 1), (LOOP_PATH, 0)] + # two rebases (passes 2 and 3); /loop 0 comes right after the last offset + offsets = [i for i, c in enumerate(calls) if c[0] == OFFSET_PATH] + assert len(offsets) == 2 + assert calls.index((LOOP_PATH, 0)) == offsets[-1] + 1 + assert calls[-1] == (LOOP_PATH, 0) + + +def test_infinite_loop_keeps_wrapping(): + calls = _run(loop=-1, stop_after=6) + assert calls[0] == (LOOP_PATH, 1) + assert (LOOP_PATH, 0) not in calls diff --git a/tests/test_node_comms_ping.py b/tests/test_node_comms_ping.py index 80cfe751..c8d639d8 100644 --- a/tests/test_node_comms_ping.py +++ b/tests/test_node_comms_ping.py @@ -14,6 +14,8 @@ """ import asyncio +import logging +import threading from unittest.mock import AsyncMock, MagicMock import pytest @@ -123,3 +125,21 @@ def test_non_command_type_returns_early(comms): comms._handle_command_operation(status_op) assert comms.nng_hub.send_operation.call_count == 0 comms._command_callback.assert_not_called() + + +def test_a_failing_command_callback_is_logged_with_its_traceback(comms, caplog): + # 869evtdf7: a load that died on an EPERM left only "Error executing + # command callback for load: [Errno 1] Operation not permitted" — no + # step, no line. The traceback says where it came from. + comms._command_callback.side_effect = PermissionError(1, "Operation not permitted") + with caplog.at_level(logging.ERROR): + comms._handle_command_operation(_normal_command_op("load")) + for t in threading.enumerate(): + if t.name == "NNG-Command-load": + t.join(timeout=5) + + errors = [r for r in caplog.records if r.levelno == logging.ERROR] + assert len(errors) == 1 + assert "load" in errors[0].getMessage() + assert errors[0].exc_info is not None + assert errors[0].exc_info[0] is PermissionError diff --git a/tests/test_node_engine_load_orphan_eperm.py b/tests/test_node_engine_load_orphan_eperm.py new file mode 100644 index 00000000..d043ae2c --- /dev/null +++ b/tests/test_node_engine_load_orphan_eperm.py @@ -0,0 +1,107 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera + +"""A node load goes on when an orphan cannot be killed (869evtdf7). + +On 2026-09-04 a hand-launched test player owned by another user made every +load on a node fail: kill_orphaned_audio_processes got EPERM, the exception +left _load_project_inner after the old project was torn down and before the +new one was armed, and the only trace was "Error executing command callback +for load: [Errno 1] Operation not permitted". + +Here the sweep runs for real (only pgrep and os.kill are faked) and the rest +of the load is stubbed as in test_node_engine_gradient.py. +""" + +from __future__ import annotations + +import contextlib +import logging +import threading +from unittest.mock import MagicMock, Mock, patch + + +def _make_ne_for_load(): + from cuemsengine.NodeEngine import NodeEngine + + ne = NodeEngine.__new__(NodeEngine) + ne._command_lock = threading.Lock() + ne._loading_lock = threading.Lock() + ne._loading = False + ne.cm = MagicMock() + ne.cm.node_uuid = "node-001" + ne.cm.node_conf = {"gradient_osc_port": "7100", "nng_hub_port": "5555"} + ne.cm.node_network_map = {} + ne._project_generation = 0 + ne.script = MagicMock() + ne.script.unix_name = "old-project" + ne.mtc_listener = None + return ne + + +def _load_patches(ne): + from cuemsengine.cues.CueHandler import CUE_HANDLER + from cuemsengine.players.PlayerHandler import PLAYER_HANDLER + + return { + "deploy": patch.object(ne, "deploy_project", return_value=True), + "gc": patch.object(PLAYER_HANDLER, "get_gradient_client", return_value=None), + "dmx": patch.object(PLAYER_HANDLER, "get_dmx_player_client", return_value=None), + "mixer": patch.object( + PLAYER_HANDLER, "get_audio_mixer_client", return_value=None + ), + "kill_all": patch.object(PLAYER_HANDLER, "kill_all_audio_players"), + "zombies": patch.object(PLAYER_HANDLER, "cleanup_zombie_jack_clients"), + "video": patch.object(ne, "unload_video_devs"), + "get_status": patch.object(ne, "get_status", return_value="no"), + "set_status": patch.object(ne, "set_status"), + "ready_project": patch.object(ne, "ready_project"), + "ready_script": patch.object(ne, "ready_script"), + "lock_file": patch.object(ne, "set_show_lock_file"), + "nextcue": patch.object(ne, "_broadcast_nextcue"), + "disarm": patch.object(CUE_HANDLER, "disarm_all"), + "stop": patch.object(CUE_HANDLER, "stop_all_cues"), + # Only the OS is faked under the sweep: pgrep lists one untracked + # player, and killing it is not permitted. + "pgrep": patch( + "cuemsengine.players.PlayerHandler.subprocess.run", + return_value=Mock(returncode=0, stdout="4432\n", stderr=""), + ), + "kill": patch( + "os.kill", side_effect=PermissionError(1, "Operation not permitted") + ), + } + + +def test_load_reaches_the_new_project_when_an_orphan_kill_is_not_permitted(caplog): + ne = _make_ne_for_load() + with contextlib.ExitStack() as stack: + mocks = {k: stack.enter_context(p) for k, p in _load_patches(ne).items()} + with caplog.at_level(logging.WARNING): + ne._load_project_inner("new-project") + + mocks["kill"].assert_called_once() + mocks["disarm"].assert_called_once() + mocks["ready_project"].assert_called_once_with("new-project") + mocks["ready_script"].assert_called_once() + mocks["lock_file"].assert_called_once() + assert any( + "Cannot kill" in r.getMessage() and "4432" in r.getMessage() + for r in caplog.records + ) + + +def test_set_players_checks_the_binary_names_the_cleanup_relies_on(): + # G4b: a configured player binary with another name escapes every orphan + # cleanup; the node says so at start. + ne = _make_ne_for_load() + with ( + patch.object(ne, "set_video_players"), + patch.object(ne, "set_audio_players"), + patch.object(ne, "set_dmx_players"), + patch.object(ne, "set_gradient_client"), + patch("cuemsengine.NodeEngine.check_orphan_binary_names") as check, + ): + ne.set_players() + check.assert_called_once_with(ne.cm.node_conf) diff --git a/tests/test_player_handler_mixer_orphan.py b/tests/test_player_handler_mixer_orphan.py index 99ae8d40..aca1a2e9 100644 --- a/tests/test_player_handler_mixer_orphan.py +++ b/tests/test_player_handler_mixer_orphan.py @@ -12,6 +12,7 @@ shells out to pgrep / os.kill, so a lightweight stand-in is enough. """ +import os from types import SimpleNamespace from unittest.mock import Mock, patch @@ -33,8 +34,11 @@ def _run_kill(fake_self, stdout, returncode=0): def test_kills_all_untracked_when_no_mixer(): fake = SimpleNamespace(_audio_mixer=None) run, kill = _run_kill(fake, "111\n222\n") + # Own user only (869evtdf7): another user's process is not ours to kill. run.assert_called_once_with( - ["pgrep", "-f", "jack-volume -c"], capture_output=True, text=True + ["pgrep", "-u", str(os.geteuid()), "-f", "jack-volume -c"], + capture_output=True, + text=True, ) assert sorted(c.args[0] for c in kill.call_args_list) == [111, 222] diff --git a/tests/test_player_handler_orphan_kill.py b/tests/test_player_handler_orphan_kill.py new file mode 100644 index 00000000..a329365e --- /dev/null +++ b/tests/test_player_handler_orphan_kill.py @@ -0,0 +1,324 @@ +# SPDX-FileCopyrightText: 2026 Stagelab Coop SCCL +# SPDX-License-Identifier: GPL-3.0-or-later +# SPDX-FileContributor: Ion Reguera + +"""Orphan sweeps never abort their caller, and match only our own players +(869evtdf7). + +kill_orphaned_audio_processes runs in the middle of a node's project load, +kill_orphaned_mixer_processes right before the mixer starts. An exception +from either one used to escape: an orphan owned by another user (EPERM) sank +the whole load after the old project was torn down, or left the node without +a mixer. The sweeps are hygiene, not a precondition: every failure is logged +and the sweep goes on. + +They also used to match any command line that merely contained the binary +name, owned by anyone (an operator's `tail -f …/cuems-audioplayer.log`, another +user's process). Now they list only processes of the engine's own user whose +argv[0] is the player binary. + +The sweeps are called unbound on lightweight stand-ins, like +test_player_handler_mixer_orphan.py does. +""" + +import importlib +import logging +import os +import re +import threading +from types import SimpleNamespace +from unittest.mock import Mock, patch + +import pytest + +from cuemsengine.players.PlayerHandler import PlayerHandler + +# The module, not the class of the same name. +ph = importlib.import_module("cuemsengine.players.PlayerHandler") + +RUN = "cuemsengine.players.PlayerHandler.subprocess.run" + + +def _audio_self(tracked=()): + players = { + f"cue-{pid}": SimpleNamespace(p=SimpleNamespace(pid=pid)) for pid in tracked + } + return SimpleNamespace(_lock=threading.RLock(), _audio_players_by_id=players) + + +def _mixer_self(): + return SimpleNamespace(_audio_mixer=None) + + +def _proc(stdout="", returncode=0, stderr=""): + return Mock(returncode=returncode, stdout=stdout, stderr=stderr) + + +def _sweep_audio(fake, run_kw, kill_kw): + with patch(RUN, **run_kw) as run, patch("os.kill", **kill_kw) as kill: + PlayerHandler.kill_orphaned_audio_processes(fake) + return run, kill + + +def _sweep_mixer(fake, run_kw, kill_kw): + with patch(RUN, **run_kw) as run, patch("os.kill", **kill_kw) as kill: + PlayerHandler.kill_orphaned_mixer_processes(fake) + return run, kill + + +SWEEPS = [ + pytest.param(_audio_self, _sweep_audio, "audioplayer", id="audio"), + pytest.param(_mixer_self, _sweep_mixer, "jack-volume mixer", id="mixer"), +] + + +def _warnings(caplog): + return [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING] + + +# --------------------------------------------------------------------------- +# What pgrep is asked for +# --------------------------------------------------------------------------- + + +def test_audio_sweep_lists_own_user_cuems_audioplayer_only(): + run, _kill = _sweep_audio(_audio_self(), {"return_value": _proc(returncode=1)}, {}) + run.assert_called_once_with( + ["pgrep", "-u", str(os.geteuid()), "-f", ph.AUDIOPLAYER_ORPHAN_PATTERN], + capture_output=True, + text=True, + ) + + +def test_mixer_sweep_lists_own_user_only(): + run, _kill = _sweep_mixer(_mixer_self(), {"return_value": _proc(returncode=1)}, {}) + run.assert_called_once_with( + ["pgrep", "-u", str(os.geteuid()), "-f", "jack-volume -c"], + capture_output=True, + text=True, + ) + + +@pytest.mark.parametrize( + "cmdline, matches", + [ + ( + "/usr/bin/cuems-audioplayer --port 7001 --uuid ab12 " + "/opt/cuems_library/media/x.wav", + True, + ), + ("/usr/local/bin/cuems-audioplayer --port 7001 x.wav", True), + ("cuems-audioplayer", True), + ("tail -f /var/log/cuems-audioplayer.log", False), + ("grep cuems-audioplayer", False), + ('/bin/sh -c /usr/bin/pkill -u cuems -f "cuems-audioplayer"', False), + ("/usr/local/bin/cuems-audioplayer-slow --port 7001 x.wav", False), + ("/usr/bin/cuems-audioplayer.bak --port 1", False), + ], +) +def test_audioplayer_pattern(cmdline, matches): + # pgrep matches a POSIX ERE against the space-joined cmdline; Python's re + # agrees with ERE on this pattern. + assert bool(re.search(ph.AUDIOPLAYER_ORPHAN_PATTERN, cmdline)) is matches + + +# --------------------------------------------------------------------------- +# A kill that fails never escapes +# --------------------------------------------------------------------------- + + +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_eperm_is_logged_and_the_sweep_goes_on(make_self, sweep, label, caplog): + def kill(pid, _sig): + if pid == 111: + raise PermissionError(1, "Operation not permitted") + + with ( + caplog.at_level(logging.WARNING), + patch.object(ph, "_pid_owner", return_value="stagelab(1000)"), + ): + _run, killer = sweep( + make_self(), {"return_value": _proc("111\n222\n")}, {"side_effect": kill} + ) + + # The second orphan is still killed. + assert [c.args[0] for c in killer.call_args_list] == [111, 222] + eperm = [m for m in _warnings(caplog) if "Cannot kill" in m] + assert len(eperm) == 1 + assert "111" in eperm[0] + assert label in eperm[0] + assert "stagelab(1000)" in eperm[0] + + +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_esrch_is_silent(make_self, sweep, label, caplog): + with caplog.at_level(logging.WARNING): + sweep( + make_self(), + {"return_value": _proc("111\n")}, + {"side_effect": ProcessLookupError}, + ) + assert not [m for m in _warnings(caplog) if "Cannot kill" in m] + + +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_any_other_kill_error_is_logged_and_the_sweep_goes_on( + make_self, sweep, label, caplog +): + with caplog.at_level(logging.WARNING): + _run, killer = sweep( + make_self(), + {"return_value": _proc("111\n222\n")}, + {"side_effect": RuntimeError("boom")}, + ) + assert [c.args[0] for c in killer.call_args_list] == [111, 222] + assert len([m for m in _warnings(caplog) if "Cannot kill" in m]) == 2 + + +# --------------------------------------------------------------------------- +# pgrep itself failing +# --------------------------------------------------------------------------- + + +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_pgrep_no_match_is_silent(make_self, sweep, label, caplog): + with caplog.at_level(logging.WARNING): + _run, killer = sweep(make_self(), {"return_value": _proc(returncode=1)}, {}) + killer.assert_not_called() + assert _warnings(caplog) == [] + + +@pytest.mark.parametrize("rc", [2, 3]) +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_pgrep_error_is_logged_not_silent(make_self, sweep, label, rc, caplog): + proc = _proc(returncode=rc, stderr="pgrep: invalid user name: x") + with caplog.at_level(logging.WARNING): + _run, killer = sweep(make_self(), {"return_value": proc}, {}) + killer.assert_not_called() + msgs = _warnings(caplog) + assert any(f"rc {rc}" in m and "invalid user name" in m for m in msgs), msgs + + +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_pgrep_that_cannot_run_is_logged(make_self, sweep, label, caplog): + with caplog.at_level(logging.WARNING): + _run, killer = sweep( + make_self(), {"side_effect": FileNotFoundError("pgrep")}, {} + ) + killer.assert_not_called() + assert _warnings(caplog) + + +@pytest.mark.parametrize("make_self, sweep, label", SWEEPS) +def test_a_bad_pgrep_line_is_skipped_not_fatal(make_self, sweep, label, caplog): + with caplog.at_level(logging.WARNING): + _run, killer = sweep(make_self(), {"return_value": _proc("abc\n222\n")}, {}) + assert [c.args[0] for c in killer.call_args_list] == [222] + assert any("abc" in m for m in _warnings(caplog)) + + +def test_audio_sweep_spares_tracked_players(): + _run, killer = _sweep_audio( + _audio_self(tracked=[222]), {"return_value": _proc("111\n222\n")}, {} + ) + assert [c.args[0] for c in killer.call_args_list] == [111] + + +# --------------------------------------------------------------------------- +# The owner named in the EPERM warning +# --------------------------------------------------------------------------- + + +def test_pid_owner_of_this_process_names_its_uid(): + assert f"({os.getuid()})" in ph._pid_owner(os.getpid()) + + +def test_pid_owner_names_a_differing_effective_uid(): + status = "Name:\tx\nUid:\t0\t4242\t0\t4242\nGid:\t0\t0\t0\t0\n" + users = {0: "root", 4242: "cuems"} + with ( + patch("builtins.open", Mock(return_value=_FakeFile(status))), + patch.object( + ph.pwd, "getpwuid", side_effect=lambda u: SimpleNamespace(pw_name=users[u]) + ), + ): + owner = ph._pid_owner(1234) + assert owner == "root(0), euid cuems(4242)" + + +def test_pid_owner_of_a_vanished_process_is_unknown(): + with patch("builtins.open", side_effect=FileNotFoundError): + assert ph._pid_owner(999999) == "?" + + +class _FakeFile: + def __init__(self, text): + self._text = text + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def read(self): + return self._text + + def __iter__(self): + return iter(self._text.splitlines(keepends=True)) + + +# --------------------------------------------------------------------------- +# The binary names the cleanup relies on (G4b) +# --------------------------------------------------------------------------- + +CANONICAL = { + "audioplayer": {"path": "/usr/bin/cuems-audioplayer", "args": ""}, + "audiomixer": {"path": "/usr/bin/jack-volume", "args": ""}, + "dmxplayer": {"path": "/usr/bin/cuems-dmxplayer", "args": ""}, +} + + +def test_canonical_binary_names_pass_silently(caplog): + with caplog.at_level(logging.WARNING): + assert ph.check_orphan_binary_names(CANONICAL) == [] + assert _warnings(caplog) == [] + + +def test_cuems_jack_volume_is_a_known_mixer_name(): + conf = dict(CANONICAL, audiomixer={"path": "/usr/local/bin/cuems-jack-volume"}) + assert ph.check_orphan_binary_names(conf) == [] + + +def test_an_unknown_binary_name_is_warned(caplog): + conf = dict(CANONICAL, audioplayer={"path": "/opt/x/audioplayer-cuems"}) + with caplog.at_level(logging.WARNING): + assert ph.check_orphan_binary_names(conf) == ["audioplayer"] + msgs = _warnings(caplog) + assert len(msgs) == 1 + assert "audioplayer-cuems" in msgs[0] + assert "cuems-audioplayer" in msgs[0] + + +def test_missing_keys_are_skipped(caplog): + with caplog.at_level(logging.WARNING): + assert ph.check_orphan_binary_names({"gradient_osc_port": "7100"}) == [] + assert _warnings(caplog) == [] + + +# --------------------------------------------------------------------------- +# The zombie JACK client cleanup never aborts a load either (G7) +# --------------------------------------------------------------------------- + + +def test_zombie_cleanup_survives_a_jack_error(caplog): + conn_man = Mock() + conn_man.get_ports.side_effect = RuntimeError("JACK server not running") + fake = SimpleNamespace( + _audio_mixer=SimpleNamespace(conn_man=conn_man), + _lock=threading.RLock(), + _audio_players_by_id={}, + ) + with caplog.at_level(logging.WARNING): + assert PlayerHandler.cleanup_zombie_jack_clients(fake) == 0 + assert any("zombie" in m.lower() for m in _warnings(caplog)) diff --git a/tests/test_player_handler_port_wait_abort.py b/tests/test_player_handler_port_wait_abort.py index a75e037f..96b37279 100644 --- a/tests/test_player_handler_port_wait_abort.py +++ b/tests/test_player_handler_port_wait_abort.py @@ -66,3 +66,31 @@ def test_an_exited_process_aborts_the_wait(): def test_a_player_without_a_process_yet_does_not_abort_the_wait(): assert _should_abort(SimpleNamespace(p=None))() is False + + +# 869fbyjzx: the wiring waits for the player's own readiness event. The whole +# fix hangs on this one argument, so it has its own tests. + + +def _wire(player): + ph = _handler(player) + with patch("cuemsengine.players.PlayerHandler.PORT_HANDLER") as ports: + ports.assign_ports.return_value = {"audio_output": 9999} + ph.new_audio_output(_cue()) + return ph._audio_mixer.connect_player_to_outputs.call_args.kwargs + + +def test_the_players_ready_event_reaches_the_wiring(): + from threading import Event + + player = SimpleNamespace(p=None, ready=Event()) + assert _wire(player)["ready"] is player.ready + + +def test_a_player_without_a_ready_event_warns_and_is_wired_on_the_port(caplog): + import logging + + with caplog.at_level(logging.WARNING): + kwargs = _wire(SimpleNamespace(p=None)) + assert kwargs["ready"] is None + assert "has no ready event" in caplog.text diff --git a/tests/test_players_audiomixer.py b/tests/test_players_audiomixer.py index 0c97fa20..e777512f 100644 --- a/tests/test_players_audiomixer.py +++ b/tests/test_players_audiomixer.py @@ -3,7 +3,9 @@ # SPDX-FileContributor: Adrià Masip # SPDX-FileContributor: Ion Reguera +import contextlib import logging +import threading from unittest.mock import MagicMock, Mock, call, patch import pytest @@ -17,6 +19,28 @@ from cuemsengine.players.JackConnectionManager import JackConnectionManager +@contextlib.contextmanager +def _this_thread_sleeps(): + """Patch time.sleep (connect_player_to_outputs imports it at call time) + and record only the calls made by the test's own thread. + + Patching time.sleep is process-wide: under pytest-xdist, threads left + running by other tests in the same worker sleep through the patch too. + Counting every call once added 6083 s of foreign sleeps to a sub-second + budget check and failed CI on an unrelated PR (869fbyjzx test, found + 2026-10-08 on PR #25). Foreign calls are still swallowed, as before. + """ + me = threading.get_ident() + calls = [] + + def fake_sleep(seconds): + if threading.get_ident() == me: + calls.append(seconds) + + with patch("time.sleep", side_effect=fake_sleep): + yield calls + + class TestAudioMixer: """Test cases for AudioMixer class.""" @@ -60,7 +84,6 @@ def test_audio_mixer_initialization(self, mock_audio_outputs, mock_conn_manager) patch("cuemsengine.players.AudioMixer.sleep"), patch.object(AudioMixer, "call_subprocess"), ): - mixer = AudioMixer( audio_outputs=mock_audio_outputs, port=8000, mixer_id="test-node-123" ) @@ -79,7 +102,6 @@ def test_audio_mixer_initialization_with_custom_path( patch("cuemsengine.players.AudioMixer.sleep"), patch.object(AudioMixer, "call_subprocess"), ): - mixer = AudioMixer( audio_outputs=mock_audio_outputs, port=8000, @@ -227,13 +249,13 @@ def test_port_never_registers_returns_false_no_connect(self): ports = {"test_mixer:input_1", "test_mixer:input_2"} cm = _fake_conn_man(ports) m = _build_bare_mixer(self.OUTS, cm) - with patch("time.sleep") as mock_sleep: + with _this_thread_sleeps() as sleeps: result = m.connect_player_to_outputs(self.PLAYER, "outport", self.OUTS) assert result is False cm.connect_by_name.assert_not_called() # The wait loop must actually have waited (the old defeated guard # broke on attempt 0 without a single sleep). - assert mock_sleep.call_count >= 29 + assert len(sleeps) >= 29 def test_a_dead_player_process_ends_the_wait(self, caplog): """869f9wqpn: a STOP (or a load) kills the player while the engine @@ -248,25 +270,25 @@ def process_gone(): polls.append(1) return len(polls) > 2 # alive twice, then dead - with caplog.at_level("WARNING"), patch("time.sleep") as mock_sleep: + with caplog.at_level("WARNING"), _this_thread_sleeps() as sleeps: result = m.connect_player_to_outputs( self.PLAYER, "outport", self.OUTS, should_abort=process_gone ) assert result is False cm.connect_by_name.assert_not_called() - assert mock_sleep.call_count == 2, "kept waiting for a dead process" + assert len(sleeps) == 2, "kept waiting for a dead process" assert "exited before registering" in caplog.text def test_a_live_player_still_gets_the_whole_wait(self): ports = {"test_mixer:input_1", "test_mixer:input_2"} cm = _fake_conn_man(ports) m = _build_bare_mixer(self.OUTS, cm) - with patch("time.sleep") as mock_sleep: + with _this_thread_sleeps() as sleeps: result = m.connect_player_to_outputs( self.PLAYER, "outport", self.OUTS, should_abort=lambda: False ) assert result is False - assert mock_sleep.call_count >= 29 + assert len(sleeps) >= 29 def test_registered_ports_win_over_the_abort_check(self): ports = {"test_mixer:input_1", "test_mixer:input_2", self.CH0, self.CH1} @@ -384,7 +406,11 @@ class TestPlayerConnectionsCorrect: """Pin the routing equivalence between player_connections_correct and connect_player_to_outputs. If connect_player_to_outputs is refactored and these diverge, run_audioCue will silently choose the wrong branch - on every GO.""" + on every GO. + + 869fbyjzx: the check is now a diff built on one get_connections per + outport (both share _expected_edges), so the mock answers + get_connections; every case and its intent is unchanged.""" @staticmethod def _build_mixer(audio_outputs, conn_man): @@ -403,6 +429,7 @@ def _make_conn_man(existing_ports, edges): cm = Mock() cm.port_exists.side_effect = lambda p: p in existing_ports cm.is_connected.side_effect = lambda src, dst: dst in edges.get(src, []) + cm.get_connections.side_effect = lambda p: list(edges.get(p, [])) return cm def test_stereo_all_edges_correct_returns_true(self): @@ -525,9 +552,8 @@ def test_mono_does_not_check_outport_1(self): "outport", ["system:playback_1", "system:playback_2"], ) - # is_connected must never be called with outport 1 as source on a mono - # player. - for c in cm.is_connected.call_args_list: + # Outport 1 must never be read on a mono player. + for c in cm.get_connections.call_args_list + cm.is_connected.call_args_list: assert ( c.args[0] != "Audio_Player-X:outport 1" ), f"mono check leaked an outport 1 probe: {c}" @@ -587,10 +613,11 @@ def test_subprocess_crashed_returns_false_immediately(self): ) # No edge probes when port is gone. cm.is_connected.assert_not_called() + cm.get_connections.assert_not_called() def test_query_count_is_linear_in_selected_outputs(self): - # 8 outputs → at most 8 is_connected calls. Quadratic blowup - # under refactor would push this over the bound. + # 8 outputs → one get_connections per outport (2), whatever the + # number of outputs; it runs on the GO path before /offset. n = 8 audio_outputs = [f"system:playback_{i+1}" for i in range(n)] existing_ports = {f"test_mixer:input_{i+1}" for i in range(n)} @@ -618,7 +645,8 @@ def test_query_count_is_linear_in_selected_outputs(self): ) is True ) - assert cm.is_connected.call_count == n + assert cm.get_connections.call_count == 2 + cm.is_connected.assert_not_called() class TestMixerClient: @@ -750,7 +778,6 @@ def test_add_to_oscquery_server(self, mixer_client): "cuemsengine.players.AudioMixer.add_callback_to_all" ) as mock_add_callback, ): - mixer_client.add_to_oscquery_server(mock_server) mock_add_callback.assert_called_once() @@ -798,7 +825,6 @@ def test_start_audio_mixer(self): patch("cuemsengine.players.AudioMixer.MixerClient") as mock_client_class, patch("cuemsengine.players.AudioMixer.sleep"), ): - # Mock mixer instance mock_mixer = Mock() mock_mixer.pid = 12345 @@ -838,7 +864,6 @@ def test_start_audio_mixer_with_custom_path(self): patch("cuemsengine.players.AudioMixer.MixerClient") as mock_client_class, patch("cuemsengine.players.AudioMixer.sleep"), ): - mock_mixer = Mock() mock_mixer.pid = 12345 mock_mixer_class.return_value = mock_mixer @@ -933,3 +958,449 @@ def test_snapshot_is_a_copy(self, mixer_client): snap = mixer_client.snapshot() snap["master"] = 0.0 assert mixer_client.snapshot() == {"master": 0.5} + + +# --------------------------------------------------------------------------- +# 869fbyjzx — wire an audio player only once it reports itself started, and +# check / repair its wiring at GO edge by edge. +# --------------------------------------------------------------------------- + +PL = "Audio_Player-X" +P0 = f"{PL}:outport 0" +P1 = f"{PL}:outport 1" +IN1, IN2, IN3, IN4 = (f"test_mixer:input_{i}" for i in range(1, 5)) +OUTS2 = ["system:playback_1", "system:playback_2"] +OUTS4 = [f"system:playback_{i}" for i in range(1, 5)] + + +class _ReadyNever: + """Stands in for Player.ready: wait() returns at once, never set.""" + + def __init__(self): + self.calls = 0 + + def wait(self, _timeout): + self.calls += 1 + return False + + +class _ReadyAfter(_ReadyNever): + def __init__(self, n): + super().__init__() + self.n = n + + def wait(self, _timeout): + self.calls += 1 + return self.calls > self.n + + +class TestPlayerReadyLine: + """Player.ready is set by the stdout reader on the player's RUNNING line.""" + + @staticmethod + def _run(lines): + import io + + from cuemsengine.players.Player import Player + + player = Player() + fake = Mock() + fake.pid = 1234 + fake.stdout = io.BytesIO(b"".join(lines)) + fake.poll.side_effect = [None, 0] + with ( + patch("cuemsengine.players.Player.Popen", return_value=fake), + patch("cuemsengine.players.Player.sleep"), + ): + player.call_subprocess(["cuems-audioplayer"]) + return player + + def test_the_running_line_sets_ready(self): + player = self._run( + [ + b"[Cuems:dabc] [OK] AudioPlayer object created OK!\n", + b"[Cuems:dabc] [OK] RUNNING!\n", + ] + ) + assert player.ready.is_set() + + def test_a_second_run_starts_not_ready(self): + from cuemsengine.players.Player import Player + + player = Player() + player.ready.set() # left over from an earlier run + import io + + fake = Mock() + fake.pid = 1 + fake.stdout = io.BytesIO(b"starting\n") + fake.poll.side_effect = [None, 0] + with ( + patch("cuemsengine.players.Player.Popen", return_value=fake), + patch("cuemsengine.players.Player.sleep"), + ): + player.call_subprocess(["cuems-audioplayer"]) + assert not player.ready.is_set() + + def test_other_lines_do_not(self): + player = self._run( + [ + b"[Cuems:dabc] [OK] AudioPlayer object created OK!\n", + b"Starting object with 2 channels\n", + ] + ) + assert not player.ready.is_set() + + +class TestConnectWaitsForReady: + @staticmethod + def _mixer(ports, edges=None): + cm = _fake_conn_man(ports, edges) + return _build_bare_mixer(OUTS2, cm), cm + + def test_ready_already_set_wires_without_waiting(self, caplog): + import threading + + ready = threading.Event() + ready.set() + m, cm = self._mixer({P0, P1, IN1, IN2}) + with _this_thread_sleeps() as sleeps, caplog.at_level(logging.INFO): + result = m.connect_player_to_outputs(PL, "outport", OUTS2, ready=ready) + assert result is True + assert sleeps == [] + assert "reported RUNNING" in caplog.text + cm.connect_by_name.assert_any_call(P0, IN1) + cm.connect_by_name.assert_any_call(P1, IN2) + + def test_ready_after_some_slices_then_wires(self, caplog): + ready = _ReadyAfter(3) + m, cm = self._mixer({P0, P1, IN1, IN2}) + with patch("time.sleep"), caplog.at_level(logging.INFO): + result = m.connect_player_to_outputs(PL, "outport", OUTS2, ready=ready) + assert result is True + assert ready.calls == 4 + assert "reported RUNNING after" in caplog.text + + def test_wiring_happens_after_ready_and_removes_the_auto_connect(self): + """The point of the gate: by RUNNING, RtAudio has auto-connected the + outports to system:playback, and the wiring removes those edges.""" + edges = {P0: ["system:playback_1"], P1: ["system:playback_2"]} + m, cm = self._mixer({P0, P1, IN1, IN2}, edges) + ready = _ReadyAfter(0) + with patch("time.sleep"): + assert m.connect_player_to_outputs(PL, "outport", OUTS2, ready=ready) + cm.disconnect_by_name.assert_any_call(P0, "system:playback_1") + cm.disconnect_by_name.assert_any_call(P1, "system:playback_2") + + def test_a_dead_player_ends_the_ready_wait(self, caplog): + ready = _ReadyNever() + m, cm = self._mixer({IN1, IN2}) + with patch("time.sleep"), caplog.at_level(logging.WARNING): + result = m.connect_player_to_outputs( + PL, "outport", OUTS2, should_abort=lambda: True, ready=ready + ) + assert result is False + assert ready.calls == 1 + cm.connect_by_name.assert_not_called() + assert "exited before reporting RUNNING" in caplog.text + + def test_never_ready_falls_back_to_the_port_and_warns(self, caplog): + ready = _ReadyNever() + m, cm = self._mixer({P0, P1, IN1, IN2}) + with patch("time.sleep"), caplog.at_level(logging.WARNING): + result = m.connect_player_to_outputs( + PL, "outport", OUTS2, should_abort=lambda: False, ready=ready + ) + assert result is True + assert "never reported RUNNING" in caplog.text + cm.connect_by_name.assert_any_call(P0, IN1) + + def test_no_jack_client_returns_at_once_without_waiting(self): + """A JACK-stubbed host (the test2 controller) must not wait for ready: + the 2026-07 load->GO 16 s regression came from such a wait.""" + ready = _ReadyNever() + m, cm = self._mixer({P0, P1, IN1, IN2}) + cm.client = None + with _this_thread_sleeps() as sleeps: + result = m.connect_player_to_outputs(PL, "outport", OUTS2, ready=ready) + assert result is False + assert ready.calls == 0 + assert sleeps == [] + + def test_one_budget_for_both_phases(self): + """Never ready AND no port: the total stays today's ceiling (14.5 s), + not the ready wait plus a full port wait on top.""" + ready = _ReadyNever() + m, cm = self._mixer({IN1, IN2}) + with _this_thread_sleeps() as sleeps: + result = m.connect_player_to_outputs( + PL, "outport", OUTS2, should_abort=lambda: False, ready=ready + ) + assert result is False + ready_s = ready.calls * 0.05 + port_s = sum(sleeps) + assert ready_s + port_s <= 14.5 + 1e-9 + assert ready_s >= 14.5 - 0.05 + + def test_without_ready_nothing_changes(self): + m, cm = self._mixer({P0, P1, IN1, IN2}) + with patch("time.sleep"): + assert m.connect_player_to_outputs(PL, "outport", OUTS2) is True + + +class TestPlayerConnectionDiff: + """Every case asserts both lists exactly.""" + + @staticmethod + def _diff(ports, edges, audio_outputs=OUTS2, selected=None): + cm = _fake_conn_man(ports, edges) + m = _build_bare_mixer(audio_outputs, cm) + return m.player_connection_diff(PL, "outport", selected or audio_outputs) + + def test_clean(self): + assert self._diff({P0, P1, IN1, IN2}, {P0: [IN1], P1: [IN2]}) == ([], []) + + def test_one_stray(self): + edges = {P0: [IN1, "system:playback_1"], P1: [IN2]} + assert self._diff({P0, P1, IN1, IN2}, edges) == ( + [], + [(P0, "system:playback_1")], + ) + + def test_right_edge_missing(self): + assert self._diff({P0, P1, IN1, IN2}, {P0: [IN1]}) == ([(P1, IN2)], []) + + def test_wrong_destination_is_a_stray_plus_the_missing_edge(self): + edges = {P0: [IN1], P1: [IN3]} + assert self._diff({P0, P1, IN1, IN2, IN3}, edges) == ( + [(P1, IN2)], + [(P1, IN3)], + ) + + def test_stereo_player_one_output_selected(self): + # Arm wires only outport 0 to input_1; outport 1 -> input_1 is stray. + edges = {P0: [IN1], P1: [IN1]} + assert self._diff( + {P0, P1, IN1, IN2}, edges, selected=["system:playback_1"] + ) == ([], [(P1, IN1)]) + + def test_four_outputs_with_a_missing_middle_input_shifts_the_pairing(self): + # input_2 does not exist: targets are [input_1, input_3, input_4], + # so L -> 1, R -> 3, L -> 4, exactly as the arm-time wiring pairs them. + edges = {P0: [IN1, IN4], P1: [IN3]} + assert self._diff({P0, P1, IN1, IN3, IN4}, edges, audio_outputs=OUTS4) == ( + [], + [], + ) + + def test_strays_on_both_outports(self): + edges = { + P0: [IN1, "system:playback_1"], + P1: [IN2, "system:playback_2"], + } + assert self._diff({P0, P1, IN1, IN2}, edges) == ( + [], + [(P0, "system:playback_1"), (P1, "system:playback_2")], + ) + + def test_mono_player_ignores_outport_1(self): + edges = {P0: [IN1, IN2]} + assert self._diff({P0, IN1, IN2}, edges) == ([], []) + + def test_mono_at_arm_stereo_at_go_converges(self): + # Wired as mono (outport 0 to both); outport 1 exists by GO. + edges = {P0: [IN1, IN2]} + assert self._diff({P0, P1, IN1, IN2}, edges) == ([(P1, IN2)], [(P0, IN2)]) + + def test_an_edge_is_never_both_missing_and_stray(self): + edges = {P0: ["x:y", IN2], P1: [IN1]} + missing, stray = self._diff({P0, P1, IN1, IN2}, edges) + assert not set(missing) & set(stray) + + def test_no_mixer_input_is_none_not_clean(self): + assert self._diff({P0, P1}, {P0: [], P1: []}) is None + + def test_player_port_gone_is_none(self): + assert self._diff({IN1, IN2}, {}) is None + + +class TestRepairPlayerConnections: + @staticmethod + def _mixer(edges, connect_result=True, disconnect_result=True): + cm = _fake_conn_man({P0, P1, IN1, IN2}, edges, connect_result) + cm.disconnect_by_name.return_value = disconnect_result + return _build_bare_mixer(OUTS2, cm), cm + + def test_strays_only(self): + m, cm = self._mixer({P0: [IN1, "system:playback_1"], P1: [IN2]}) + assert m.repair_player_connections([], [(P0, "system:playback_1")]) == ( + True, + [], + ) + cm.disconnect_by_name.assert_called_once_with(P0, "system:playback_1") + cm.connect_by_name.assert_not_called() + + def test_a_stray_already_gone_is_not_disconnected(self): + m, cm = self._mixer({P0: [IN1], P1: [IN2]}) + assert m.repair_player_connections([], [(P0, "system:playback_1")]) == ( + True, + [], + ) + cm.disconnect_by_name.assert_not_called() + + def test_missing_only(self): + m, cm = self._mixer({P0: [IN1]}) + assert m.repair_player_connections([(P1, IN2)], []) == (True, []) + cm.connect_by_name.assert_called_once_with(P1, IN2) + cm.disconnect_by_name.assert_not_called() + + def test_both(self): + m, cm = self._mixer({P0: [IN1, "system:playback_1"]}) + m.repair_player_connections([(P1, IN2)], [(P0, "system:playback_1")]) + cm.disconnect_by_name.assert_called_once_with(P0, "system:playback_1") + cm.connect_by_name.assert_called_once_with(P1, IN2) + + def test_a_failed_connect_is_reported(self): + m, cm = self._mixer({P0: [IN1]}, connect_result=False) + assert m.repair_player_connections([(P1, IN2)], []) == (False, []) + + def test_a_failed_stray_disconnect_is_reported(self): + m, cm = self._mixer( + {P0: [IN1, "system:playback_1"], P1: [IN2]}, disconnect_result=False + ) + assert m.repair_player_connections([], [(P0, "system:playback_1")]) == ( + True, + [(P0, "system:playback_1")], + ) + + def test_never_disconnects_an_expected_edge(self): + m, cm = self._mixer({P0: [IN1, "system:playback_1"], P1: []}) + m.repair_player_connections([(P1, IN2)], [(P0, "system:playback_1")]) + for c in cm.disconnect_by_name.call_args_list: + assert c.args[1] not in (IN1, IN2), c + + +class TestVerifyAudioWiringAtGo: + """run_audioCue's GO-time check (869fbyjzx): edge by edge, never a full + rewire — a GO can reach it while the cue is audible.""" + + @staticmethod + def _run(diff, repair=(True, [])): + from types import SimpleNamespace + + from cuemsengine.cues.run_cue import _verify_audio_wiring_at_go + + mixer = Mock() + mixer.player_connection_diff.return_value = diff + mixer.repair_player_connections.return_value = repair + _verify_audio_wiring_at_go(SimpleNamespace(id="cue-1"), mixer, PL, OUTS2) + mixer.connect_player_to_outputs.assert_not_called() + return mixer + + def test_clean_graph_is_left_alone(self): + mixer = self._run(([], [])) + mixer.repair_player_connections.assert_not_called() + + def test_a_stray_is_repaired_edge_by_edge(self, caplog): + with caplog.at_level(logging.WARNING): + mixer = self._run(([], [(P0, "system:playback_1")])) + mixer.repair_player_connections.assert_called_once_with( + [], [(P0, "system:playback_1")] + ) + # The go_repair= harness counter reads this literal prefix. + assert "graph not wired correctly at GO" in caplog.text + + def test_a_missing_edge_is_repaired_edge_by_edge(self): + mixer = self._run(([(P1, IN2)], [])) + mixer.repair_player_connections.assert_called_once_with([(P1, IN2)], []) + + def test_no_mixer_input_is_a_silent_cue_error(self, caplog): + with caplog.at_level(logging.ERROR): + mixer = self._run(None) + mixer.repair_player_connections.assert_not_called() + assert "will be SILENT" in caplog.text + + def test_a_failed_connect_is_a_silent_cue_error(self, caplog): + with caplog.at_level(logging.ERROR): + self._run(([(P1, IN2)], []), repair=(False, [])) + assert "will be SILENT" in caplog.text + + def test_a_surviving_stray_is_an_error(self, caplog): + with caplog.at_level(logging.ERROR): + self._run( + ([], [(P0, "system:playback_1")]), + repair=(True, [(P0, "system:playback_1")]), + ) + assert "stray edge(s) still connected" in caplog.text + + +class TestSharedBudget: + """The ready wait and the port wait never exceed today's ceiling, + whatever share the ready wait used (869fbyjzx review).""" + + @pytest.mark.parametrize("n", [0, 1, 7, 10, 11, 100, 289]) + @pytest.mark.parametrize( + "max_retries,retry_delay", [(30, 0.5), (10, 0.3), (6, 0.2)] + ) + def test_total_wait_stays_within_the_ceiling(self, n, max_retries, retry_delay): + ready = _ReadyAfter(n) + m, cm = TestConnectWaitsForReady._mixer({IN1, IN2}) # port never appears + with _this_thread_sleeps() as sleeps: + m.connect_player_to_outputs( + PL, + "outport", + OUTS2, + should_abort=lambda: False, + ready=ready, + max_retries=max_retries, + retry_delay=retry_delay, + ) + ceiling = (max_retries - 1) * retry_delay + # Slices actually waited: the call that returns \"ready\" waits for nothing. + waited_slices = min(n, max(1, int(round(ceiling / 0.05)))) + used = waited_slices * 0.05 + sum(sleeps) + assert used <= ceiling + 1e-9, (n, used, ceiling) + + +class TestRepairRecheck: + def test_a_stray_removed_by_someone_else_is_not_a_survivor(self): + # disconnect_by_name fails (the edge was already gone), and the edge + # is not connected any more: it is not reported as left. + cm = _fake_conn_man({P0, P1, IN1, IN2}, {P0: ["system:playback_2"]}) + calls = {"n": 0} + + def is_connected(src, dst): + calls["n"] += 1 + return calls["n"] == 1 # connected at the first check, gone after + + cm.is_connected.side_effect = is_connected + cm.disconnect_by_name.return_value = False + m = _build_bare_mixer(OUTS2, cm) + assert m.repair_player_connections([], [(P0, "system:playback_2")]) == ( + True, + [], + ) + + +def test_sleep_patch_ignores_other_threads(): + # The guard against the 869fbyjzx CI flake: a thread left running by + # another test sleeps while the patch is active; its calls must not be + # counted against the test's own wait budget. + import time + + go, done = threading.Event(), threading.Event() + + def foreign(): + go.wait(5) + for _ in range(50): + time.sleep(100) + done.set() + + t = threading.Thread(target=foreign, daemon=True) + t.start() + with _this_thread_sleeps() as sleeps: + go.set() + done.wait(5) + time.sleep(0.25) + assert done.is_set() + assert sleeps == [0.25]