diff --git a/ptlinux/cli.py b/ptlinux/cli.py index e353ab5..c265f96 100644 --- a/ptlinux/cli.py +++ b/ptlinux/cli.py @@ -9,7 +9,9 @@ from datetime import datetime import json from pathlib import Path import re +import signal import sys +import threading import time from typing import Callable, Sequence @@ -1379,6 +1381,8 @@ def _play_locked( ) game_started_ns = time.time_ns() game_started_at = time.monotonic() + launch_success_lock = threading.Lock() + launch_success_reported = False if telemetry is not None and not dry_run: telemetry.send_event( "game_launch_started", @@ -1399,6 +1403,36 @@ def _play_locked( if depot_file_catalog is not None else None ) + + def observe_game_output(line: str) -> str: + """Timestamp launch success when the supervisor first confirms readiness.""" + + nonlocal launch_success_reported + live_readiness_signal = _game_readiness_signal(line) + if telemetry is None or dry_run or live_readiness_signal is None: + return line + with launch_success_lock: + if launch_success_reported: + return line + ready_at = time.monotonic() + launch_success_reported = telemetry.send_event( + "game_launch_success", + metadata={ + "launch_duration_ms": round( + (ready_at - launch_requested_at) * 1000 + ), + "game_start_duration_ms": round( + (ready_at - game_started_at) * 1000 + ), + "game_window_ready": True, + "readiness_signal": live_readiness_signal, + "runtime": selection.kind, + "realm": start_option.name, + }, + context={"operation": "launch_game", "stage": "ready"}, + ) + return line + try: outcome = run_game( paths, @@ -1409,6 +1443,7 @@ def _play_locked( use_gamebox=not no_box, concurrent_prefix_launch=reuse_prepared, check=False, + output_line_filter=observe_game_output, pass_fds=game_lease_fds, ) except KeyboardInterrupt: @@ -1449,6 +1484,7 @@ def _play_locked( game_started_ns, ) runtime_issues = _runtime_issue_summary(outcome.stderr) + game_window_ready = runtime_issues["game_window_ready"] is True if ( selection.kind == "proton7-container" and runtime_issues["host_futex_fatal_count"] @@ -1458,8 +1494,13 @@ def _play_locked( runtime_issues["recommended_one_variable_comparison"] = "proton7-container" elif runtime_issues["dbghelp_symdeferred_assertion_count"]: runtime_issues["recommended_one_variable_comparison"] = "umu" + clean_exit = outcome.returncode == 0 and current_game_crash is None + launch_succeeded = ( + clean_exit or game_window_ready or current_game_log is not None + ) report = { - "ok": outcome.returncode == 0 and current_game_crash is None, + "ok": clean_exit, + "launch_succeeded": launch_succeeded, "dry_run": dry_run, "runtime": asdict(selection), "umu_bootstrap": asdict(umu_bootstrap) if umu_bootstrap else None, @@ -1481,22 +1522,40 @@ def _play_locked( "runtime_issues": runtime_issues, } game_runtime_seconds = max(0.0, time.monotonic() - game_started_at) - clean_exit = outcome.returncode == 0 and current_game_crash is None if telemetry is not None and not dry_run: - common_game_metadata = { + common_game_metadata: dict[str, object] = { "runtime_seconds": round(game_runtime_seconds), - "exit_code": outcome.returncode, "clean_exit": clean_exit, + "timed_out": outcome.timed_out, + "launch_succeeded": launch_succeeded, + "game_window_ready": game_window_ready, + "crash_dump": current_game_crash is not None, "session_duration_class": _session_duration_class(game_runtime_seconds), "runtime": selection.kind, "realm": start_option.name, + **_game_exit_metadata(outcome.returncode, selection.kind), } - if clean_exit: - telemetry.send_event( - "game_launch_success", - metadata=common_game_metadata, - context={"operation": "launch_game", "stage": "completed"}, - ) + if launch_succeeded: + if not launch_success_reported: + readiness_signal = _game_readiness_signal(outcome.stderr) + if readiness_signal is None: + readiness_signal = ( + "game_log" + if current_game_log is not None + else "clean_process_exit" + ) + telemetry.send_event( + "game_launch_success", + metadata={ + "detection_duration_ms": round(game_runtime_seconds * 1000), + "detected_after_exit": True, + "game_window_ready": game_window_ready, + "readiness_signal": readiness_signal, + "runtime": selection.kind, + "realm": start_option.name, + }, + context={"operation": "launch_game", "stage": "post_exit"}, + ) else: telemetry.send_event( "game_launch_failed", @@ -1504,17 +1563,57 @@ def _play_locked( message=( "Game client wrote a crash dump" if current_game_crash is not None + else "Game session timed out" + if outcome.timed_out else f"Game client exited with status {outcome.returncode}" ), - metadata={**common_game_metadata, "runtime_issues": runtime_issues}, - context={"operation": "launch_game", "stage": "running"}, + metadata={ + **common_game_metadata, + "runtime_issues": runtime_issues, + "stdout": outcome.stdout, + "stderr": outcome.stderr, + }, + context={"operation": "launch_game", "stage": "game_start"}, + ) + if launch_succeeded: + exit_message = None + if current_game_crash is not None: + exit_message = "Game client wrote a crash dump" + elif outcome.timed_out: + exit_message = "Game session timed out" + elif common_game_metadata.get("signal_inferred") is True: + exit_message = ( + "Game session ended with status " + f"{common_game_metadata['raw_exit_code']}, consistent with " + f"{common_game_metadata['signal_name']} wrapped by UMU" + ) + elif "signal" in common_game_metadata: + exit_message = ( + "Game session was terminated by " + f"{common_game_metadata['signal_name']}" + ) + elif outcome.returncode not in {0, None}: + exit_message = f"Game session ended with status {outcome.returncode}" + telemetry.send_event( + "game_exited", + severity=( + "error" + if current_game_crash is not None + else "info" if clean_exit else "warning" + ), + message=exit_message, + metadata=( + common_game_metadata + if clean_exit + else { + **common_game_metadata, + "runtime_issues": runtime_issues, + "stdout": outcome.stdout, + "stderr": outcome.stderr, + } + ), + context={"operation": "launch_game", "stage": "exited"}, ) - telemetry.send_event( - "game_exited", - severity="info" if clean_exit else "warning", - metadata=common_game_metadata, - context={"operation": "launch_game", "stage": "exited"}, - ) if as_json or dry_run: _emit(report, as_json) else: @@ -1535,6 +1634,49 @@ def _session_duration_class(duration_seconds: float) -> str: return "normal" +def _game_exit_metadata( + returncode: int | None, + runtime_kind: str, +) -> dict[str, object]: + metadata: dict[str, object] = {"exit_code": returncode} + if returncode is None: + return metadata + if returncode < 0: + signal_number = -returncode + metadata.update( + { + "exit_code": 128 + min(signal_number, 127), + "raw_exit_code": returncode, + "signal": signal_number, + "signal_name": _signal_name(signal_number), + } + ) + return metadata + + # UMU returns Popen's negative child status from a Python main function. + # SystemExit encodes -SIGKILL as 247 before our Python gamebox sees it. + wrapped_sigkill = 256 - int(signal.SIGKILL) + if runtime_kind in {"umu", "proton7-container"} and returncode == wrapped_sigkill: + metadata.update( + { + "exit_code": 128 + int(signal.SIGKILL), + "raw_exit_code": returncode, + "signal": int(signal.SIGKILL), + "signal_name": signal.SIGKILL.name, + "signal_inferred": True, + "signal_inference": "umu_python_system_exit", + } + ) + return metadata + + +def _signal_name(signal_number: int) -> str: + try: + return signal.Signals(signal_number).name + except ValueError: + return f"signal {signal_number}" + + def _ensure_portable_umu_for_play( paths: AppPaths, settings: Settings, @@ -1684,6 +1826,7 @@ def _runtime_issue_summary(stderr: str) -> dict[str, object]: } ) return { + "game_window_ready": _game_window_was_ready(folded), "host_futex_fatal_count": folded.count(futex_message), "gstreamer_wrong_elf_class_count": folded.count(wrong_elf_message), "gstreamer_missing_library_count": len(missing_libraries), @@ -1696,6 +1839,25 @@ def _runtime_issue_summary(stderr: str) -> dict[str, object]: } +def _game_window_was_ready(stderr: str) -> bool: + return _game_readiness_signal(stderr) is not None + + +def _game_readiness_signal(output: str) -> str | None: + folded = output.casefold() + for signal_name, marker in ( + ("window_ready", "game window ready:"), + ("rendered_frame", "rendered game frame:"), + ( + "window_supervision", + "game window resizing is disabled to prevent repeated direct3d device resets", + ), + ): + if marker in folded: + return signal_name + return None + + def _print_game_outcome( outcome: CommandOutcome, current_game_log: dict[str, object] | None, diff --git a/ptlinux/command.py b/ptlinux/command.py index 20c9d6b..acf5874 100644 --- a/ptlinux/command.py +++ b/ptlinux/command.py @@ -110,6 +110,7 @@ class CommandRunner: output_line_filter: OutputLineFilter | None = None, pass_fds: Sequence[int] = (), telemetry_stage: str | None = None, + report_failure_telemetry: bool = True, ) -> CommandOutcome: arguments = [str(value) for value in argv] if not arguments: @@ -179,7 +180,9 @@ class CommandRunner: dry_run=False, ) self._record(outcome, cwd, overrides) - if outcome.timed_out or outcome.returncode != 0: + if report_failure_telemetry and ( + outcome.timed_out or outcome.returncode != 0 + ): telemetry = current_telemetry() if telemetry is not None: telemetry.report_subprocess_failure( diff --git a/ptlinux/telemetry.py b/ptlinux/telemetry.py index 50a428c..df3eb93 100644 --- a/ptlinux/telemetry.py +++ b/ptlinux/telemetry.py @@ -34,6 +34,8 @@ DEFAULT_TELEMETRY_ENDPOINT = "https://pristontale.eu/api/launcher/telemetry" TELEMETRY_ENDPOINT_VARIABLE = "PTLINUX_TELEMETRY_ENDPOINT" TELEMETRY_KEY_VARIABLE = "PTLINUX_TELEMETRY_KEY" TELEMETRY_DEBUG_VARIABLE = "PTLINUX_TELEMETRY_DEBUG" +TELEMETRY_PROCESS_ROLE_VARIABLE = "PTLINUX_TELEMETRY_PROCESS_ROLE" +TELEMETRY_OPERATION_PROCESS_ROLE = "operation" MAX_REQUEST_BYTES = 64 * 1024 MAX_MESSAGE_BYTES = 10 * 1024 @@ -263,9 +265,14 @@ class TelemetryService: self._session_metadata = dict(session_metadata or {}) self._monotonic = monotonic self._started_at = monotonic() + self._reports_launcher_lifecycle = ( + self._environment.get(TELEMETRY_PROCESS_ROLE_VARIABLE, "").strip().casefold() + != TELEMETRY_OPERATION_PROCESS_ROLE + ) self._enabled = bool(enabled) self._active = False self._accepting = False + self._closing = False self._ready = False self._first_run = False self._installation_id: str | None = None @@ -322,6 +329,7 @@ class TelemetryService: self._base_payload = self._collect_common_payload(first_seen) self._stop.clear() self._accepting = True + self._closing = False self._active = True worker = threading.Thread( target=self._worker_loop, @@ -338,15 +346,16 @@ class TelemetryService: self._debug_log(f"initialization failed: {type(exc).__name__}") return - self.send_event( - "launcher_started", - metadata={"cold_start": True, **self._session_metadata}, - ) - if self._first_run: + if self._reports_launcher_lifecycle: self.send_event( - "first_run_started", - metadata={"install_type": self._install_type()}, + "launcher_started", + metadata={"cold_start": True, **self._session_metadata}, ) + if self._first_run: + self.send_event( + "first_run_started", + metadata={"install_type": self._install_type()}, + ) self._start_environment_collection() def set_enabled(self, enabled: bool) -> None: @@ -368,6 +377,8 @@ class TelemetryService: if self._ready or not self._active: return self._ready = True + if not self._reports_launcher_lifecycle: + return duration_ms = round((self._monotonic() - self._started_at) * 1000) self.send_event( "launcher_ready", @@ -674,11 +685,12 @@ class TelemetryService: self._send_repeated_error(state) def shutdown(self, timeout_seconds: float = SHUTDOWN_WAIT_SECONDS) -> None: - """Queue the closing event and give the daemon worker a bounded flush.""" + """Finish this process role and give the daemon worker a bounded flush.""" with self._state_lock: - if not self._active: + if not self._active or self._closing: return + self._closing = True deadline = time.monotonic() + max(0.0, timeout_seconds) environment_worker = self._environment_worker if isinstance(environment_worker, threading.Thread) and ( @@ -692,17 +704,18 @@ class TelemetryService: ) self._flush_repeated_errors() runtime_seconds = max(0, round(self._monotonic() - self._started_at)) - if self._first_run and not self._ready: + if self._reports_launcher_lifecycle: + if self._first_run and not self._ready: + self.send_event( + "first_run_failed", + severity="error", + message="Launcher did not reach the ready state", + metadata={"duration_ms": runtime_seconds * 1000}, + ) self.send_event( - "first_run_failed", - severity="error", - message="Launcher did not reach the ready state", - metadata={"duration_ms": runtime_seconds * 1000}, + "launcher_closed", + metadata={"runtime_seconds": runtime_seconds, **self._session_metadata}, ) - self.send_event( - "launcher_closed", - metadata={"runtime_seconds": runtime_seconds, **self._session_metadata}, - ) with self._state_lock: self._accepting = False self._stop.set() @@ -719,6 +732,7 @@ class TelemetryService: with self._state_lock: self._enabled = False self._accepting = False + self._closing = True self._stop.set() self._repeated_errors.clear() while True: @@ -795,6 +809,11 @@ class TelemetryService: self._base_payload[key] = {**existing, **value} else: self._base_payload[key] = value + if not self._reports_launcher_lifecycle: + # Dashboard operation subprocesses enrich their own events with the + # detected environment, while the dashboard remains the sole source + # of launcher lifecycle and automatic compatibility events. + return runtime = sanitized.get("runtime") dependencies = sanitized.get("dependencies") @@ -816,14 +835,38 @@ class TelemetryService: context={"operation": "launcher", "stage": "environment_detection"}, ) missing_required = dependency_details.get("missing_required") - if dependency_details.get("healthy") is False: + generic_dependency_failures = ( + [ + str(value) + for value in missing_required + if isinstance(value, str) and value + ] + if isinstance(missing_required, list) + else [] + ) + if ( + dependency_details.get("container_ready") is False + and "container_host" not in generic_dependency_failures + ): + generic_dependency_failures.append("container_host") + if ( + dependency_details.get("healthy") is False + and generic_dependency_failures + ): self.send_event( "dependency_check_failed", severity="warning", message="One or more launcher dependencies are unavailable", metadata={ - "dependencies": ( - missing_required if isinstance(missing_required, list) else [] + "dependencies": generic_dependency_failures, + "required_shared_libraries_present": dependency_details.get( + "required_shared_libraries_present" + ), + "vulkan_64bit_available": dependency_details.get( + "vulkan_64bit_available" + ), + "vulkan_32bit_available": dependency_details.get( + "vulkan_32bit_available" ), }, context={"operation": "launcher", "stage": "dependency_check"}, @@ -846,7 +889,17 @@ class TelemetryService: self.send_event( "vulkan_32bit_check_failed", severity="warning", - metadata={"dependency": "vulkan_32bit", "check": "32bit_vulkan"}, + metadata={ + "dependency": "vulkan_32bit", + "check": "32bit_vulkan", + "loader_available": runtime_details.get( + "vulkan_32bit_loader_available" + ), + "icd_available": runtime_details.get( + "vulkan_32bit_icd_available" + ), + "detection": runtime_details.get("vulkan_32bit_detection"), + }, context={"operation": "launcher", "stage": "vulkan_check"}, ) diff --git a/ptlinux/telemetry_environment.py b/ptlinux/telemetry_environment.py index c4b3076..b266ac0 100644 --- a/ptlinux/telemetry_environment.py +++ b/ptlinux/telemetry_environment.py @@ -29,8 +29,11 @@ _VULKAN_MANIFEST_DIRECTORIES = ( ) _LIBRARY_ROOTS = ( Path("/lib"), + Path("/lib32"), Path("/usr/lib"), + Path("/usr/lib32"), Path("/usr/local/lib"), + Path("/usr/local/lib32"), ) _PCI_DATABASES = ( Path("/usr/share/hwdata/pci.ids"), @@ -198,13 +201,12 @@ def _vulkan_info( if api_version and _VERSION_PATTERN.fullmatch(api_version): api_versions.append(api_version) library = _short_string(icd.get("library_path")) - architecture = _manifest_library_architecture( + architectures = _manifest_library_architectures( manifest, library, library_roots, ) - if architecture is not None: - manifest_architectures.add(architecture) + manifest_architectures.update(architectures) vulkaninfo = shutil.which("vulkaninfo", path=environment.get("PATH", "")) probe = ( @@ -240,6 +242,11 @@ def _vulkan_info( "vulkan_available": available_64bit, "vulkan_64bit": available_64bit, "vulkan_32bit": available_32bit, + "vulkan_64bit_loader_available": 64 in loader_architectures, + "vulkan_64bit_icd_available": 64 in manifest_architectures, + "vulkan_64bit_probe_succeeded": functional_64bit, + "vulkan_32bit_loader_available": 32 in loader_architectures, + "vulkan_32bit_icd_available": 32 in manifest_architectures, "vulkan_64bit_detection": ( "vulkaninfo" if functional_64bit else "loader_and_icd" ), @@ -860,17 +867,18 @@ def _vulkan_loader_architectures(library_roots: Sequence[Path]) -> set[int]: return architectures -def _manifest_library_architecture( +def _manifest_library_architectures( manifest: Path, library: str | None, library_roots: Sequence[Path], -) -> int | None: +) -> set[int]: + architectures: set[int] = set() if library: path = Path(library) if path.is_absolute(): architecture = _elf_architecture(path) if architecture is not None: - return architecture + architectures.add(architecture) else: candidates = [manifest.parent / path] for root in library_roots: @@ -878,13 +886,15 @@ def _manifest_library_architecture( for candidate in candidates: architecture = _elf_architecture(candidate) if architecture is not None: - return architecture + architectures.add(architecture) + if architectures: + return architectures lowered = manifest.name.casefold() if any(token in lowered for token in ("i386", "i486", "i586", "i686", "x86_32")): - return 32 + return {32} if any(token in lowered for token in ("x86_64", "amd64")): - return 64 - return None + return {64} + return set() def _library_candidates(root: Path, prefix: str) -> tuple[Path, ...]: diff --git a/ptlinux/ui/__init__.py b/ptlinux/ui/__init__.py index e410f0d..007ec99 100644 --- a/ptlinux/ui/__init__.py +++ b/ptlinux/ui/__init__.py @@ -36,6 +36,7 @@ from .viewmodels.dashboard import ( game_client_activity_text, interrupt_game_supervisor, launcher_child_command, + launcher_child_environment, launcher_restart_spec, launcher_update_presentation, news_card_columns, @@ -131,6 +132,7 @@ __all__ = [ "interrupt_game_supervisor", "launch_external_url", "launcher_child_command", + "launcher_child_environment", "launcher_restart_spec", "launcher_update_presentation", "news_card_columns", diff --git a/ptlinux/ui/dashboard.py b/ptlinux/ui/dashboard.py index 5bf5365..891372a 100644 --- a/ptlinux/ui/dashboard.py +++ b/ptlinux/ui/dashboard.py @@ -123,6 +123,7 @@ from .viewmodels.dashboard import ( game_client_activity_text, interrupt_game_supervisor, launcher_child_command, + launcher_child_environment, launcher_restart_spec, launcher_update_presentation, news_card_columns, @@ -1064,7 +1065,8 @@ def run_dashboard(paths: AppPaths) -> None: stdout=subprocess.PIPE, stderr=subprocess.STDOUT, bufsize=1, - ) + env=launcher_child_environment(), + ) except OSError as process_error: publish_output(f"Could not start operation: {process_error}\n") if game_client_id is None: diff --git a/ptlinux/ui/viewmodels/dashboard.py b/ptlinux/ui/viewmodels/dashboard.py index f02f749..fcfe2b9 100644 --- a/ptlinux/ui/viewmodels/dashboard.py +++ b/ptlinux/ui/viewmodels/dashboard.py @@ -14,6 +14,10 @@ from typing import TYPE_CHECKING, Callable, Mapping from ...paths import AppPaths from ...self_update import LauncherUpdateCheck +from ...telemetry import ( + TELEMETRY_OPERATION_PROCESS_ROLE, + TELEMETRY_PROCESS_ROLE_VARIABLE, +) if TYPE_CHECKING: @@ -465,6 +469,18 @@ def launcher_child_command(*arguments: str) -> list[str]: return [sys.executable, "-B", "-m", "ptlinux", *arguments] +def launcher_child_environment( + environment: Mapping[str, str] | None = None, +) -> dict[str, str]: + """Mark an internal CLI process as part of the current dashboard session.""" + + child_environment = dict(os.environ if environment is None else environment) + child_environment[TELEMETRY_PROCESS_ROLE_VARIABLE] = ( + TELEMETRY_OPERATION_PROCESS_ROLE + ) + return child_environment + + def dashboard_poll_interval( *, operation_active: bool,