Fixed issues with telemetry.
This commit is contained in:
198
ptlinux/cli.py
198
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,
|
||||
|
||||
Reference in New Issue
Block a user