From 9ac6b39b2dd279e2f6a031033f257f2a1bb95646 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 1 Oct 2026 10:50:39 +0200 Subject: [PATCH 01/25] fix(video): only enable videocomposer wraparound for cues that repeat (869fa89uh) loop_videoCue sent /loop 1 for every video cue, play-once ones included. The videocomposer runs its display latency (33 ms) ahead of MTC, so with wraparound on it reached end of file before the engine hid the layer and showed the first frame again for a frame or two at the end of the cue. Send /loop 1 only when cue.loop != 1, and on the last pass of a counted loop send /loop 0 after the new offset, so the end holds the last frame. --- src/cuemsengine/cues/loop_cue.py | 34 +++++++++--- tests/test_loop_video_wraparound.py | 83 +++++++++++++++++++++++++++++ 2 files changed, 109 insertions(+), 8 deletions(-) create mode 100644 tests/test_loop_video_wraparound.py diff --git a/src/cuemsengine/cues/loop_cue.py b/src/cuemsengine/cues/loop_cue.py index bb96021d..99954ad4 100644 --- a/src/cuemsengine/cues/loop_cue.py +++ b/src/cuemsengine/cues/loop_cue.py @@ -287,14 +287,18 @@ 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: @@ -353,6 +357,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/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 From 6dad8cc41761731bfe9021f6bd37c14b627f1814 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 11:06:31 +0200 Subject: [PATCH 02/25] test(follow): the controller's run counter and follow relay (869fc8ytz) (red) Every GO carries run_seq; STOP, load and unload bump it before they forward anything; a node's follow message is relayed to every node only while the show runs and only with the current run_seq. The four tests that pinned the GO value now expect it to be a dict in every case. --- tests/test_controller_commands.py | 28 ++- tests/test_cross_node_follow_controller.py | 228 +++++++++++++++++++++ 2 files changed, 248 insertions(+), 8 deletions(-) create mode 100644 tests/test_cross_node_follow_controller.py 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_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() From 16a6d6a347200ab9f29b526a854e093169ddcb9b Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 11:06:31 +0200 Subject: [PATCH 03/25] feat(follow): the controller relays cross-node Auto follow messages (869fc8ytz) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The controller keeps a run counter, started from the clock. STOP, load and unload bump it before forwarding; every GO ships it to the nodes. A node's 'follow' status message (announce or cancel) is forwarded to every node only while running and only with the current value; the check and the forward share one lock with the bump, so a relayed follow is always queued ahead of the STOP that ends its run. The controller keeps no follow state. The GO value is now always a dict. Nodes read nothing from it but the anchor (_resolve_go_anchor), so the caller's own value is no longer passed on. Plan: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md §3.3-3.4. --- src/cuemsengine/ControllerEngine.py | 68 ++++++++++++++++++++++++++++- 1 file changed, 66 insertions(+), 2 deletions(-) diff --git a/src/cuemsengine/ControllerEngine.py b/src/cuemsengine/ControllerEngine.py index 5e8dd149..a20fad28 100644 --- a/src/cuemsengine/ControllerEngine.py +++ b/src/cuemsengine/ControllerEngine.py @@ -101,6 +101,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 +626,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 ######################### @@ -970,6 +1028,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() @@ -1085,10 +1144,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 +1438,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,6 +1465,7 @@ 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 = {} From fd5261574e52151029b7197a2d40eb42f02b8aaa Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 11:06:32 +0200 Subject: [PATCH 04/25] test(follow): node side of the cross-node Auto follow (869fc8ytz) (red) The receive hook (bus order, never the command lock), the receiving node's follow table (announce, pre-arm, wait for the instant, dispatch through a commit gate in go(), cancel by entry state, the 2 s rule), and the owning node's announce/cancel (at the reveal or the last loop; one cancel per announcement; the restart cancel from go()). Includes the tests for the seven findings of the code review of the implementation. --- tests/test_cross_node_follow_hook.py | 164 ++++++ tests/test_cross_node_follow_owner.py | 638 ++++++++++++++++++++++ tests/test_cross_node_follow_receiver.py | 668 +++++++++++++++++++++++ 3 files changed, 1470 insertions(+) create mode 100644 tests/test_cross_node_follow_hook.py create mode 100644 tests/test_cross_node_follow_owner.py create mode 100644 tests/test_cross_node_follow_receiver.py 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 From 8236720b1d8466970193fac26ecd08d94c7d73d4 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 11:06:32 +0200 Subject: [PATCH 05/25] fix(follow): an Auto follow into a cue on another node starts it (869fc8ytz) An Auto follow (post_go='go_at_end') fired its target only on the nodes where the source is local, so a target on another node never started, silently, on every engine line. The node that owns an AudioCue or VideoCue source now announces the follow instant when the cue reveals (or at the start of its last loop; never for an endless loop), through the controller. Every other node pre-arms what it would start, waits for the instant on MTC and dispatches it there through go_from. ActionCue, FadeCue, CueList and DmxCue sources are local on every node and keep firing their own follow. If the follow does not happen the owner cancels: 'stop' (stop, pause or fade-out action), 'restart' (sent from go()'s commit section when the source is started again), 'error'. A STOP, a load or the yield send nothing; every node handles those itself. A cancel that reaches a target already on stage stops it only within 2 s and only for stop/restart. - cues/FollowRelay.py: both halves of the node side; one entry per source, its own lock, never calls into CueHandler while holding it. - NodeCommunications: a receive hook in bus order, before any command thread; send_operation_nowait. - NodeEngine: run_seq recorded and pending follows dropped at receipt; follow messages applied there, never under the command lock; STOP and load marked applied after they run. - CueHandler: go() gets a commit_gate (refusals, gate, restart cancel, assignments); go_from passes arm_epoch/require_stop_epoch/commit_gate through; stop_dispatched_follow and disarm_if_unchanged (guarded disarm under the cue's arm claim); the reveal stamp; go_threaded wraps the pass so every exit decides its cancel once. - loop_cue: on_last_loop callback for audio and video. Verified on test2 (suite 1109 passed; 40 live runs, 0 LATE, 0 fallback; old-node smoke test; PR #22 drills and a Medina sala1 replay unchanged). Plan: cuems-RELATIONS Plans/2026-10-05-engine-cross-node-auto-follow.md. --- src/cuemsengine/NodeEngine.py | 69 ++- src/cuemsengine/comms/NodeCommunications.py | 35 ++ src/cuemsengine/cues/CueHandler.py | 403 +++++++++++++- src/cuemsengine/cues/FollowRelay.py | 563 ++++++++++++++++++++ src/cuemsengine/cues/loop_cue.py | 20 +- 5 files changed, 1075 insertions(+), 15 deletions(-) create mode 100644 src/cuemsengine/cues/FollowRelay.py diff --git a/src/cuemsengine/NodeEngine.py b/src/cuemsengine/NodeEngine.py index 61d2997d..0bd4a32f 100644 --- a/src/cuemsengine/NodeEngine.py +++ b/src/cuemsengine/NodeEngine.py @@ -15,6 +15,7 @@ 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 @@ -97,6 +98,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 +176,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 +202,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 +492,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") diff --git a/src/cuemsengine/comms/NodeCommunications.py b/src/cuemsengine/comms/NodeCommunications.py index cbc421b6..d3505dd4 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 @@ -145,6 +168,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..d37ffabd 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 @@ -1165,6 +1187,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 +1210,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 @@ -1298,6 +1326,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 +1351,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 +1397,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 +1417,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 +1461,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 +1578,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 @@ -1656,6 +1759,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 +1775,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 +1823,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 +1859,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 +1925,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 +1947,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..d97b62fe 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}" @@ -300,6 +315,7 @@ def loop_videoCue(cue: VideoCue, mtc: MtcListener): 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: From 2c358f40e6594a278c194943f7ef0e561e4437bc Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 11:06:32 +0200 Subject: [PATCH 06/25] docs(follow): the cross-node Auto follow relay in CLAUDE.md (869fc8ytz) --- CLAUDE.md | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/CLAUDE.md b/CLAUDE.md index 4dc7fc92..847b9985 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. From a90adf9c8b8203e784d845c508ed41c13414686c Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 19:48:08 +0200 Subject: [PATCH 07/25] test(audio): wire a player only once it reports RUNNING; check and repair its wiring at GO edge by edge; honest arm-wait log lines (869fbyjzx) (red) - the player's [OK] RUNNING! stdout line sets Player.ready; the mixer wiring waits for it (one budget with the port wait, after the no-JACK fail-fast; a dead player ends the wait; a player that never reports it is wired on port presence with a WARNING); - player_connection_diff reports missing and stray edges (None when no mixer input resolves); repair_player_connections fixes them one by one and never disconnects an expected edge; the GO-time check uses them; - the routing-equivalence tests of player_connections_correct now drive get_connections (one read per outport), every case kept; - go() and the dispatch site say whether a cue was still being armed (waited for) or not armed at all (a real fallback). --- tests/test_arm_wait_messages.py | 188 +++++++++++++++ tests/test_players_audiomixer.py | 382 ++++++++++++++++++++++++++++++- 2 files changed, 560 insertions(+), 10 deletions(-) create mode 100644 tests/test_arm_wait_messages.py diff --git a/tests/test_arm_wait_messages.py b/tests/test_arm_wait_messages.py new file mode 100644 index 00000000..1d224053 --- /dev/null +++ b/tests/test_arm_wait_messages.py @@ -0,0 +1,188 @@ +# 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 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) + + +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): + from test_dispatch_reorder import _FakeMtc, _cue as reorder_cue + + mtc = _FakeMtc(0) + c = reorder_cue(id=cue.id) + c.loaded = False + 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_players_audiomixer.py b/tests/test_players_audiomixer.py index 0c97fa20..16b4f68c 100644 --- a/tests/test_players_audiomixer.py +++ b/tests/test_players_audiomixer.py @@ -384,7 +384,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 +407,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,12 +530,11 @@ 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: - assert ( - c.args[0] != "Audio_Player-X:outport 1" - ), f"mono check leaked an outport 1 probe: {c}" + # 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}" + ) def test_mono_with_4_outputs(self): # 4 fan-out targets, mono player: outport 0 → all 4 inputs. @@ -587,10 +591,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 +623,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: @@ -933,3 +939,359 @@ 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_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 patch("time.sleep") as mock_sleep, caplog.at_level(logging.INFO): + result = m.connect_player_to_outputs(PL, "outport", OUTS2, ready=ready) + assert result is True + mock_sleep.assert_not_called() + 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 patch("time.sleep") as mock_sleep: + result = m.connect_player_to_outputs(PL, "outport", OUTS2, ready=ready) + assert result is False + assert ready.calls == 0 + mock_sleep.assert_not_called() + + 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 patch("time.sleep") as mock_sleep: + 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(c.args[0] for c in mock_sleep.call_args_list) + 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 From 58315afaed68a279d790fe55e2da0435ed15c7c1 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 19:48:18 +0200 Subject: [PATCH 08/25] fix(audio): wire an audio player only once it reports RUNNING (869fbyjzx) The engine wired a player to the mixer as soon as its JACK port was visible, polling every 0.5 s. The port exists before the player has finished starting: RtAudio auto-connects its outports to system:playback only when the stream starts, and the constructor goes on after that. - Wiring before the auto-connect found nothing to disconnect; the auto-connect then landed and stayed, and the cue sounded through the mixer AND straight to the outputs (869fcvz85, ~3.5 % of arms). - A GO waiting on the arm could message a half-built player. - The 0.5 s poll made a pre-arm that started at a hand-off miss a GO 0.5 s later by ~360 ms (869fbyjzx). The player prints [OK] RUNNING! once it is fully started (main.cpp), and the stdout reader now sets Player.ready on it. connect_player_to_outputs waits for that event when given one (after the no-JACK fail-fast, in counted 50 ms slices, sharing today's 14.5 s budget with the port wait), then wires; the existing disconnect step now always finds and removes the auto-connects. A dead player ends the wait; a player that never reports ready is wired on port presence with a WARNING. new_audio_output passes the player's event; the test fixtures' mocked players set it. --- src/cuemsengine/players/AudioMixer.py | 69 +++++++++++++++++++++--- src/cuemsengine/players/Player.py | 17 +++++- src/cuemsengine/players/PlayerHandler.py | 4 ++ tests/fixtures.py | 5 ++ 4 files changed, 88 insertions(+), 7 deletions(-) diff --git a/src/cuemsengine/players/AudioMixer.py b/src/cuemsengine/players/AudioMixer.py index fa1ee30c..c428e9d2 100644 --- a/src/cuemsengine/players/AudioMixer.py +++ b/src/cuemsengine/players/AudioMixer.py @@ -242,6 +242,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 +267,17 @@ 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. Returns: True if every required player→mixer connection was made, False if @@ -311,6 +323,51 @@ 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: + spent_attempts = int(slices_used * ready_slice / retry_delay) + 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 +385,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 +401,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 diff --git a/src/cuemsengine/players/Player.py b/src/cuemsengine/players/Player.py index f20604b4..86953f34 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,11 @@ 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). + self.ready = Event() def run(self): raise NotImplementedError @@ -57,6 +70,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..bea44972 100644 --- a/src/cuemsengine/players/PlayerHandler.py +++ b/src/cuemsengine/players/PlayerHandler.py @@ -555,6 +555,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=getattr(player, "ready", None), ) 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 ( From a4eeebce8ffdbeead42f673ed39f74ec3f18930d Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 19:48:39 +0200 Subject: [PATCH 09/25] fix(audio): check and repair a player's wiring at GO edge by edge (869fbyjzx, 869fcvz85) The GO-time check (player_connections_correct) confirmed only that the expected player->mixer edges exist, so a stray direct edge to system:playback passed, and the cue sounded doubled and outside the mixer's volume and mute (869fcvz85). Its repair was a full rewire (connect_player_to_outputs disconnects every edge first). A GO can reach it while the cue is audible: go() refuses a duplicate only inside one chain pass, the 'play' action has no playing check, and run_audioCue has no early exit. So the rewire also cut the healthy channels. - _expected_edges: the one copy of the routing (L/R pairs, mono fan-out, missing mixer inputs dropped), used by the arm-time wiring and the check, so they cannot drift. - player_connection_diff -> (missing, stray), one get_connections per outport; None when the player's port is gone or no mixer input resolves (a silent cue, never "correct"). - player_connections_correct stays, as a wrapper on the diff. - repair_player_connections: disconnects each stray (re-checked first, since a failed disconnect resets the shared JACK client), connects each missing edge, never touches an expected edge; it reports a failed connect and the strays that survive. - run_audioCue calls _verify_audio_wiring_at_go, which uses the diff and the repair and logs a SILENT error for no mixer input or a failed connect, and an error for a surviving stray. The WARNING keeps its prefix "graph not wired correctly at GO". --- src/cuemsengine/cues/run_cue.py | 69 ++++++---- src/cuemsengine/players/AudioMixer.py | 188 +++++++++++++++++--------- 2 files changed, 167 insertions(+), 90 deletions(-) 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 c428e9d2..eef60ada 100644 --- a/src/cuemsengine/players/AudioMixer.py +++ b/src/cuemsengine/players/AudioMixer.py @@ -298,12 +298,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 @@ -445,41 +439,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: @@ -489,59 +468,136 @@ 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): + 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( From 58869e6439f91214af3ed2c7b41b6c74a712c15c Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 19:48:49 +0200 Subject: [PATCH 10/25] fix(arm): say whether a GO waited for an arm in progress or fell back (869fbyjzx) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A GO that found its cue still being armed (a pre-arm, an audio player still starting) logged "this should not happen, pre-arm may have failed. Re-arming as fallback." It had not failed: the arm was in flight and the GO waited for it. - go() and the dispatch site now ask describe_arm_in_flight first: - an arm in flight: INFO "still being armed (...) — waiting for the arm in progress"; - nothing in flight: the WARNING, which keeps "not loaded at go() time" / "not loaded at dispatch" and "Re-arming as fallback", so the harnesses keep counting real fallbacks only; - a continuation at go() (which never arms there): INFO "dispatching; its own thread arms it or waits". - arm() takes an optional wait_report and fills it when it actually waits for another thread's arm, so "waited Y s" reports what happened, not the guess made before the call. - The control flow is unchanged: same arm() calls, same epoch checks. - Test stand-ins of arm() accept the new optional argument. --- src/cuemsengine/cues/CueHandler.py | 84 ++++++++++++++++++++++++++---- tests/test_arm_publish_gate.py | 4 +- tests/test_chain_epoch.py | 2 +- tests/test_dispatch_reorder.py | 8 +-- 4 files changed, 81 insertions(+), 17 deletions(-) diff --git a/src/cuemsengine/cues/CueHandler.py b/src/cuemsengine/cues/CueHandler.py index e6d4db5b..7d557425 100644 --- a/src/cuemsengine/cues/CueHandler.py +++ b/src/cuemsengine/cues/CueHandler.py @@ -494,9 +494,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 +544,7 @@ def arm( return False wait_deadline = None + waited_total = 0.0 while True: needs_disarm = False claim = None @@ -586,7 +594,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 +764,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.""" @@ -1222,18 +1252,39 @@ 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. + 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) @@ -1579,11 +1630,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 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_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_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 From bd8381b702fe820b5e42fc318c5868c08ec4a579 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 19:49:06 +0200 Subject: [PATCH 11/25] docs: audio wiring waits for the player's RUNNING line and repairs edge by edge at GO (869fbyjzx) --- CLAUDE.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CLAUDE.md b/CLAUDE.md index 4dc7fc92..7c06684d 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -100,7 +100,7 @@ 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"). - **`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`). From d7499257f54cdad649603bd54cb1a9b150ed2236 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Tue, 6 Oct 2026 20:09:33 +0200 Subject: [PATCH 12/25] test(arm): make the arm-wait message tests self-contained (869fbyjzx) They imported helpers from test_dispatch_reorder, which only resolves when tests/ is on sys.path; the test2 suite run does not put it there. --- tests/test_arm_wait_messages.py | 44 ++++++++++++++++++++++++++++++--- 1 file changed, 40 insertions(+), 4 deletions(-) diff --git a/tests/test_arm_wait_messages.py b/tests/test_arm_wait_messages.py index 1d224053..0e7b843a 100644 --- a/tests/test_arm_wait_messages.py +++ b/tests/test_arm_wait_messages.py @@ -21,6 +21,8 @@ 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" @@ -138,6 +140,43 @@ def test_the_same_arm_call_as_before(self): 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) @@ -158,11 +197,8 @@ def _dispatch_handler(in_flight, arm): class TestDispatchSite: @staticmethod def _dispatch(ch, cue): - from test_dispatch_reorder import _FakeMtc, _cue as reorder_cue - mtc = _FakeMtc(0) - c = reorder_cue(id=cue.id) - c.loaded = False + c = _chain_cue(cue.id) with ( patch("cuemsengine.cues.CueHandler.run_cue"), patch("cuemsengine.cues.CueHandler.reveal_cue"), From ee3b060b144c15d90e5ecfa81ad9fa5ead509a5c Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Wed, 7 Oct 2026 11:22:43 +0200 Subject: [PATCH 13/25] docs(audio): state the known limit and plan B of the ready gate (869fbyjzx) An audio arm is ~0.47 s cold, so a GO that reaches the cue sooner after its arm began still fires late (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: no real show hits it today). Recorded in the code and CLAUDE.md. --- CLAUDE.md | 2 +- src/cuemsengine/cues/CueHandler.py | 4 ++++ src/cuemsengine/players/AudioMixer.py | 16 ++++++++++++++++ src/cuemsengine/players/Player.py | 4 ++++ 4 files changed, 25 insertions(+), 1 deletion(-) diff --git a/CLAUDE.md b/CLAUDE.md index 7c06684d..4e3b3e5e 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -100,7 +100,7 @@ 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 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"). +- **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). - **`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/src/cuemsengine/cues/CueHandler.py b/src/cuemsengine/cues/CueHandler.py index 7d557425..76b98b37 100644 --- a/src/cuemsengine/cues/CueHandler.py +++ b/src/cuemsengine/cues/CueHandler.py @@ -1259,6 +1259,10 @@ def go( # 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( diff --git a/src/cuemsengine/players/AudioMixer.py b/src/cuemsengine/players/AudioMixer.py index eef60ada..345593de 100644 --- a/src/cuemsengine/players/AudioMixer.py +++ b/src/cuemsengine/players/AudioMixer.py @@ -279,6 +279,22 @@ def connect_player_to_outputs( 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 the player ports never registered, no mixer inputs resolved, or any diff --git a/src/cuemsengine/players/Player.py b/src/cuemsengine/players/Player.py index 86953f34..06055c4d 100644 --- a/src/cuemsengine/players/Player.py +++ b/src/cuemsengine/players/Player.py @@ -48,6 +48,10 @@ def __init__(self, daemon: bool = True): # 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): From 9d23f8868db4a8d64a5d31918ce60b6651df1c37 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Wed, 7 Oct 2026 12:40:52 +0200 Subject: [PATCH 14/25] fix(audio): review fixes for the ready gate (869fbyjzx) From a fresh-eyes review of the branch: - new_audio_output: a player without a ready event now logs a WARNING (the wiring would fall back to port presence and the doubled-audio race would come back unnoticed); tests that the player's Event reaches the wiring. - The ready wait and the port wait share the ceiling exactly: the slices the ready wait used are rounded UP into port attempts (they were floored, so the total could exceed the ceiling by up to one retry step); parametrized test. - Player.call_subprocess clears ready first, so a second run of the same Player cannot pass the gate on a stale Event. - repair_player_connections: a stray whose disconnect failed but is no longer connected (removed by a concurrent re-arm wiring) is not reported as left. --- src/cuemsengine/players/AudioMixer.py | 13 +++- src/cuemsengine/players/Player.py | 3 + src/cuemsengine/players/PlayerHandler.py | 11 ++- tests/test_player_handler_port_wait_abort.py | 28 ++++++++ tests/test_players_audiomixer.py | 71 ++++++++++++++++++-- 5 files changed, 118 insertions(+), 8 deletions(-) diff --git a/src/cuemsengine/players/AudioMixer.py b/src/cuemsengine/players/AudioMixer.py index 345593de..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 @@ -373,7 +374,11 @@ def connect_player_to_outputs( "presence (old or unusual player build)" ) if retry_delay > 0: - spent_attempts = int(slices_used * ready_slice / retry_delay) + # 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 @@ -608,7 +613,11 @@ def repair_player_connections(self, missing: list, stray: list): if not self.conn_man.is_connected(src, dst): continue if not self.conn_man.disconnect_by_name(src, dst): - strays_left.append((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) diff --git a/src/cuemsengine/players/Player.py b/src/cuemsengine/players/Player.py index 06055c4d..e45148e9 100644 --- a/src/cuemsengine/players/Player.py +++ b/src/cuemsengine/players/Player.py @@ -65,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) diff --git a/src/cuemsengine/players/PlayerHandler.py b/src/cuemsengine/players/PlayerHandler.py index bea44972..71606b46 100644 --- a/src/cuemsengine/players/PlayerHandler.py +++ b/src/cuemsengine/players/PlayerHandler.py @@ -546,6 +546,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", @@ -558,7 +567,7 @@ def new_audio_output(self, cue: AudioCue) -> None: # 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=getattr(player, "ready", None), + ready=ready, ) if connected is False: # Route to the mixer failed: the cue would show armed/green 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 16b4f68c..ad4b623f 100644 --- a/tests/test_players_audiomixer.py +++ b/tests/test_players_audiomixer.py @@ -60,7 +60,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 +78,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, @@ -756,7 +754,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() @@ -804,7 +801,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 @@ -844,7 +840,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 @@ -1005,6 +1000,24 @@ def test_the_running_line_sets_ready(self): ) 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( [ @@ -1295,3 +1308,51 @@ def test_a_surviving_stray_is_an_error(self, caplog): 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 patch("time.sleep") as mock_sleep: + 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(c.args[0] for c in mock_sleep.call_args_list) + 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, + [], + ) From 0118d1ed0c151db01815407df3abed2f781f215d Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Wed, 7 Oct 2026 16:47:15 +0200 Subject: [PATCH 15/25] style: black (the CI lint is black --check, not ruff format) (869fbyjzx) --- tests/test_players_audiomixer.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/test_players_audiomixer.py b/tests/test_players_audiomixer.py index ad4b623f..d66f4148 100644 --- a/tests/test_players_audiomixer.py +++ b/tests/test_players_audiomixer.py @@ -530,9 +530,9 @@ def test_mono_does_not_check_outport_1(self): ) # 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}" - ) + assert ( + c.args[0] != "Audio_Player-X:outport 1" + ), f"mono check leaked an outport 1 probe: {c}" def test_mono_with_4_outputs(self): # 4 fan-out targets, mono player: outport 0 → all 4 inputs. From df3e7968e831e0151f9aa6e8fadcda1e523d856a Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:03:55 +0200 Subject: [PATCH 16/25] =?UTF-8?q?test(status):=20cue=20names=20on=20the=20?= =?UTF-8?q?:9190=20channel=20=E2=80=94=20red=20(869fedahu)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit One /engine/status/cue_name/ per cue after the load status, replayed to late joiners, emptied on unload; a second load without unload replaces the map (duplicated projects share cue uuids). Pure unit tests, safe on a live rig. --- tests/test_controller_cue_names.py | 323 +++++++++++++++++++++++++++++ 1 file changed, 323 insertions(+) create mode 100644 tests/test_controller_cue_names.py 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 == {} From 5ffb1b809d0743621aeef5bd9fddb86b3c70a237 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:03:55 +0200 Subject: [PATCH 17/25] fix(status): broadcast cue names after load on the :9190 channel (869fedahu) The UI named the engine's next cue from whatever project its own page had loaded, so a tab viewing X while the engine held Y showed a raw uuid. The controller already pushes cue status and enabled flags per cue; the name is the missing member of that family. - cue_names built at load from the script (same walk as _collect_cue_ids; item.get("name"), None -> "") - one /engine/status/cue_name/ per cue, sent AFTER set_status("load"): duplicated projects share cue uuids, so clients treat a change of load as "new table" and refill it from this burst - replayed in _on_ws_client_connect after cue_enabled, before mixer - emptied on unload; nothing is sent then (clients clear on load "") - "Cue names initialised for N cues" next to the cue status line Node engine untouched. Verified on test2 (rc6-2+nodeadopt1 base): wire capture order, late join, X->Y without unload, unload; full suite 1057 passed. --- src/cuemsengine/ControllerEngine.py | 58 +++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/src/cuemsengine/ControllerEngine.py b/src/cuemsengine/ControllerEngine.py index 5e8dd149..862058f9 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 @@ -806,6 +812,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 +848,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 +945,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 @@ -1032,6 +1080,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. @@ -1406,6 +1463,7 @@ def unload_project(self, value, context=None): 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 From ce412084714589186974072da4b7b1d4078d32d0 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:09:13 +0200 Subject: [PATCH 18/25] test(orphan-kill): sweeps never abort a load and match only own players (869evtdf7) (red) An orphan the node cannot kill (EPERM, owned by another user) made kill_orphaned_audio_processes raise in the middle of _load_project_inner: the old project was torn down, the new one never armed, and the only trace was "Error executing command callback for load: [Errno 1] Operation not permitted". The mixer sweep has the same flaw at mixer start. Red tests for plan Plans/2026-10-07-engine-orphan-kill-eperm-aborts-load.md (cuems-RELATIONS), rev 4: - both sweeps: EPERM / any other kill error logged and the sweep goes on; ESRCH silent; pgrep rc 1 silent, rc >= 2 and "cannot run" logged; a bad pgrep line skipped; the owner named in the EPERM warning (G1, G2); - pgrep asked for own-user processes only, audioplayer argv[0] anchored, with the pattern table (G4); - a configured binary name the cleanup does not know is warned at start (G4b); - the load reaches ready_project/ready_script with the sweep running for real and os.kill raising EPERM; - the command callback failure is logged with its traceback (G6); - cleanup_zombie_jack_clients survives a JACK error (G7). test_player_handler_mixer_orphan.py: pgrep argv now carries -u . --- tests/test_node_comms_ping.py | 20 ++ tests/test_node_engine_load_orphan_eperm.py | 107 +++++++ tests/test_player_handler_mixer_orphan.py | 6 +- tests/test_player_handler_orphan_kill.py | 324 ++++++++++++++++++++ 4 files changed, 456 insertions(+), 1 deletion(-) create mode 100644 tests/test_node_engine_load_orphan_eperm.py create mode 100644 tests/test_player_handler_orphan_kill.py 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)) From 674aefbcf0052896f6556bffc581f04d8092fc5e Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:09:56 +0200 Subject: [PATCH 19/25] fix(orphan-kill): an orphan sweep never aborts its caller (869evtdf7) Both sweeps now share module-level helpers that never raise: _orphan_pids runs pgrep (rc 1 = nothing to do, silent; rc >= 2 or pgrep that cannot run = WARNING with rc and stderr; a bad line is skipped with a WARNING), _kill_orphan kills one PID (ESRCH silent; EPERM = WARNING naming the PID, its owner and the silent-cue risk; anything else = WARNING), and _pid_owner reads the owner from /proc//status. Before, an EPERM on an orphan owned by another user escaped kill_orphaned_audio_processes in the middle of _load_project_inner (old project torn down, new one never armed), and escaped kill_orphaned_mixer_processes at mixer start (node without a mixer, all audio silent). Module-level, not methods: the existing tests call the sweeps unbound on a SimpleNamespace stand-in. --- src/cuemsengine/players/PlayerHandler.py | 142 +++++++++++++++++------ 1 file changed, 106 insertions(+), 36 deletions(-) diff --git a/src/cuemsengine/players/PlayerHandler.py b/src/cuemsengine/players/PlayerHandler.py index 71606b46..ffa79a1d 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,97 @@ 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. + +AUDIOPLAYER_ORPHAN_PATTERN = "cuems-audioplayer" +MIXER_ORPHAN_PATTERN = "jack-volume -c" + + +def _orphan_pids(pattern: str, label: str) -> list[int]: + """PIDs whose command line matches `pattern` (pgrep -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", "-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. @@ -383,16 +476,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 +489,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 +508,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 From 32dae0d83106b99bd71252f00b4975046809a985 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:10:22 +0200 Subject: [PATCH 20/25] fix(orphan-kill): sweep only own-user processes of the known binaries (869evtdf7) Both sweeps ask pgrep for the engine's own user only (-u , the scope of the node-engine unit's own pkill -u cuems): another user's process cannot hold a client name on our per-user JACK server, and trying to kill it is what produced the EPERM. The audioplayer pattern is anchored on argv[0] (^([^ ]*/)?cuems-audioplayer( |$)), so a tail -f of a cuems-audioplayer log, a grep or a sh -c containing the word are no longer SIGKILLed. The mixer pattern (jack-volume -c) is unchanged. The cleanups now rely on the binary's name, so set_players warns at start when a configured audioplayer/audiomixer/dmxplayer path has a basename they do not know (check_orphan_binary_names): such orphans would escape every cleanup. --- src/cuemsengine/NodeEngine.py | 9 ++++- src/cuemsengine/players/PlayerHandler.py | 48 ++++++++++++++++++++++-- 2 files changed, 53 insertions(+), 4 deletions(-) diff --git a/src/cuemsengine/NodeEngine.py b/src/cuemsengine/NodeEngine.py index 61d2997d..b4fb499b 100644 --- a/src/cuemsengine/NodeEngine.py +++ b/src/cuemsengine/NodeEngine.py @@ -17,7 +17,11 @@ from .cues.CueHandler import CUE_HANDLER, _ArmWalk 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 @@ -445,6 +449,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/players/PlayerHandler.py b/src/cuemsengine/players/PlayerHandler.py index ffa79a1d..1e561be9 100644 --- a/src/cuemsengine/players/PlayerHandler.py +++ b/src/cuemsengine/players/PlayerHandler.py @@ -53,12 +53,54 @@ def _positive_int(value) -> bool: # (old project torn down, new one never armed), and one from the mixer sweep # left the node without a mixer. -AUDIOPLAYER_ORPHAN_PATTERN = "cuems-audioplayer" +# +# 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 whose command line matches `pattern` (pgrep -f). Never raises. + """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 @@ -66,7 +108,7 @@ def _orphan_pids(pattern: str, label: str) -> list[int]: """ try: result = subprocess.run( - ["pgrep", "-f", pattern], + ["pgrep", "-u", str(os.geteuid()), "-f", pattern], capture_output=True, text=True, ) From f57f154f2805c7cfcb5cc395a5baa96f448223df Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:10:34 +0200 Subject: [PATCH 21/25] fix(comms): log the command callback traceback (869evtdf7) A node load that died on an EPERM in the orphan sweep left only "Error executing command callback for load: [Errno 1] Operation not permitted": no step, no line. The error now carries its traceback (exc_info=True; cuemsutils' Logger forwards it to logging). --- src/cuemsengine/comms/NodeCommunications.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/cuemsengine/comms/NodeCommunications.py b/src/cuemsengine/comms/NodeCommunications.py index cbc421b6..27148dfc 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 @@ -118,8 +119,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( From 6ae329139183828ac5ddac5854c345342aee3f76 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:10:48 +0200 Subject: [PATCH 22/25] fix(load): the zombie JACK client cleanup never aborts a load (869evtdf7) cleanup_zombie_jack_clients runs right after the audioplayer orphan sweep in _load_project_inner, and its conn_man.get_ports call was unguarded: a JACK error aborted the load at the same point, after the old project was torn down. Now it logs a WARNING and returns 0; audio cues still fail loudly at their own arm, video and DMX load. --- src/cuemsengine/players/PlayerHandler.py | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/src/cuemsengine/players/PlayerHandler.py b/src/cuemsengine/players/PlayerHandler.py index 1e561be9..075c98e7 100644 --- a/src/cuemsengine/players/PlayerHandler.py +++ b/src/cuemsengine/players/PlayerHandler.py @@ -470,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. @@ -478,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 From 0d197f399cd8b26642fcaf6dae9f87201ea30071 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 19:11:05 +0200 Subject: [PATCH 23/25] docs(orphan-kill): sweeps never abort a load and depend on the binary name (869evtdf7) --- CLAUDE.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CLAUDE.md b/CLAUDE.md index 4e3b3e5e..e76800ee 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -101,6 +101,7 @@ 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 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`). From 173301e3b8d0cff1e3375ab983c0bc33662f2671 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 20:16:25 +0200 Subject: [PATCH 24/25] test(audio): count only the test thread's sleeps in the AudioMixer wait tests (869fbyjzx) Seven tests patched time.sleep process-wide and counted every call. Under pytest-xdist, threads left running by other tests in the same worker sleep through that patch too: on PR #25's CI run the shared-budget check saw 6083 s of foreign sleeps against a 1 s ceiling. _this_thread_sleeps() records only the calls made by the test's own thread (foreign calls are still swallowed), with a guard test. Test-only change. --- tests/test_players_audiomixer.py | 76 ++++++++++++++++++++++++++------ 1 file changed, 62 insertions(+), 14 deletions(-) diff --git a/tests/test_players_audiomixer.py b/tests/test_players_audiomixer.py index d66f4148..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.""" @@ -225,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 @@ -246,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} @@ -1040,10 +1064,10 @@ def test_ready_already_set_wires_without_waiting(self, caplog): ready = threading.Event() ready.set() m, cm = self._mixer({P0, P1, IN1, IN2}) - with patch("time.sleep") as mock_sleep, caplog.at_level(logging.INFO): + 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 - mock_sleep.assert_not_called() + 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) @@ -1097,24 +1121,24 @@ def test_no_jack_client_returns_at_once_without_waiting(self): ready = _ReadyNever() m, cm = self._mixer({P0, P1, IN1, IN2}) cm.client = None - with patch("time.sleep") as mock_sleep: + 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 - mock_sleep.assert_not_called() + 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 patch("time.sleep") as mock_sleep: + 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(c.args[0] for c in mock_sleep.call_args_list) + port_s = sum(sleeps) assert ready_s + port_s <= 14.5 + 1e-9 assert ready_s >= 14.5 - 0.05 @@ -1321,7 +1345,7 @@ class TestSharedBudget: 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 patch("time.sleep") as mock_sleep: + with _this_thread_sleeps() as sleeps: m.connect_player_to_outputs( PL, "outport", @@ -1334,7 +1358,7 @@ def test_total_wait_stays_within_the_ceiling(self, n, max_retries, 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(c.args[0] for c in mock_sleep.call_args_list) + used = waited_slices * 0.05 + sum(sleeps) assert used <= ceiling + 1e-9, (n, used, ceiling) @@ -1356,3 +1380,27 @@ def is_connected(src, dst): 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] From e71aca8ea313ab97a74ec31488f0307bb43656e7 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Thu, 8 Oct 2026 21:12:33 +0200 Subject: [PATCH 25/25] release: cuems-engine 0.1.0rc6-3 --- debian/changelog | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) 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):