From bb983d019cfb3fc45aba8bfb4a15d189a1837ff9 Mon Sep 17 00:00:00 2001 From: Andrew Wilson Date: Tue, 13 Oct 2026 14:50:26 -0500 Subject: [PATCH 1/2] feat(cloudxr): publish OOB progress from shared service Signed-off-by: Andrew Wilson --- .../isaaccapture/cloudxr/oob_teleop_env.py | 28 +-- .../cloudxr/oob_teleop_progress.py | 108 +++++++++++ .../isaaccapture/cloudxr/service/__main__.py | 172 +---------------- .../isaaccapture/cloudxr/service/_service.py | 34 ++++ tests/python/core/cloudxr/conftest.py | 1 + .../core/cloudxr/test_oob_teleop_env.py | 14 ++ .../core/cloudxr/test_oob_teleop_progress.py | 123 ++++++++++++ tests/python/core/cloudxr/test_service.py | 19 ++ tests/python/core/cloudxr/test_service_cli.py | 182 +----------------- .../core/cloudxr/test_service_oob_status.py | 27 ++- 10 files changed, 351 insertions(+), 357 deletions(-) create mode 100644 src/python/isaaccapture/cloudxr/oob_teleop_progress.py create mode 100644 tests/python/core/cloudxr/test_oob_teleop_progress.py diff --git a/src/python/isaaccapture/cloudxr/oob_teleop_env.py b/src/python/isaaccapture/cloudxr/oob_teleop_env.py index dfc84681ba..2b39336d91 100644 --- a/src/python/isaaccapture/cloudxr/oob_teleop_env.py +++ b/src/python/isaaccapture/cloudxr/oob_teleop_env.py @@ -817,7 +817,9 @@ def ss_listeners_on_port(port: int) -> list[str]: return out -def print_host_preflight_warnings(*, usb_local: bool) -> None: +def print_host_preflight_warnings( + *, usb_local: bool, emit_console: bool = True +) -> None: """Best-effort host preflight (port conflicts + ufw). In ``--usb-local`` mode this is fail-fast: a port conflict on any of @@ -830,6 +832,8 @@ def print_host_preflight_warnings(*, usb_local: bool) -> None: ufw findings are always warn-only (best-effort: ``status`` parsing can yield false positives on permissive rulesets), and ufw is only checked in WiFi mode (USB-local is loopback, not firewalled). + Shared service callers use ``emit_console=False`` to avoid duplicating + logger warnings in embedded operator terminals. The WSS proxy binds the wildcard address (``host=""`` in :mod:`websockets`, i.e. ``0.0.0.0``), but we probe via loopback @@ -860,19 +864,21 @@ def print_host_preflight_warnings(*, usb_local: bool) -> None: "then retry." ) log.warning("preflight: port(s) already in use: %s", busy) - print( - f"\n\033[33m[preflight] port(s) {busy} already in use; kill the " - f"holder (`ss -tulpn | grep -E '{ports_re}'`) or override via " - "PROXY_PORT.\033[0m\n" - ) + if emit_console: + print( + f"\n\033[33m[preflight] port(s) {busy} already in use; kill the " + f"holder (`ss -tulpn | grep -E '{ports_re}'`) or override via " + "PROXY_PORT.\033[0m\n" + ) # ufw is only meaningful in WiFi mode (USB-local is loopback, not firewalled). if not usb_local: unallowed = _ufw_unallowed_ports([wss_proxy_port()]) if unallowed: cmd = "; ".join(f"sudo ufw allow {p}/tcp" for p in unallowed) log.warning("preflight: ufw blocks port(s) %s", unallowed) - print( - f"\n\033[33m[preflight] ufw is active and may block port(s) " - f"{unallowed} from reaching the headset. Allow with: {cmd}" - "\033[0m\n" - ) + if emit_console: + print( + f"\n\033[33m[preflight] ufw is active and may block port(s) " + f"{unallowed} from reaching the headset. Allow with: {cmd}" + "\033[0m\n" + ) diff --git a/src/python/isaaccapture/cloudxr/oob_teleop_progress.py b/src/python/isaaccapture/cloudxr/oob_teleop_progress.py new file mode 100644 index 0000000000..551bdea764 --- /dev/null +++ b/src/python/isaaccapture/cloudxr/oob_teleop_progress.py @@ -0,0 +1,108 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Sparse operator progress derived from OOB lifecycle snapshots.""" + +from __future__ import annotations + +import time +from collections.abc import Callable + + +class OobProgressReporter: + """Describe setup transitions for foreground and embedded service owners.""" + + def __init__(self, clock: Callable[[], float] = time.monotonic) -> None: + self._clock = clock + self._adb_ready = False + self._ever_adb_ready = False + self._last_stage: tuple | None = None + self._last_health: str | None = None + self._last_wait: tuple | None = None + self._last_wait_at = float("-inf") + self._last_delay_at: dict[str, float] = {} + + def observe(self, snapshot: dict) -> list[str]: + """Return new messages; repeated waits get at most one reminder per minute.""" + if snapshot.get("health") == "starting": + return [] + + state = snapshot.get("state") + health = snapshot.get("health") + reason = snapshot.get("reason") or "unknown reason" + serial = snapshot.get("selectedSerial") + ready = bool(snapshot.get("adbReady")) + stage = ( + state, + reason, + snapshot.get("episodeStartedAt"), + snapshot.get("generation"), + ) + entered = stage != self._last_stage + now = self._clock() + messages: list[str] = [] + + if ready and not self._adb_ready: + verb = "reconnected" if self._ever_adb_ready else "detected" + messages.append( + f"USB-attached HMD {verb} (serial {serial}); continuing OOB setup." + ) + self._ever_adb_ready = True + self._adb_ready = ready + + if state == "WAITING_FOR_ADB" and not ready: + wait = (serial, reason, snapshot.get("adbDiagnostic")) + if wait != self._last_wait or now - self._last_wait_at >= 60: + if snapshot.get("adbDiagnostic"): + messages.append(f"ADB diagnostic: {snapshot['adbDiagnostic']}") + elif serial is None and not any( + word in reason.lower() + for word in ("unauthorized", "offline", "multiple") + ): + messages.append( + "No USB-attached HMD detected; connect a headset to continue." + ) + else: + messages.append(f"Waiting for USB-attached HMD: {reason}") + self._last_wait_at = now + self._last_wait = wait + else: + self._last_wait = None + + if entered: + if state == "PREPARING_DEVICE": + messages.append( + f"Waiting for headset transport: {reason}" + if snapshot.get("networkPresent") is False + else f"Preparing headset {serial} for OOB setup." + ) + elif state == "REBUILDING_USB": + messages.append("Configuring USB reverse rules and TURN.") + elif state == "AUTOMATING_BROWSER": + messages.append( + "USB reverse rules and TURN verified; opening headset browser." + if reason == "TURN and reverse rules verified" + else "Opening headset browser and connecting OOB client." + ) + elif state == "VERIFYING_EXISTING_BROWSER": + messages.append("USB transport restored; checking existing browser.") + elif state == "VERIFYING_BROWSER": + messages.append("Waiting for headset browser health report.") + elif state == "WAITING_FOR_AWAKE": + messages.append(f"Waiting for selected headset to wake: {reason}") + elif state == "USB_HEALTH_BLOCKED": + messages.append(f"USB health policy blocked browser launch: {reason}") + elif state == "DEGRADED" or "Recovery episode expired" in reason: + if now - self._last_delay_at.get(reason, float("-inf")) >= 30: + messages.append(f"OOB recovery delayed: {reason}") + self._last_delay_at[reason] = now + + if health == "browser_ready" and health != self._last_health: + messages.append( + "OOB browser ready; waiting for fresh stream metrics." + if snapshot.get("streaming") + else "OOB browser ready; waiting for OpenXR stream." + ) + self._last_stage = stage + self._last_health = health + return messages diff --git a/src/python/isaaccapture/cloudxr/service/__main__.py b/src/python/isaaccapture/cloudxr/service/__main__.py index ebfb51248b..96fae05df2 100644 --- a/src/python/isaaccapture/cloudxr/service/__main__.py +++ b/src/python/isaaccapture/cloudxr/service/__main__.py @@ -14,7 +14,6 @@ import sys import time from pathlib import Path -from typing import Callable from ._service import CloudXRService @@ -130,18 +129,7 @@ def _fail(message: str) -> None: def _oob_preflight(args: argparse.Namespace) -> str | None: - """Check host prerequisites; headset readiness belongs to the lifecycle. - - Valid flag combinations: - - ============================== ================================================== - (none) headset navigates to the GitHub Pages URL over WiFi - ``--host-client`` client served at ``https://:/client/`` - ``--setup-oob`` OOB hub + CDP automation; GitHub Pages URL - ``--setup-oob --host-client`` OOB hub + CDP; client on the WSS proxy - ``--setup-oob --usb-local`` OOB hub + CDP; adb-reverse + coturn; /client/ on WSS - ============================== ================================================== - """ + """Check foreground-specific prerequisites; shared progress is service-owned.""" from ..oob_teleop_adb import ( # noqa: PLC0415 OobAdbError, require_adb_on_path, @@ -149,8 +137,6 @@ def _oob_preflight(args: argparse.Namespace) -> str | None: require_turn_port_free, ) from ..oob_teleop_env import ( # noqa: PLC0415 - oob_progress, - print_host_preflight_warnings, resolve_lan_host_for_oob, resolve_oob_recovery_config, usb_turn_port, @@ -158,53 +144,24 @@ def _oob_preflight(args: argparse.Namespace) -> str | None: if args.setup_oob: try: - config = resolve_oob_recovery_config() + args._oob_recovery_config = resolve_oob_recovery_config() except ValueError as exc: _fail(str(exc)) - args._oob_recovery_config = config - oob_progress( - "setup-oob", - f"recovery episode {config.timeout_sec:g}s, retry/observe {config.interval_sec:g}s", - ) if args.usb_local: - oob_progress( - "usb-local", - "host preflight: adb, coturn, ports, assets ...", - ) require_adb_on_path() try: require_coturn_available() require_turn_port_free(usb_turn_port()) except OobAdbError as exc: _fail(str(exc)) - try: - print_host_preflight_warnings(usb_local=True) - except RuntimeError as exc: - _fail(str(exc)) - oob_progress("usb-local", "host preflight OK; waiting for headset after listen") return None if not args.setup_oob: return None - - # TELEOP_OOB_HUB_ONLY skips every adb step — the hub starts, but the - # operator opens the teleop page on the headset themselves. - hub_only = bool(os.getenv("TELEOP_OOB_HUB_ONLY")) - if hub_only: - oob_progress( - "setup-oob", "hub-only mode (TELEOP_OOB_HUB_ONLY) — skipping adb preflight" - ) - else: - oob_progress("setup-oob", "host preflight: adb and network configuration ...") + if not os.getenv("TELEOP_OOB_HUB_ONLY"): require_adb_on_path() - lan_host = resolve_lan_host_for_oob() - try: - print_host_preflight_warnings(usb_local=False) - except RuntimeError as exc: - _fail(str(exc)) - oob_progress("setup-oob", "host preflight OK; headset automation may be pending") - return lan_host + return resolve_lan_host_for_oob() def _env_file_value(run_dir: str, key: str) -> str | None: @@ -311,111 +268,6 @@ def _print_service_summary( ) -class _OobConsoleReporter: - """Turn lifecycle snapshots into sparse, actionable launcher messages.""" - - def __init__(self, clock: Callable[[], float] = time.monotonic): - self._clock = clock - self._last_emitted: dict[str, float] = {} - self._adb_ready = False - self._ever_ready = False - self._last_health: str | None = None - self._last_stage: tuple | None = None - self._last_ignored: tuple | None = None - - def observe(self, snapshot: dict) -> list[str]: - """Return messages for a new snapshot, with repeated states limited.""" - health = snapshot.get("health") - if health == "starting": - return [] - state = snapshot.get("state") - reason = snapshot.get("reason") or "unknown reason" - serial = snapshot.get("selectedSerial") - ready = bool(snapshot.get("adbReady")) - stage = (state, snapshot.get("episodeStartedAt"), snapshot.get("generation")) - entered_stage = stage != self._last_stage - messages: list[str] = [] - ignored = tuple(sorted(snapshot.get("ignoredSerials") or ())) - ignored_signature = (ignored, ready, reason if not ready else None) - - def emit(key: str, message: str, interval: float = 30.0) -> None: - now = self._clock() - if now - self._last_emitted.get(key, float("-inf")) >= interval: - self._last_emitted[key] = now - messages.append(f"[setup-oob] {message}") - - if ready and not self._adb_ready: - verb = "reconnected" if self._ever_ready else "detected" - emit( - "adb-ready", - f"USB-attached HMD {verb} (serial {serial}); continuing OOB setup.", - 0, - ) - self._ever_ready = True - elif not ready and self._adb_ready: - emit( - "adb-lost", - "USB-attached HMD connection lost; waiting for the selected headset.", - 0, - ) - self._adb_ready = ready - - if ignored and ignored_signature != self._last_ignored: - names = ", ".join(ignored) - if ready: - messages.append( - f"[setup-oob] Ignored ADB device(s) {names}; continuing with selected headset {serial}." - ) - else: - state_detail = ( - " (offline)" - if "offline" in reason.lower() - else " (unauthorized)" - if "unauthorized" in reason.lower() - else "" - ) - messages.append( - f"[setup-oob] Ignored ADB device(s) {names}; waiting for selected headset {serial}{state_detail} to reconnect." - ) - self._last_ignored = ignored_signature - - if state == "WAITING_FOR_ADB" and not ready: - diagnostic = snapshot.get("adbDiagnostic") - if diagnostic: - emit(f"adb-diagnostic:{diagnostic}", f"ADB diagnostic: {diagnostic}") - elif serial is None and not any( - word in reason.lower() - for word in ("unauthorized", "offline", "multiple") - ): - emit( - "no-hmd", - "No USB-attached HMD detected; connect a headset to continue.", - 60, - ) - else: - emit(f"adb-wait:{reason}", f"Waiting for USB-attached HMD: {reason}") - elif state == "PREPARING_DEVICE" and ready and entered_stage: - emit("prepare", f"Preparing headset {serial} for OOB setup.", 0) - elif state == "REBUILDING_USB" and entered_stage: - emit("usb", "Configuring USB reverse rules and TURN.", 0) - elif state == "AUTOMATING_BROWSER" and entered_stage: - emit("browser", "Opening headset browser and connecting OOB client.", 0) - elif state == "VERIFYING_BROWSER" and entered_stage: - emit("verify", "Waiting for headset browser health report.", 0) - elif state == "DEGRADED": - emit(f"failure:{reason}", f"OOB recovery delayed: {reason}") - elif health == "fatal": - emit("fatal", f"OOB stopped: {reason}", 0) - - if health == "browser_ready" and self._last_health != health: - emit("browser-ready", "OOB browser ready; waiting for OpenXR stream.") - elif health == "active" and self._last_health != health: - emit("active", "OOB stream active with fresh client metrics.") - self._last_health = health - self._last_stage = stage - return messages - - def _cmd_run(args: argparse.Namespace) -> int: """Run the service in the foreground until interrupted.""" if args.usb_local and not args.setup_oob: @@ -439,8 +291,6 @@ def _cmd_run(args: argparse.Namespace) -> int: recovery_config=getattr(args, "_oob_recovery_config", None), ) except RuntimeError as exc: - # Operator-facing conditions (a live runtime, a rejected EULA); the - # message is the whole point, so don't bury it in a traceback. _fail(str(exc)) with service: @@ -454,15 +304,6 @@ def _cmd_run(args: argparse.Namespace) -> int: include_oob=True, ) _out_interactive("\033[33mKeep this terminal open, Ctrl+C to terminate.\033[0m") - reporter = _OobConsoleReporter() if args.setup_oob else None - - def report_oob_updates() -> None: - if reporter is not None: - for snapshot in service.drain_oob_updates(): - for message in reporter.observe(snapshot): - _out(message) - - report_oob_updates() stop = False @@ -475,14 +316,13 @@ def on_signal(sig, frame): signal.signal(signal.SIGTERM, on_signal) while not stop: - report_oob_updates() try: service.health_check() except RuntimeError: status = service.oob_status() - if reporter is None or not status or status.get("health") != "fatal": + if not args.setup_oob or not status or status.get("health") != "fatal": raise - report_oob_updates() + # The shared service logs the fatal reason once for every owner. return 1 time.sleep(0.1) diff --git a/src/python/isaaccapture/cloudxr/service/_service.py b/src/python/isaaccapture/cloudxr/service/_service.py index 3faa3df3a0..82324f6ada 100644 --- a/src/python/isaaccapture/cloudxr/service/_service.py +++ b/src/python/isaaccapture/cloudxr/service/_service.py @@ -30,6 +30,8 @@ from pathlib import Path from ..env_config import DEFAULT_DEVICE_PROFILE, ENV_FILE_NAME, EnvConfig +from ..oob_teleop_env import oob_progress +from ..oob_teleop_progress import OobProgressReporter from ...logging_config._core import logging_enabled from ...logging_config._native_api import native_capture_fd, native_capture_path from ..runtime import ( @@ -171,6 +173,11 @@ def __init__( self._usb_local = usb_local self._host_client = host_client + if setup_oob and (usb_local or host_client): + oob_progress( + "usb-local" if usb_local else "setup-oob", + "host preflight: checking web client assets", + ) if self._usb_local or self._host_client: from ..oob_teleop_env import require_web_client_static_dir # noqa: PLC0415 @@ -190,6 +197,8 @@ def __init__( self._oob_publish_lock = asyncio.Lock() self._oob_snapshot: dict | None = None self._oob_updates: deque[dict] = deque(maxlen=128) + # Shared publication reaches embedded owners; the service CLI does not. + self._oob_progress_reporter = OobProgressReporter() if setup_oob else None self._oob_session_id = uuid.uuid4().hex self._fatal_error: Exception | None = None self._fatal_supervisor: threading.Thread | None = None @@ -219,10 +228,22 @@ def __init__( require_turn_port_free, ) from ..oob_teleop_env import ( # noqa: PLC0415 + print_host_preflight_warnings, resolve_lan_host_for_oob, usb_turn_port, ) + stage = "usb-local" if usb_local else "setup-oob" + oob_progress( + stage, + f"recovery episode {self._recovery_config.timeout_sec:g}s, " + f"retry/observe {self._recovery_config.interval_sec:g}s", + ) + oob_progress( + stage, "host preflight: checking adb and transport dependencies" + ) + if not usb_local and os.getenv("TELEOP_OOB_HUB_ONLY"): + oob_progress(stage, "hub-only mode; skipping adb preflight") if usb_local or not os.getenv("TELEOP_OOB_HUB_ONLY"): require_adb_on_path() if usb_local: @@ -230,6 +251,8 @@ def __init__( require_turn_port_free(usb_turn_port()) else: resolve_lan_host_for_oob() + print_host_preflight_warnings(usb_local=usb_local, emit_console=False) + oob_progress(stage, "host preflight OK; starting CloudXR runtime") try: self._oob_status_path.unlink(missing_ok=True) except OSError as exc: @@ -322,6 +345,11 @@ def __init__( self.stop() raise logger.info("CloudXR WSS proxy listening (log=%s)", wss_log_path) + if setup_oob: + oob_progress( + "usb-local" if usb_local else "setup-oob", + "runtime and OOB proxy listening; headset setup may still be pending", + ) # ------------------------------------------------------------------ # Context manager @@ -438,6 +466,11 @@ async def _publish_oob_status(self, snapshot: dict) -> None: # so it cannot recreate a stale status file after cleanup. await persistence raise + reporter = getattr(self, "_oob_progress_reporter", None) + if reporter is not None: + stage = "usb-local" if self._usb_local else "setup-oob" + for message in reporter.observe(payload): + oob_progress(stage, message) def oob_status(self) -> dict | None: """Return the latest lifecycle snapshot without touching the WSS event loop.""" @@ -504,6 +537,7 @@ async def _on_oob_fatal( payload["readinessSince"] = payload["updatedAt"] self._oob_snapshot = payload self._oob_updates.append(payload) + logger.error("OOB stopped: %s", reason) self._fatal_supervisor = threading.Thread( target=self._stop_after_oob_fatal, name="cloudxr-oob-fatal-supervisor", diff --git a/tests/python/core/cloudxr/conftest.py b/tests/python/core/cloudxr/conftest.py index 0a8592a9e3..e11eefb094 100644 --- a/tests/python/core/cloudxr/conftest.py +++ b/tests/python/core/cloudxr/conftest.py @@ -197,6 +197,7 @@ def mock_service_deps(tmp_path, ready=True, wss=True): "isaaccapture.cloudxr.oob_teleop_env.require_web_client_static_dir", return_value=static_dir, ) as m_static_client, + patch("isaaccapture.cloudxr.oob_teleop_env.print_host_preflight_warnings"), patch( "isaaccapture.cloudxr.service._service.subprocess.Popen", return_value=mock_proc, diff --git a/tests/python/core/cloudxr/test_oob_teleop_env.py b/tests/python/core/cloudxr/test_oob_teleop_env.py index 729f91f233..f0bc246a8a 100644 --- a/tests/python/core/cloudxr/test_oob_teleop_env.py +++ b/tests/python/core/cloudxr/test_oob_teleop_env.py @@ -718,6 +718,20 @@ def test_print_host_preflight_warnings_busy_port(capsys) -> None: assert "PROXY_PORT" in out +def test_host_preflight_warning_can_use_logger_only(capsys) -> None: + with ( + patch("cloudxr_py_test_ns.oob_teleop_env._port_in_use", return_value=True), + patch( + "cloudxr_py_test_ns.oob_teleop_env._ufw_unallowed_ports", + return_value=None, + ), + patch("cloudxr_py_test_ns.oob_teleop_env.log.warning") as warning, + ): + print_host_preflight_warnings(usb_local=False, emit_console=False) + assert capsys.readouterr().out == "" + warning.assert_called_once() + + def test_print_host_preflight_warnings_ufw_blocks(capsys) -> None: """ufw blocking the proxy port prints a warning with the ufw allow command.""" with ( diff --git a/tests/python/core/cloudxr/test_oob_teleop_progress.py b/tests/python/core/cloudxr/test_oob_teleop_progress.py new file mode 100644 index 0000000000..4564fc4503 --- /dev/null +++ b/tests/python/core/cloudxr/test_oob_teleop_progress.py @@ -0,0 +1,123 @@ +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Operator progress delivered by the shared OOB service.""" + +from isaaccapture.cloudxr.oob_teleop_progress import OobProgressReporter + + +def test_absent_headset_wait_is_visible_and_rate_limited(): + now = [0.0] + reporter = OobProgressReporter(clock=lambda: now[0]) + waiting = { + "health": "degraded", + "state": "WAITING_FOR_ADB", + "reason": "Waiting for selected headset", + "adbReady": False, + } + assert reporter.observe({**waiting, "health": "starting"}) == [] + assert reporter.observe(waiting) == [ + "No USB-attached HMD detected; connect a headset to continue." + ] + now[0] = 5 + assert reporter.observe(waiting) == [] + now[0] = 61 + assert reporter.observe(waiting) == [ + "No USB-attached HMD detected; connect a headset to continue." + ] + + +def test_selected_headset_and_adb_diagnostics_are_actionable(): + reporter = OobProgressReporter(clock=lambda: 0) + waiting = { + "health": "degraded", + "state": "WAITING_FOR_ADB", + "reason": "Selected headset HMD-1 offline; reconnect USB", + "selectedSerial": "HMD-1", + "adbReady": False, + } + assert reporter.observe(waiting) == [ + "Waiting for USB-attached HMD: Selected headset HMD-1 offline; reconnect USB" + ] + diagnostic = { + **waiting, + "reason": "adb: failed to connect to daemon at tcp:5037", + "adbDiagnostic": "adb: failed to connect to daemon at tcp:5037", + } + assert reporter.observe(diagnostic) == [ + "ADB diagnostic: adb: failed to connect to daemon at tcp:5037" + ] + + +def test_replug_reports_reentered_phases_without_steady_state_spam(): + reporter = OobProgressReporter(clock=lambda: 0) + base = { + "health": "degraded", + "selectedSerial": "HMD-1", + "adbReady": True, + } + phases = ( + ("PREPARING_DEVICE", "Preparing headset HMD-1"), + ("REBUILDING_USB", "Configuring USB reverse rules"), + ("AUTOMATING_BROWSER", "Opening headset browser"), + ("VERIFYING_BROWSER", "Waiting for headset browser"), + ) + for state, expected in phases: + messages = reporter.observe({**base, "state": state}) + assert any(expected in message for message in messages) + assert reporter.observe({**base, "state": state}) == [] + + lost = { + **base, + "state": "WAITING_FOR_ADB", + "reason": "Selected headset disconnected", + "adbReady": False, + } + assert any("Waiting for USB-attached HMD" in m for m in reporter.observe(lost)) + for state, expected in phases: + messages = reporter.observe({**base, "state": state}) + assert any(expected in message for message in messages) + if state == "PREPARING_DEVICE": + assert any("HMD reconnected" in message for message in messages) + + +def test_new_episode_reannounces_same_phase(): + reporter = OobProgressReporter(clock=lambda: 0) + phase = { + "health": "degraded", + "state": "REBUILDING_USB", + "reason": "Configuring USB reverse rules", + "episodeStartedAt": 10, + } + assert reporter.observe(phase) == ["Configuring USB reverse rules and TURN."] + assert reporter.observe(phase) == [] + assert reporter.observe({**phase, "episodeStartedAt": 20}) == [ + "Configuring USB reverse rules and TURN." + ] + + +def test_browser_ready_is_not_claimed_to_be_streaming(): + reporter = OobProgressReporter(clock=lambda: 0) + base = {"selectedSerial": "HMD-1", "adbReady": True, "state": "ACTIVE"} + messages = reporter.observe({**base, "health": "browser_ready"}) + assert "OOB browser ready; waiting for OpenXR stream." in messages + assert reporter.observe({**base, "health": "browser_ready"}) == [] + assert reporter.observe({**base, "health": "active"}) == [] + + +def test_recovery_delay_is_rate_limited(): + now = [0.0] + reporter = OobProgressReporter(clock=lambda: now[0]) + delayed = { + "health": "degraded", + "state": "DEGRADED", + "reason": "coturn is not listening", + } + assert reporter.observe(delayed) == [ + "OOB recovery delayed: coturn is not listening" + ] + assert reporter.observe(delayed) == [] + now[0] = 31 + assert reporter.observe({**delayed, "generation": 2}) == [ + "OOB recovery delayed: coturn is not listening" + ] diff --git a/tests/python/core/cloudxr/test_service.py b/tests/python/core/cloudxr/test_service.py index d32eea5385..476a58ebb4 100644 --- a/tests/python/core/cloudxr/test_service.py +++ b/tests/python/core/cloudxr/test_service.py @@ -74,6 +74,25 @@ def test_embedded_usb_preflight_checks_coturn_before_runtime_spawn(self, tmp_pat ) mocks["popen"].assert_not_called() + def test_embedded_usb_port_conflict_fails_before_runtime_spawn(self, tmp_path): + with ( + mock_service_deps(tmp_path, ready=True) as mocks, + patch("isaaccapture.cloudxr.oob_teleop_env.require_web_client_static_dir"), + patch("isaaccapture.cloudxr.oob_teleop_adb.require_adb_on_path"), + patch("isaaccapture.cloudxr.oob_teleop_adb.require_coturn_available"), + patch("isaaccapture.cloudxr.oob_teleop_adb.require_turn_port_free"), + patch( + "isaaccapture.cloudxr.oob_teleop_env.print_host_preflight_warnings", + side_effect=RuntimeError("required ports occupied"), + ) as ports, + ): + with pytest.raises(RuntimeError, match="required ports occupied"): + CloudXRService( + install_dir=str(tmp_path), setup_oob=True, usb_local=True + ) + ports.assert_called_once_with(usb_local=True, emit_console=False) + mocks["popen"].assert_not_called() + def test_oob_rejects_incompatible_webxr_bundle_before_runtime_spawn(self, tmp_path): with ( mock_service_deps(tmp_path, ready=True) as mocks, diff --git a/tests/python/core/cloudxr/test_service_cli.py b/tests/python/core/cloudxr/test_service_cli.py index 8bf54ec15b..26734b6ae8 100644 --- a/tests/python/core/cloudxr/test_service_cli.py +++ b/tests/python/core/cloudxr/test_service_cli.py @@ -56,179 +56,8 @@ def test_accept_eula_is_never_baked_into_the_unit(self): assert "--accept-eula" not in cli._run_flags(_run_args(accept_eula=True)) -class TestOobConsoleReporter: - def test_ignored_set_and_selected_state_changes_emit_once(self): - reporter = cli._OobConsoleReporter(clock=lambda: 0) - base = { - "health": "degraded", - "state": "WAITING_FOR_ADB", - "reason": "Waiting for selected headset to reconnect", - "selectedSerial": "original", - "adbReady": False, - "ignoredSerials": ["other"], - } - assert any( - "Ignored ADB device(s) other; waiting for selected headset original" in line - for line in reporter.observe(base) - ) - assert reporter.observe(base) == [] - offline = { - **base, - "reason": "Selected headset offline; reconnect the USB cable", - } - assert any("original (offline)" in line for line in reporter.observe(offline)) - assert reporter.observe(offline) == [] - more = {**offline, "ignoredSerials": ["other", "another"]} - assert any("another, other" in line for line in reporter.observe(more)) - assert reporter.observe({**more, "ignoredSerials": ["another", "other"]}) == [] - ready = {**more, "state": "PREPARING_DEVICE", "adbReady": True} - assert any( - "continuing with selected headset original" in line - for line in reporter.observe(ready) - ) - assert reporter.observe(ready) == [] - - def test_absent_headset_is_visible_but_rate_limited(self): - now = [0.0] - reporter = cli._OobConsoleReporter(clock=lambda: now[0]) - waiting = { - "health": "degraded", - "state": "WAITING_FOR_ADB", - "reason": "Waiting for selected headset", - "selectedSerial": None, - "adbReady": False, - } - assert reporter.observe({**waiting, "health": "starting"}) == [] - assert reporter.observe(waiting) == [ - "[setup-oob] No USB-attached HMD detected; connect a headset to continue." - ] - now[0] = 5 - assert reporter.observe(waiting) == [] - now[0] = 61 - assert reporter.observe(waiting) == [ - "[setup-oob] No USB-attached HMD detected; connect a headset to continue." - ] - - def test_exact_adb_diagnostic_reaches_console(self): - reporter = cli._OobConsoleReporter(clock=lambda: 0) - messages = reporter.observe( - { - "health": "degraded", - "state": "WAITING_FOR_ADB", - "reason": "Waiting for selected headset", - "selectedSerial": None, - "adbReady": False, - "adbDiagnostic": "adb: failed to connect to daemon at tcp:5037", - } - ) - assert messages == [ - "[setup-oob] ADB diagnostic: adb: failed to connect to daemon at tcp:5037" - ] - - def test_ready_loss_and_reconnection_are_reported(self): - reporter = cli._OobConsoleReporter(clock=lambda: 0) - ready = { - "health": "degraded", - "state": "PREPARING_DEVICE", - "reason": "Preparing selected headset", - "selectedSerial": "HMD-1", - "adbReady": True, - } - first = reporter.observe(ready) - assert any("HMD detected (serial HMD-1)" in line for line in first) - assert reporter.observe(ready) == [] - lost = {**ready, "state": "WAITING_FOR_ADB", "adbReady": False} - assert any("connection lost" in line for line in reporter.observe(lost)) - assert any( - "HMD reconnected (serial HMD-1)" in line for line in reporter.observe(ready) - ) - - def test_phase_failure_and_health_transitions(self): - reporter = cli._OobConsoleReporter(clock=lambda: 0) - base = {"selectedSerial": "HMD-1", "adbReady": True, "health": "degraded"} - assert any( - "USB reverse rules" in line - for line in reporter.observe({**base, "state": "REBUILDING_USB"}) - ) - assert reporter.observe({**base, "state": "REBUILDING_USB"}) == [] - failure = {**base, "state": "DEGRADED", "reason": "coturn is not listening"} - assert reporter.observe(failure) == [ - "[setup-oob] OOB recovery delayed: coturn is not listening" - ] - assert reporter.observe(failure) == [] - browser = {**base, "health": "browser_ready", "state": "ACTIVE"} - assert reporter.observe(browser) == [ - "[setup-oob] OOB browser ready; waiting for OpenXR stream." - ] - assert reporter.observe({**browser, "health": "active"}) == [ - "[setup-oob] OOB stream active with fresh client metrics." - ] - - def test_quick_replug_reports_each_reentered_phase(self): - reporter = cli._OobConsoleReporter(clock=lambda: 0) - base = {"health": "degraded", "selectedSerial": "HMD-1", "adbReady": True} - phases = ( - ("PREPARING_DEVICE", "Preparing headset HMD-1"), - ("REBUILDING_USB", "Configuring USB reverse rules"), - ("AUTOMATING_BROWSER", "Opening headset browser"), - ("VERIFYING_BROWSER", "Waiting for headset browser"), - ) - for state, expected in phases: - snapshot = {**base, "state": state} - assert any(expected in line for line in reporter.observe(snapshot)) - assert reporter.observe(snapshot) == [] - - lost = {**base, "state": "WAITING_FOR_ADB", "adbReady": False} - assert any("connection lost" in line for line in reporter.observe(lost)) - for state, expected in phases: - snapshot = {**base, "state": state} - assert any(expected in line for line in reporter.observe(snapshot)) - assert reporter.observe(snapshot) == [] - - same_stage_new_generation = { - **base, - "state": "VERIFYING_BROWSER", - "generation": 2, - } - assert any( - "Waiting for headset browser" in line - for line in reporter.observe(same_stage_new_generation) - ) - - def test_foreground_run_prints_queued_lifecycle_after_banner( - self, tmp_path, capsys - ): - service = MagicMock() - service.__enter__.return_value = service - service.drain_oob_updates.side_effect = [ - [ - {"health": "starting", "state": "WAITING_FOR_ADB"}, - { - "health": "degraded", - "state": "WAITING_FOR_ADB", - "selectedSerial": None, - "adbReady": False, - }, - ], - [], - ] - args = _run_args( - setup_oob=True, usb_local=True, cloudxr_install_dir=str(tmp_path) - ) - with ( - patch.object(cli, "_oob_preflight", return_value=None), - patch.object(cli, "CloudXRService", return_value=service), - patch.object(cli, "_print_service_summary") as summary, - patch.object(cli.time, "sleep", side_effect=KeyboardInterrupt), - ): - with pytest.raises(KeyboardInterrupt): - cli._cmd_run(args) - summary.assert_called_once() - assert capsys.readouterr().out.count("No USB-attached HMD detected") == 1 - - @pytest.mark.parametrize("hub_only", [False, True]) -def test_foreground_fatal_emits_one_operator_diagnostic( +def test_foreground_fatal_relies_on_shared_service_diagnostic( tmp_path, capsys, monkeypatch, hub_only ): if hub_only: @@ -244,7 +73,6 @@ def test_foreground_fatal_emits_one_operator_diagnostic( "selectedSerial": None, "adbReady": False, } - service.drain_oob_updates.side_effect = [[], [], [fatal]] service.oob_status.return_value = fatal service.health_check.side_effect = RuntimeError("boom") args = _run_args(setup_oob=True, cloudxr_install_dir=str(tmp_path)) @@ -255,13 +83,12 @@ def test_foreground_fatal_emits_one_operator_diagnostic( ): assert cli._cmd_run(args) == 1 output = capsys.readouterr() - assert output.out.count("OOB stopped:") == 1 - assert "restart" in output.out + assert "OOB stopped:" not in output.out assert output.err == "" service.__exit__.assert_called_once() -def test_foreground_fatal_with_stalled_writer_keeps_single_diagnostic(tmp_path, capsys): +def test_foreground_fatal_with_stalled_writer_returns_error(tmp_path, capsys): service = object.__new__(cli.CloudXRService) service._fatal_error = RuntimeError("worker failed") service._runtime_proc = None @@ -272,7 +99,6 @@ def test_foreground_fatal_with_stalled_writer_keeps_single_diagnostic(tmp_path, "state": "FATAL", "reason": "OOB worker failed; check wss.log and restart", } - service.drain_oob_updates = MagicMock(side_effect=[[], [], [fatal]]) service.oob_status = MagicMock(return_value=fatal) service.health_check = MagicMock(side_effect=RuntimeError("worker failed")) args = _run_args(setup_oob=True, cloudxr_install_dir=str(tmp_path)) @@ -283,7 +109,7 @@ def test_foreground_fatal_with_stalled_writer_keeps_single_diagnostic(tmp_path, ): assert cli._cmd_run(args) == 1 output = capsys.readouterr() - assert output.out.count("OOB stopped:") == 1 + assert "OOB stopped:" not in output.out assert output.err == "" service.stop.assert_called_once() diff --git a/tests/python/core/cloudxr/test_service_oob_status.py b/tests/python/core/cloudxr/test_service_oob_status.py index 24aa0bbe5b..a68a981015 100644 --- a/tests/python/core/cloudxr/test_service_oob_status.py +++ b/tests/python/core/cloudxr/test_service_oob_status.py @@ -15,6 +15,7 @@ import pytest from isaaccapture.cloudxr.launcher import CloudXRLauncher +from isaaccapture.cloudxr.oob_teleop_progress import OobProgressReporter from isaaccapture.cloudxr.service import CloudXRService @@ -38,6 +39,25 @@ def _service_for_status(tmp_path): return service +@pytest.mark.asyncio +async def test_status_progress_reaches_embedded_owner_once(tmp_path): + service = _service_for_status(tmp_path) + service._usb_local = True + service._oob_progress_reporter = OobProgressReporter(clock=lambda: 0) + waiting = { + "health": "degraded", + "state": "WAITING_FOR_ADB", + "reason": "Waiting for selected headset", + "adbReady": False, + } + with patch("isaaccapture.cloudxr.service._service.oob_progress") as progress: + await service._publish_oob_status(waiting) + await service._publish_oob_status(waiting) + progress.assert_called_once_with( + "usb-local", "No USB-attached HMD detected; connect a headset to continue." + ) + + @pytest.mark.asyncio async def test_status_file_is_atomic_and_bound_to_session(tmp_path): service = _service_for_status(tmp_path) @@ -225,8 +245,11 @@ async def test_fatal_callback_publishes_terminal_status_once_before_teardown(tmp ) service.drain_oob_updates() error = RuntimeError("fatal lifecycle failure") - await service._on_oob_fatal(error) - await service._on_oob_fatal(RuntimeError("another failure")) + with patch("isaaccapture.cloudxr.service._service.logger.error") as log_error: + await service._on_oob_fatal(error) + await service._on_oob_fatal(RuntimeError("another failure")) + log_error.assert_called_once() + assert log_error.call_args.args[0] == "OOB stopped: %s" service._fatal_supervisor.join(timeout=2) service.stop.assert_called_once() status = service.oob_status() From 54253b8d250ddb40c984faebaf586f6c3b2a9e96 Mon Sep 17 00:00:00 2001 From: Andrew Wilson Date: Wed, 14 Oct 2026 16:17:45 -0500 Subject: [PATCH 2/2] refactor(cloudxr): keep OOB operator progress concise Signed-off-by: Andrew Wilson --- docs/source/references/oob_teleop_control.rst | 8 + .../isaaccapture/cloudxr/oob_teleop_adb.py | 8 +- .../isaaccapture/cloudxr/oob_teleop_env.py | 12 +- .../cloudxr/oob_teleop_lifecycle.py | 1 + .../cloudxr/oob_teleop_progress.py | 111 +++++++++---- .../isaaccapture/cloudxr/service/_service.py | 20 ++- .../isaaccapture/logging_config/_console.py | 2 +- .../core/cloudxr/test_oob_teleop_env.py | 33 +++- .../core/cloudxr/test_oob_teleop_progress.py | 156 ++++++++++++++---- .../core/cloudxr/test_service_oob_status.py | 28 +++- .../core/logging_config/test_console.py | 13 +- 11 files changed, 302 insertions(+), 90 deletions(-) diff --git a/docs/source/references/oob_teleop_control.rst b/docs/source/references/oob_teleop_control.rst index 12b01d54c2..78c6d2fef5 100644 --- a/docs/source/references/oob_teleop_control.rst +++ b/docs/source/references/oob_teleop_control.rst @@ -46,6 +46,14 @@ change opens a fresh 60-second recovery episode. Override the positive, finite values with ``TELEOP_OOB_RECOVERY_TIMEOUT_SEC`` and ``TELEOP_OOB_RETRY_INTERVAL_SEC``; invalid values fail host preflight. +At INFO, OOB progress reports headset waiting and connection, browser readiness, +and streaming loss or recovery. ADB authorization, missing headset Wi-Fi, and +USB-health blocks remain visible with operator action. An unchanged wait for +an absent headset is announced once; routine setup steps are DEBUG messages. +Progress uses the ``isaaccapture.cloudxr.oob_teleop_env.progress`` logger. +It remains visible through filters selecting its parent logger, while embedded +applications can also select progress alone. + To start the hub **without** any ``adb`` interaction — useful in containers, CI, or wireless-only environments — set ``TELEOP_OOB_HUB_ONLY=1`` and open the teleop URL on the headset manually. This mode supports WiFi setup only diff --git a/src/python/isaaccapture/cloudxr/oob_teleop_adb.py b/src/python/isaaccapture/cloudxr/oob_teleop_adb.py index c3332abe93..63a5d74077 100644 --- a/src/python/isaaccapture/cloudxr/oob_teleop_adb.py +++ b/src/python/isaaccapture/cloudxr/oob_teleop_adb.py @@ -373,7 +373,7 @@ def assert_headset_awake(*, timeout: float = 15.0, require_awake: bool = False) except (FileNotFoundError, subprocess.TimeoutExpired): pass - log.warning( + log.debug( "Headset appears asleep (wakefulness=%s). Put it on or cover the " "proximity sensor; waiting up to %.0fs for it to wake.", wake or "?", @@ -2036,7 +2036,7 @@ def _is_candidate_tab(tab: dict) -> bool: if not am_start_retried and time.monotonic() >= retry_at: am_start_retried = True - log.warning( + log.debug( "CDP: tab not found after %.1fs — re-firing am start (cold-launch race)", timeout / 2, ) @@ -2044,6 +2044,7 @@ def _is_candidate_tab(tab: dict) -> bool: "setup-oob", "tab not found yet — re-firing am start (browser may have " "swallowed the first intent on cold launch) ...", + level=logging.DEBUG, ) try: rc, diag = await asyncio.to_thread( @@ -2069,6 +2070,7 @@ def _is_candidate_tab(tab: dict) -> bool: "setup-oob", "teleop tab found — accepting cert, waiting for CONNECT button, " "then auto-clicking it ...", + level=logging.DEBUG, ) # cert interstitial + bring to front + readiness + click @@ -2146,6 +2148,7 @@ async def run_oob_connect( oob_progress( "setup-oob", f"closed {closed} stale teleop tab(s) from a prior session", + level=logging.DEBUG, ) # Brief pause so the browser actually releases WebXR / media # resources before the new page tries to acquire them. @@ -2168,6 +2171,7 @@ async def run_oob_connect( oob_progress( "setup-oob", "headset browser launched — discovering DevTools socket ...", + level=logging.DEBUG, ) # --- Step 2: wait for DevTools socket ------------------------------------ diff --git a/src/python/isaaccapture/cloudxr/oob_teleop_env.py b/src/python/isaaccapture/cloudxr/oob_teleop_env.py index 2b39336d91..96ab71338e 100644 --- a/src/python/isaaccapture/cloudxr/oob_teleop_env.py +++ b/src/python/isaaccapture/cloudxr/oob_teleop_env.py @@ -22,6 +22,7 @@ from .oob_teleop_hub import OOB_WS_PATH log = logging.getLogger("isaaccapture.cloudxr.oob_teleop_env") +progress_log = logging.getLogger("isaaccapture.cloudxr.oob_teleop_env.progress") WSS_PROXY_DEFAULT_PORT = 48322 @@ -565,15 +566,14 @@ def resolve_lan_host_for_oob() -> str: return h -def oob_progress(stage: str, msg: str) -> None: - """One-line progress update for ``--setup-oob`` / ``--usb-local`` steps. +def oob_progress(stage: str, msg: str, *, level: int = logging.INFO) -> None: + """Log OOB progress on its own filterable logger at the requested level. - Logged at INFO as ``[] ``; printed to stderr instead when - ``ISAACCAPTURE_LOGGING=off``, where no handler of ours would show it. + With logging off, retain operator messages on stderr but omit DEBUG detail. """ if logging_enabled(): - log.info("[%s] %s", stage, msg) - else: + progress_log.log(level, "[%s] %s", stage, msg) + elif level >= logging.INFO: print(f"\033[36m[{stage}]\033[0m {msg}", file=sys.stderr, flush=True) diff --git a/src/python/isaaccapture/cloudxr/oob_teleop_lifecycle.py b/src/python/isaaccapture/cloudxr/oob_teleop_lifecycle.py index 9f28b97002..5e433b8d7a 100644 --- a/src/python/isaaccapture/cloudxr/oob_teleop_lifecycle.py +++ b/src/python/isaaccapture/cloudxr/oob_teleop_lifecycle.py @@ -588,6 +588,7 @@ async def _close_teleop_tab(self) -> None: oob_progress( "usb-local" if self.usb_local else "setup-oob", f"closed {closed} teleop tab(s) on the headset; session ended", + level=logging.DEBUG, ) async def _shielded_cleanup(self) -> None: diff --git a/src/python/isaaccapture/cloudxr/oob_teleop_progress.py b/src/python/isaaccapture/cloudxr/oob_teleop_progress.py index 551bdea764..29d10a7873 100644 --- a/src/python/isaaccapture/cloudxr/oob_teleop_progress.py +++ b/src/python/isaaccapture/cloudxr/oob_teleop_progress.py @@ -5,8 +5,16 @@ from __future__ import annotations +import logging import time from collections.abc import Callable +from dataclasses import dataclass + + +@dataclass(frozen=True) +class OobProgressEvent: + level: int + message: str class OobProgressReporter: @@ -19,11 +27,10 @@ def __init__(self, clock: Callable[[], float] = time.monotonic) -> None: self._last_stage: tuple | None = None self._last_health: str | None = None self._last_wait: tuple | None = None - self._last_wait_at = float("-inf") self._last_delay_at: dict[str, float] = {} - def observe(self, snapshot: dict) -> list[str]: - """Return new messages; repeated waits get at most one reminder per minute.""" + def observe(self, snapshot: dict) -> list[OobProgressEvent]: + """Return leveled progress on meaningful state changes.""" if snapshot.get("health") == "starting": return [] @@ -39,69 +46,105 @@ def observe(self, snapshot: dict) -> list[str]: snapshot.get("generation"), ) entered = stage != self._last_stage + state_changed = self._last_stage is None or state != self._last_stage[0] now = self._clock() - messages: list[str] = [] + messages: list[OobProgressEvent] = [] + + def emit(level: int, message: str) -> None: + messages.append(OobProgressEvent(level, message)) if ready and not self._adb_ready: verb = "reconnected" if self._ever_adb_ready else "detected" - messages.append( - f"USB-attached HMD {verb} (serial {serial}); continuing OOB setup." + emit( + logging.INFO, + f"USB-attached HMD {verb} (serial {serial}); continuing OOB setup.", ) self._ever_adb_ready = True self._adb_ready = ready if state == "WAITING_FOR_ADB" and not ready: - wait = (serial, reason, snapshot.get("adbDiagnostic")) - if wait != self._last_wait or now - self._last_wait_at >= 60: - if snapshot.get("adbDiagnostic"): - messages.append(f"ADB diagnostic: {snapshot['adbDiagnostic']}") - elif serial is None and not any( - word in reason.lower() - for word in ("unauthorized", "offline", "multiple") - ): - messages.append( - "No USB-attached HMD detected; connect a headset to continue." - ) - else: - messages.append(f"Waiting for USB-attached HMD: {reason}") - self._last_wait_at = now + diagnostic = snapshot.get("adbDiagnostic") + lower_reason = reason.lower() + # ADB authorization needs operator action even when raw diagnostics exist. + if "unauthorized" in lower_reason: + wait = ("unauthorized", serial) + level = logging.WARNING + message = ( + "ADB authorization required: unlock the headset and accept " + "the USB debugging prompt." + ) + elif "offline" in lower_reason: + wait = ("offline", serial) + level = logging.INFO + message = f"Waiting for USB-attached HMD: {reason}" + elif "multiple" in lower_reason: + wait = ("multiple", serial) + level = logging.WARNING + message = f"Waiting for USB-attached HMD: {reason}" + elif diagnostic: + wait = ("adb_diagnostic", diagnostic) + level = logging.WARNING + message = f"ADB diagnostic: {diagnostic}" + elif serial is None: + wait = ("no_headset",) + level = logging.INFO + message = "No USB-attached HMD detected; connect a headset to continue." + else: + wait = ("selected_missing", serial) + level = logging.INFO + message = f"Waiting for USB-attached HMD: {reason}" + if wait != self._last_wait: + emit(level, message) self._last_wait = wait else: self._last_wait = None if entered: if state == "PREPARING_DEVICE": - messages.append( + emit( + logging.DEBUG, f"Waiting for headset transport: {reason}" if snapshot.get("networkPresent") is False - else f"Preparing headset {serial} for OOB setup." + else f"Preparing headset {serial} for OOB setup.", ) elif state == "REBUILDING_USB": - messages.append("Configuring USB reverse rules and TURN.") + emit(logging.DEBUG, "Configuring USB reverse rules and TURN.") elif state == "AUTOMATING_BROWSER": - messages.append( + emit( + logging.DEBUG, "USB reverse rules and TURN verified; opening headset browser." if reason == "TURN and reverse rules verified" - else "Opening headset browser and connecting OOB client." + else "Opening headset browser and connecting OOB client.", ) elif state == "VERIFYING_EXISTING_BROWSER": - messages.append("USB transport restored; checking existing browser.") + emit( + logging.DEBUG, "USB transport restored; checking existing browser." + ) elif state == "VERIFYING_BROWSER": - messages.append("Waiting for headset browser health report.") - elif state == "WAITING_FOR_AWAKE": - messages.append(f"Waiting for selected headset to wake: {reason}") - elif state == "USB_HEALTH_BLOCKED": - messages.append(f"USB health policy blocked browser launch: {reason}") + emit(logging.DEBUG, "Waiting for headset browser health report.") + elif state == "WAITING_FOR_AWAKE" and state_changed: + emit(logging.INFO, f"Waiting for selected headset to wake: {reason}") + elif state == "WAITING_FOR_NETWORK" and state_changed: + emit( + logging.WARNING, + "Headset network unavailable; connect it to Wi-Fi to continue.", + ) + elif state == "USB_HEALTH_BLOCKED" and state_changed: + emit( + logging.WARNING, + f"USB health policy blocked browser launch: {reason}", + ) elif state == "DEGRADED" or "Recovery episode expired" in reason: if now - self._last_delay_at.get(reason, float("-inf")) >= 30: - messages.append(f"OOB recovery delayed: {reason}") + emit(logging.WARNING, f"OOB recovery delayed: {reason}") self._last_delay_at[reason] = now if health == "browser_ready" and health != self._last_health: - messages.append( + emit( + logging.INFO, "OOB browser ready; waiting for fresh stream metrics." if snapshot.get("streaming") - else "OOB browser ready; waiting for OpenXR stream." + else "OOB browser ready; waiting for OpenXR stream.", ) self._last_stage = stage self._last_health = health diff --git a/src/python/isaaccapture/cloudxr/service/_service.py b/src/python/isaaccapture/cloudxr/service/_service.py index 82324f6ada..fa7b8f436f 100644 --- a/src/python/isaaccapture/cloudxr/service/_service.py +++ b/src/python/isaaccapture/cloudxr/service/_service.py @@ -177,6 +177,7 @@ def __init__( oob_progress( "usb-local" if usb_local else "setup-oob", "host preflight: checking web client assets", + level=logging.DEBUG, ) if self._usb_local or self._host_client: from ..oob_teleop_env import require_web_client_static_dir # noqa: PLC0415 @@ -238,12 +239,17 @@ def __init__( stage, f"recovery episode {self._recovery_config.timeout_sec:g}s, " f"retry/observe {self._recovery_config.interval_sec:g}s", + level=logging.DEBUG, ) oob_progress( - stage, "host preflight: checking adb and transport dependencies" + stage, + "host preflight: checking adb and transport dependencies", + level=logging.DEBUG, ) if not usb_local and os.getenv("TELEOP_OOB_HUB_ONLY"): - oob_progress(stage, "hub-only mode; skipping adb preflight") + oob_progress( + stage, "hub-only mode; skipping adb preflight", level=logging.DEBUG + ) if usb_local or not os.getenv("TELEOP_OOB_HUB_ONLY"): require_adb_on_path() if usb_local: @@ -252,7 +258,11 @@ def __init__( else: resolve_lan_host_for_oob() print_host_preflight_warnings(usb_local=usb_local, emit_console=False) - oob_progress(stage, "host preflight OK; starting CloudXR runtime") + oob_progress( + stage, + "host preflight OK; starting CloudXR runtime", + level=logging.DEBUG, + ) try: self._oob_status_path.unlink(missing_ok=True) except OSError as exc: @@ -469,8 +479,8 @@ async def _publish_oob_status(self, snapshot: dict) -> None: reporter = getattr(self, "_oob_progress_reporter", None) if reporter is not None: stage = "usb-local" if self._usb_local else "setup-oob" - for message in reporter.observe(payload): - oob_progress(stage, message) + for event in reporter.observe(payload): + oob_progress(stage, event.message, level=event.level) def oob_status(self) -> dict | None: """Return the latest lifecycle snapshot without touching the WSS event loop.""" diff --git a/src/python/isaaccapture/logging_config/_console.py b/src/python/isaaccapture/logging_config/_console.py index ebd5c61a9f..458db661d8 100644 --- a/src/python/isaaccapture/logging_config/_console.py +++ b/src/python/isaaccapture/logging_config/_console.py @@ -31,7 +31,7 @@ # Logger name to ANSI emphasis; a name's colour also covers its dotted descendants. _logger_colors: dict[str, str] = { - # cloudxr.oob_teleop_env contains [setup-oob] / [usb-local] progress. + # OOB progress is a child; color the parent and its descendants. "isaaccapture.cloudxr.oob_teleop_env": "\033[36m", } diff --git a/tests/python/core/cloudxr/test_oob_teleop_env.py b/tests/python/core/cloudxr/test_oob_teleop_env.py index f0bc246a8a..08fa37667f 100644 --- a/tests/python/core/cloudxr/test_oob_teleop_env.py +++ b/tests/python/core/cloudxr/test_oob_teleop_env.py @@ -615,12 +615,14 @@ def test_startup_banner_hides_control_and_turn_credentials( def test_oob_progress_logs_at_info( monkeypatch: pytest.MonkeyPatch, capsys, caplog ) -> None: - """With logging on, progress is an INFO record on the module logger, not a print.""" + """With logging on, progress uses the dedicated status logger, not a print.""" monkeypatch.delenv("ISAACCAPTURE_LOGGING", raising=False) - with caplog.at_level(logging.INFO, logger="isaaccapture.cloudxr.oob_teleop_env"): + with caplog.at_level( + logging.INFO, logger="isaaccapture.cloudxr.oob_teleop_env.progress" + ): oob_teleop_env_under_test.oob_progress("setup-oob", "teleop tab found") [record] = caplog.records - assert record.name == "isaaccapture.cloudxr.oob_teleop_env" + assert record.name == "isaaccapture.cloudxr.oob_teleop_env.progress" assert record.levelno == logging.INFO assert record.getMessage() == "[setup-oob] teleop tab found" assert capsys.readouterr().err == "" @@ -631,12 +633,35 @@ def test_oob_progress_prints_when_logging_is_off( ) -> None: """``ISAACCAPTURE_LOGGING=off`` keeps the cyan stderr line and logs nothing.""" monkeypatch.setenv("ISAACCAPTURE_LOGGING", "off") - with caplog.at_level(logging.INFO, logger="isaaccapture.cloudxr.oob_teleop_env"): + with caplog.at_level( + logging.INFO, logger="isaaccapture.cloudxr.oob_teleop_env.progress" + ): oob_teleop_env_under_test.oob_progress("setup-oob", "teleop tab found") assert capsys.readouterr().err == "\033[36m[setup-oob]\033[0m teleop tab found\n" assert not caplog.records +def test_oob_progress_debug_is_quiet_when_logging_is_off( + monkeypatch: pytest.MonkeyPatch, capsys, caplog +) -> None: + monkeypatch.delenv("ISAACCAPTURE_LOGGING", raising=False) + with caplog.at_level( + logging.DEBUG, logger="isaaccapture.cloudxr.oob_teleop_env.progress" + ): + oob_teleop_env_under_test.oob_progress( + "setup-oob", "browser launched", level=logging.DEBUG + ) + [record] = caplog.records + assert record.levelno == logging.DEBUG + assert record.getMessage() == "[setup-oob] browser launched" + + monkeypatch.setenv("ISAACCAPTURE_LOGGING", "off") + oob_teleop_env_under_test.oob_progress( + "setup-oob", "browser launched", level=logging.DEBUG + ) + assert capsys.readouterr().err == "" + + # Host preflight (H5) ------------------------------------------------------ diff --git a/tests/python/core/cloudxr/test_oob_teleop_progress.py b/tests/python/core/cloudxr/test_oob_teleop_progress.py index 4564fc4503..a52d5a2564 100644 --- a/tests/python/core/cloudxr/test_oob_teleop_progress.py +++ b/tests/python/core/cloudxr/test_oob_teleop_progress.py @@ -3,10 +3,15 @@ """Operator progress delivered by the shared OOB service.""" -from isaaccapture.cloudxr.oob_teleop_progress import OobProgressReporter +import logging +from isaaccapture.cloudxr.oob_teleop_progress import ( + OobProgressEvent, + OobProgressReporter, +) -def test_absent_headset_wait_is_visible_and_rate_limited(): + +def test_absent_headset_wait_is_visible_once(): now = [0.0] reporter = OobProgressReporter(clock=lambda: now[0]) waiting = { @@ -17,17 +22,16 @@ def test_absent_headset_wait_is_visible_and_rate_limited(): } assert reporter.observe({**waiting, "health": "starting"}) == [] assert reporter.observe(waiting) == [ - "No USB-attached HMD detected; connect a headset to continue." + OobProgressEvent( + logging.INFO, "No USB-attached HMD detected; connect a headset to continue." + ) ] - now[0] = 5 - assert reporter.observe(waiting) == [] now[0] = 61 - assert reporter.observe(waiting) == [ - "No USB-attached HMD detected; connect a headset to continue." - ] + assert reporter.observe(waiting) == [] + assert reporter.observe({**waiting, "generation": 2}) == [] -def test_selected_headset_and_adb_diagnostics_are_actionable(): +def test_adb_authorization_overrides_diagnostic_and_remains_visible(): reporter = OobProgressReporter(clock=lambda: 0) waiting = { "health": "degraded", @@ -37,19 +41,41 @@ def test_selected_headset_and_adb_diagnostics_are_actionable(): "adbReady": False, } assert reporter.observe(waiting) == [ - "Waiting for USB-attached HMD: Selected headset HMD-1 offline; reconnect USB" + OobProgressEvent( + logging.INFO, + "Waiting for USB-attached HMD: Selected headset HMD-1 offline; reconnect USB", + ) ] - diagnostic = { + unauthorized = { **waiting, - "reason": "adb: failed to connect to daemon at tcp:5037", - "adbDiagnostic": "adb: failed to connect to daemon at tcp:5037", + "reason": "Selected headset unauthorized; accept the USB debugging prompt", + "adbDiagnostic": "adb transport unavailable", } - assert reporter.observe(diagnostic) == [ - "ADB diagnostic: adb: failed to connect to daemon at tcp:5037" + assert reporter.observe(unauthorized) == [ + OobProgressEvent( + logging.WARNING, + "ADB authorization required: unlock the headset and accept " + "the USB debugging prompt.", + ) + ] + assert ( + reporter.observe({**unauthorized, "adbDiagnostic": "another adb detail"}) == [] + ) + assert reporter.observe( + { + **waiting, + "reason": "adb: failed to connect to daemon at tcp:5037", + "adbDiagnostic": "adb: failed to connect to daemon at tcp:5037", + } + ) == [ + OobProgressEvent( + logging.WARNING, + "ADB diagnostic: adb: failed to connect to daemon at tcp:5037", + ) ] -def test_replug_reports_reentered_phases_without_steady_state_spam(): +def test_replug_reports_status_and_debug_phases_without_steady_state_spam(): reporter = OobProgressReporter(clock=lambda: 0) base = { "health": "degraded", @@ -63,8 +89,11 @@ def test_replug_reports_reentered_phases_without_steady_state_spam(): ("VERIFYING_BROWSER", "Waiting for headset browser"), ) for state, expected in phases: - messages = reporter.observe({**base, "state": state}) - assert any(expected in message for message in messages) + events = reporter.observe({**base, "state": state}) + assert any( + expected in event.message and event.level == logging.DEBUG + for event in events + ) assert reporter.observe({**base, "state": state}) == [] lost = { @@ -73,15 +102,18 @@ def test_replug_reports_reentered_phases_without_steady_state_spam(): "reason": "Selected headset disconnected", "adbReady": False, } - assert any("Waiting for USB-attached HMD" in m for m in reporter.observe(lost)) - for state, expected in phases: - messages = reporter.observe({**base, "state": state}) - assert any(expected in message for message in messages) - if state == "PREPARING_DEVICE": - assert any("HMD reconnected" in message for message in messages) + assert any( + "Waiting for USB-attached HMD" in event.message + for event in reporter.observe(lost) + ) + events = reporter.observe({**base, "state": "PREPARING_DEVICE"}) + assert any( + "HMD reconnected" in event.message and event.level == logging.INFO + for event in events + ) -def test_new_episode_reannounces_same_phase(): +def test_new_episode_reannounces_debug_phase_only(): reporter = OobProgressReporter(clock=lambda: 0) phase = { "health": "degraded", @@ -89,22 +121,75 @@ def test_new_episode_reannounces_same_phase(): "reason": "Configuring USB reverse rules", "episodeStartedAt": 10, } - assert reporter.observe(phase) == ["Configuring USB reverse rules and TURN."] + expected = OobProgressEvent( + logging.DEBUG, "Configuring USB reverse rules and TURN." + ) + assert reporter.observe(phase) == [expected] assert reporter.observe(phase) == [] - assert reporter.observe({**phase, "episodeStartedAt": 20}) == [ - "Configuring USB reverse rules and TURN." + assert reporter.observe({**phase, "episodeStartedAt": 20}) == [expected] + + +def test_normal_startup_keeps_info_progress_sparse(): + reporter = OobProgressReporter(clock=lambda: 0) + base = { + "health": "degraded", + "selectedSerial": "HMD-1", + "adbReady": True, + } + events = [] + for state in ( + "PREPARING_DEVICE", + "REBUILDING_USB", + "AUTOMATING_BROWSER", + "VERIFYING_BROWSER", + ): + events.extend(reporter.observe({**base, "state": state})) + events.extend( + reporter.observe( + {**base, "state": "VERIFYING_BROWSER", "health": "browser_ready"} + ) + ) + assert [event.message for event in events if event.level >= logging.INFO] == [ + "USB-attached HMD detected (serial HMD-1); continuing OOB setup.", + "OOB browser ready; waiting for OpenXR stream.", ] def test_browser_ready_is_not_claimed_to_be_streaming(): reporter = OobProgressReporter(clock=lambda: 0) base = {"selectedSerial": "HMD-1", "adbReady": True, "state": "ACTIVE"} - messages = reporter.observe({**base, "health": "browser_ready"}) - assert "OOB browser ready; waiting for OpenXR stream." in messages + events = reporter.observe({**base, "health": "browser_ready"}) + assert ( + OobProgressEvent(logging.INFO, "OOB browser ready; waiting for OpenXR stream.") + in events + ) assert reporter.observe({**base, "health": "browser_ready"}) == [] assert reporter.observe({**base, "health": "active"}) == [] +def test_network_and_health_blocks_are_operator_visible_once_per_entry(): + reporter = OobProgressReporter(clock=lambda: 0) + network = { + "health": "degraded", + "state": "WAITING_FOR_NETWORK", + "reason": "No non-loopback network", + } + assert reporter.observe(network) == [ + OobProgressEvent( + logging.WARNING, + "Headset network unavailable; connect it to Wi-Fi to continue.", + ) + ] + assert reporter.observe({**network, "reason": "Still no network"}) == [] + blocked = {**network, "state": "USB_HEALTH_BLOCKED", "reason": "USB too slow"} + assert reporter.observe(blocked) == [ + OobProgressEvent( + logging.WARNING, "USB health policy blocked browser launch: USB too slow" + ) + ] + assert reporter.observe({**blocked, "reason": "USB still too slow"}) == [] + + def test_recovery_delay_is_rate_limited(): now = [0.0] reporter = OobProgressReporter(clock=lambda: now[0]) @@ -113,11 +198,10 @@ def test_recovery_delay_is_rate_limited(): "state": "DEGRADED", "reason": "coturn is not listening", } - assert reporter.observe(delayed) == [ - "OOB recovery delayed: coturn is not listening" - ] + expected = OobProgressEvent( + logging.WARNING, "OOB recovery delayed: coturn is not listening" + ) + assert reporter.observe(delayed) == [expected] assert reporter.observe(delayed) == [] now[0] = 31 - assert reporter.observe({**delayed, "generation": 2}) == [ - "OOB recovery delayed: coturn is not listening" - ] + assert reporter.observe({**delayed, "generation": 2}) == [expected] diff --git a/tests/python/core/cloudxr/test_service_oob_status.py b/tests/python/core/cloudxr/test_service_oob_status.py index a68a981015..858d782f43 100644 --- a/tests/python/core/cloudxr/test_service_oob_status.py +++ b/tests/python/core/cloudxr/test_service_oob_status.py @@ -6,6 +6,7 @@ from __future__ import annotations import json +import logging import os import threading import asyncio @@ -54,7 +55,32 @@ async def test_status_progress_reaches_embedded_owner_once(tmp_path): await service._publish_oob_status(waiting) await service._publish_oob_status(waiting) progress.assert_called_once_with( - "usb-local", "No USB-attached HMD detected; connect a headset to continue." + "usb-local", + "No USB-attached HMD detected; connect a headset to continue.", + level=logging.INFO, + ) + + +@pytest.mark.asyncio +async def test_adb_authorization_reaches_embedded_owner_as_warning(tmp_path): + service = _service_for_status(tmp_path) + service._usb_local = True + service._oob_progress_reporter = OobProgressReporter(clock=lambda: 0) + unauthorized = { + "health": "degraded", + "state": "WAITING_FOR_ADB", + "reason": "Selected headset unauthorized; accept the USB debugging prompt", + "selectedSerial": "HMD-1", + "adbDiagnostic": "adb detail", + "adbReady": False, + } + with patch("isaaccapture.cloudxr.service._service.oob_progress") as progress: + await service._publish_oob_status(unauthorized) + progress.assert_called_once_with( + "usb-local", + "ADB authorization required: unlock the headset and accept " + "the USB debugging prompt.", + level=logging.WARNING, ) diff --git a/tests/python/core/logging_config/test_console.py b/tests/python/core/logging_config/test_console.py index c84d2ed8c3..370ec70471 100644 --- a/tests/python/core/logging_config/test_console.py +++ b/tests/python/core/logging_config/test_console.py @@ -60,6 +60,17 @@ def test_keeps_the_names_and_their_descendants(self): assert not handler.filter(record(name="isaaccapture.plugins.manusx")) assert not handler.filter(record(name="isaaccapture.plugins")) + def test_oob_progress_keeps_parent_filter_compatibility(self): + handler = _console.ensure_handler() + parent = "isaaccapture.cloudxr.oob_teleop_env" + progress = parent + ".progress" + logging_config.set_console_logger_name_filter({parent}) + assert handler.filter(record(name=progress)) + + logging_config.set_console_logger_name_filter({progress}) + assert handler.filter(record(name=progress)) + assert not handler.filter(record(name=parent)) + def test_a_name_left_out_of_the_next_set_no_longer_passes(self): handler = _console.ensure_handler() logging_config.set_console_logger_name_filter({"isaaccapture.plugins.manus"}) @@ -223,7 +234,7 @@ def test_a_change_reaches_names_already_looked_up(self): assert "isaaccapture.core.Probe" not in _console._logger_colors def test_oob_progress_logger_is_cyan_by_default(self): - name = "isaaccapture.cloudxr.oob_teleop_env" + name = "isaaccapture.cloudxr.oob_teleop_env.progress" assert f"[\033[36m{name}{_RESET}]" in render(_Tty(), name=name) def test_the_last_segment_keeps_the_full_names_colour(self):