Added telemetry system to get information about issues.

ptlinux/depot.py

@@ -25,6 +25,7 @@ from uuid import uuid4
 
 from . import __version__
 from .paths import AppPaths
+from .telemetry import classify_network_failure, current_telemetry
 
 
 CDN_CONFIGURATION_URL = "https://cdn-main.chatplex.io/pristontale-eu/cdn_configuration.json"
@@ -93,9 +94,16 @@ class DepotError(RuntimeError):
 class _RetryableDownloadError(DepotError):
 	"""One transient network or content-integrity failure."""
 
-	def __init__(self, message: str, *, discard_partial: bool = False) -> None:
+	def __init__(
+		self,
+		message: str,
+		*,
+		discard_partial: bool = False,
+		http_status: int | None = None,
+	) -> None:
 		super().__init__(message)
 		self.discard_partial = discard_partial
+		self.http_status = http_status
 
 
 @dataclass(frozen=True)
@@ -162,6 +170,8 @@ class DownloadTelemetry:
 	bytes_written: int = 0
 	write_seconds: float = 0.0
 	reason: str | None = None
+	http_status: int | None = None
+	resumed_bytes: int = 0
 
 
 DownloadObserver = Callable[[DownloadTelemetry], None]
@@ -827,6 +837,30 @@ class DepotSyncResult:
 	completed_at: str
 	files_planned: int = 0
 	bytes_planned: int = 0
+	manifest_duration_ms: int = 0
+	scan_duration_ms: int = 0
+	download_duration_ms: int = 0
+	apply_duration_ms: int = 0
+	update_duration_ms: int = 0
+	network_bytes_downloaded: int = 0
+	download_retry_count: int = 0
+	download_resume_used: bool = False
+	download_average_mbps: float | None = None
+	mirror_id: str | None = None
+
+
+@dataclass(frozen=True)
+class DepotDownloadMetrics:
+	"""Aggregate network measurements for one depot download phase."""
+
+	duration_ms: int = 0
+	transferred_bytes: int = 0
+	retry_count: int = 0
+	resume_used: bool = False
+	resumed_bytes: int = 0
+	average_mbps: float | None = None
+	mirror_id: str | None = None
+	http_status: int | None = None
 
 
 @dataclass(frozen=True)
@@ -959,6 +993,7 @@ class DepotClient:
 						server=attempt_server,
 						attempt=attempt_index + 1,
 						reason=str(exc),
+						http_status=exc.http_status,
 					)
 				)
 				if exc.discard_partial:
@@ -1012,6 +1047,15 @@ class DepotClient:
 				digest = hashlib.sha1(usedforsecurity=False)
 			elif written == file.size:
 				if digest.hexdigest().casefold() == file.sha1.casefold():
+					self._notify_download(
+						DownloadTelemetry(
+							kind="resume",
+							file=file.path,
+							server=server,
+							attempt=attempt,
+							resumed_bytes=written,
+						)
+					)
 					temporary.replace(destination)
 					if progress is not None:
 						progress(written)
@@ -1020,6 +1064,15 @@ class DepotClient:
 				written = 0
 				digest = hashlib.sha1(usedforsecurity=False)
 			elif written and _recover_crlf_manifest_file(temporary, destination, file):
+				self._notify_download(
+					DownloadTelemetry(
+						kind="resume",
+						file=file.path,
+						server=server,
+						attempt=attempt,
+						resumed_bytes=written,
+					)
+				)
 				temporary.unlink(missing_ok=True)
 				if progress is not None:
 					progress(file.size)
@@ -1028,6 +1081,16 @@ class DepotClient:
 			progress(written)
 
 		requested_offset = written
+		if requested_offset:
+			self._notify_download(
+				DownloadTelemetry(
+					kind="resume",
+					file=file.path,
+					server=server,
+					attempt=attempt,
+					resumed_bytes=requested_offset,
+				)
+			)
 		headers = _headers()
 		if requested_offset:
 			headers["Range"] = f"bytes={requested_offset}-"
@@ -1051,14 +1114,17 @@ class DepotClient:
 				raise _RetryableDownloadError(
 					f"server rejected the saved offset for {file.path}",
 					discard_partial=True,
+					http_status=status,
 				) from exc
 			raise _RetryableDownloadError(
-				f"HTTP {status} from {server} for {file.path}"
+				f"HTTP {status} from {server} for {file.path}",
+				http_status=status,
 			) from exc
 		except (OSError, HTTPException) as exc:
 			raise _RetryableDownloadError(
 				f"could not connect to {server} for {file.path}: {exc}"
 			) from exc
+		response_status = getattr(response, "status", None)
 		self._notify_download(
 			DownloadTelemetry(
 				kind="response",
@@ -1066,6 +1132,7 @@ class DepotClient:
 				server=server,
 				attempt=attempt,
 				latency_seconds=max(0.0, time.monotonic() - request_started_at),
+				http_status=(response_status if isinstance(response_status, int) else None),
 			)
 		)
 
@@ -1274,15 +1341,65 @@ def sync_managed_game(
 ) -> DepotSyncResult:
 	"""Synchronize the managed game directory using only official public data."""
 
+	operation_started = time.perf_counter()
+	operation = (
+		"repair"
+		if repair
+		else "update"
+		if paths.source_game.is_dir()
+		else "install"
+	)
+	telemetry_enabled = not dry_run
 	paths.create_base_directories()
 	depot_client = client or DepotClient()
 	previous_file_catalog = read_current_depot_file_catalog(paths)
+	current_version = _completed_depot_version(paths.native_depot_state)
+	manifest_started = time.perf_counter()
+	if operation == "update":
+		_send_depot_telemetry(
+			"update_check_started",
+			metadata={"current_version": current_version},
+			context={"operation": operation, "stage": "manifest"},
+			enabled=telemetry_enabled,
+		)
 	_emit_progress(progress, "manifest", 0, 0, 0, 0, None)
-	snapshot = depot_client.fetch_snapshot()
+	try:
+		snapshot = depot_client.fetch_snapshot()
+	except BaseException as exc:
+		_send_depot_telemetry(
+			"download_failed",
+			severity="error",
+			message=str(exc),
+			metadata={
+				"resource_type": "manifest",
+				"duration_ms": _elapsed_milliseconds(manifest_started),
+				"failure_type": classify_network_failure(exc),
+			},
+			context={"operation": operation, "stage": "manifest"},
+			enabled=telemetry_enabled,
+		)
+		raise
+	manifest_duration_ms = _elapsed_milliseconds(manifest_started)
+	scan_started = time.perf_counter()
 	quarantine = QuarantineResult(0, None)
-	if quarantine_unmanaged and not dry_run:
-		quarantine = _quarantine_unmanaged_files(paths, snapshot)
-	plan = plan_update(paths.source_game, snapshot, repair=repair)
+	try:
+		if quarantine_unmanaged and not dry_run:
+			quarantine = _quarantine_unmanaged_files(paths, snapshot)
+		plan = plan_update(paths.source_game, snapshot, repair=repair)
+	except BaseException as exc:
+		_send_depot_telemetry(
+			"file_validation_failed",
+			severity="error",
+			message=str(exc),
+			metadata={
+				"duration_ms": _elapsed_milliseconds(scan_started),
+				"repair": repair,
+			},
+			context={"operation": operation, "stage": "scan"},
+			enabled=telemetry_enabled,
+		)
+		raise
+	scan_duration_ms = _elapsed_milliseconds(scan_started)
 	_emit_progress(
 		progress,
 		"planned",
@@ -1292,6 +1409,32 @@ def sync_managed_game(
 		plan.bytes_total,
 		None,
 	)
+	plan_metadata = {
+		"current_version": current_version,
+		"target_version": snapshot.version,
+		"changed_file_count": len(plan.downloads) + len(plan.deletes),
+		"files_checked": plan.files_total,
+		"files_missing": sum(item.reason == "missing" for item in plan.downloads),
+		"files_invalid": sum(item.reason != "missing" for item in plan.downloads),
+		"files_replaced": len(plan.downloads),
+		"download_bytes": plan.bytes_total,
+		"manifest_duration_ms": manifest_duration_ms,
+		"scan_duration_ms": scan_duration_ms,
+	}
+	if operation == "update":
+		_send_depot_telemetry(
+			"update_available" if plan.downloads or plan.deletes else "update_not_required",
+			metadata=plan_metadata,
+			context={"operation": operation, "stage": "scan"},
+			enabled=telemetry_enabled,
+		)
+	elif operation == "repair":
+		_send_depot_telemetry(
+			"repair_scan_completed",
+			metadata=plan_metadata,
+			context={"operation": operation, "stage": "scan"},
+			enabled=telemetry_enabled,
+		)
 
 	if dry_run:
 		return _sync_result(
@@ -1303,43 +1446,96 @@ def sync_managed_game(
 			repair,
 			True,
 			quarantine=quarantine,
+			manifest_duration_ms=manifest_duration_ms,
+			scan_duration_ms=scan_duration_ms,
+			update_duration_ms=_elapsed_milliseconds(operation_started),
 		)
 
 	root = _prepare_game_root(paths.source_game, create=True)
-	_download_plan(
+	download_metrics = _download_plan(
 		depot_client,
 		snapshot,
 		root,
 		plan,
 		progress,
 		download_options or DownloadOptions(),
+		operation=operation,
+		telemetry_enabled=telemetry_enabled,
 	)
-	deleted = _apply_deletions(root, plan.deletes)
-	created = _apply_create_if_missing(root, snapshot.create_if_missing)
-	result = _sync_result(
-		snapshot,
-		plan,
-		len(plan.downloads),
-		plan.bytes_total,
-		deleted,
-		repair,
-		False,
-		created=created,
-		quarantine=quarantine,
-	)
-	verified_paths = {
-		*plan.hash_verified_paths,
-		*(download.file.path for download in plan.downloads),
-	}
-	cache_depot_file_catalog(
-		paths.depot_file_catalog,
-		root,
-		snapshot,
-		verified_paths=verified_paths,
-		previous=previous_file_catalog,
-	)
-	_write_json(paths.native_depot_state, asdict(result))
-	cache_depot_launch_catalog(paths.depot_launch_catalog_cache, snapshot)
+	apply_started = time.perf_counter()
+	if operation == "update":
+		_send_depot_telemetry(
+			"update_apply_started",
+			metadata={
+				"target_version": snapshot.version,
+				"changed_file_count": len(plan.downloads) + len(plan.deletes),
+			},
+			context={"operation": operation, "stage": "apply"},
+			enabled=telemetry_enabled,
+		)
+	try:
+		deleted = _apply_deletions(root, plan.deletes)
+		created = _apply_create_if_missing(root, snapshot.create_if_missing)
+		verified_paths = {
+			*plan.hash_verified_paths,
+			*(download.file.path for download in plan.downloads),
+		}
+		cache_depot_file_catalog(
+			paths.depot_file_catalog,
+			root,
+			snapshot,
+			verified_paths=verified_paths,
+			previous=previous_file_catalog,
+		)
+		cache_depot_launch_catalog(paths.depot_launch_catalog_cache, snapshot)
+		apply_duration_ms = _elapsed_milliseconds(apply_started)
+		update_duration_ms = _elapsed_milliseconds(operation_started)
+		result = _sync_result(
+			snapshot,
+			plan,
+			len(plan.downloads),
+			plan.bytes_total,
+			deleted,
+			repair,
+			False,
+			created=created,
+			quarantine=quarantine,
+			manifest_duration_ms=manifest_duration_ms,
+			scan_duration_ms=scan_duration_ms,
+			apply_duration_ms=apply_duration_ms,
+			update_duration_ms=update_duration_ms,
+			download_metrics=download_metrics,
+		)
+		_write_json(paths.native_depot_state, asdict(result))
+	except BaseException as exc:
+		_send_depot_telemetry(
+			"filesystem_error",
+			severity="error",
+			message=str(exc),
+			metadata={
+				"duration_ms": _elapsed_milliseconds(apply_started),
+				"target_version": snapshot.version,
+			},
+			context={"operation": operation, "stage": "apply"},
+			enabled=telemetry_enabled,
+		)
+		raise
+	if operation == "update":
+		_send_depot_telemetry(
+			"update_apply_completed",
+			metadata={
+				**plan_metadata,
+				"apply_duration_ms": result.apply_duration_ms,
+				"download_duration_ms": result.download_duration_ms,
+				"update_duration_ms": result.update_duration_ms,
+				"network_bytes_downloaded": result.network_bytes_downloaded,
+				"average_download_mbps": result.download_average_mbps,
+				"retry_count": result.download_retry_count,
+				"resume_used": result.download_resume_used,
+			},
+			context={"operation": operation, "stage": "apply"},
+			enabled=telemetry_enabled,
+		)
 	_emit_progress(
 		progress,
 		"complete",
@@ -1463,9 +1659,12 @@ def _download_plan(
 	plan: UpdatePlan,
 	progress: ProgressCallback | None,
 	options: DownloadOptions,
-) -> None:
+	*,
+	operation: str = "update",
+	telemetry_enabled: bool = True,
+) -> DepotDownloadMetrics:
 	if not plan.downloads:
-		return
+		return DepotDownloadMetrics(mirror_id=_server_display_name(depot_snapshot.server))
 
 	lock = threading.Lock()
 	emit_lock = threading.Lock()
@@ -1476,6 +1675,11 @@ def _download_plan(
 	transferred_bytes = 0
 	retry_count = 0
 	retry_reason: str | None = None
+	resume_offsets: dict[str, int] = {}
+	mirrors: set[str] = set()
+	last_http_status: int | None = None
+	retry_events_sent = 0
+	resume_events_sent = 0
 	active_workers = 0
 	target_workers = 0
 	last_progress_emitted_at = 0.0
@@ -1486,6 +1690,19 @@ def _download_plan(
 	limiter = BandwidthLimiter(bandwidth_limit) if bandwidth_limit is not None else None
 	previous_observer = client.download_observer
 	previous_limiter = client.bandwidth_limiter
+	started_event, completed_event = _download_event_names(operation)
+	_send_depot_telemetry(
+		started_event,
+		metadata={
+			"resource_type": "repair_file" if operation == "repair" else "game",
+			"download_bytes": plan.bytes_total,
+			"file_count": len(plan.downloads),
+			"mirror_id": _server_display_name(depot_snapshot.server),
+			"cdn_region": depot_snapshot.region,
+		},
+		context={"operation": operation, "stage": "download"},
+		enabled=telemetry_enabled,
+	)
 
 	def emit_download_progress(
 		current_file: str,
@@ -1543,7 +1760,8 @@ def _download_plan(
 			progress(event)
 
 	def observe_download(event: DownloadTelemetry) -> None:
-		nonlocal transferred_bytes, retry_count, retry_reason
+		nonlocal last_http_status, resume_events_sent, retry_count
+		nonlocal retry_events_sent, retry_reason, transferred_bytes
 		if event.kind == "response" and event.latency_seconds is not None:
 			controller.record_response(event.latency_seconds)
 		elif event.kind == "retry":
@@ -1552,9 +1770,12 @@ def _download_plan(
 			controller.record_chunk(event.bytes_written, event.write_seconds)
 
 		force = event.kind == "retry"
-		if event.kind in {"request", "response", "retry", "chunk"}:
+		emit_retry = False
+		emit_resume = False
+		if event.kind in {"request", "response", "retry", "resume", "chunk"}:
 			with lock:
 				current_servers[event.file] = _server_display_name(event.server)
+				mirrors.add(_server_display_name(event.server))
 				if event.kind == "chunk":
 					transferred_bytes += event.bytes_written
 					now = time.monotonic()
@@ -1563,8 +1784,51 @@ def _download_plan(
 				if event.kind == "retry":
 					retry_count += 1
 					retry_reason = event.reason
+					if retry_events_sent < 5:
+						retry_events_sent += 1
+						emit_retry = True
+				if event.kind == "resume" and event.resumed_bytes > 0:
+					prior_offset = resume_offsets.get(event.file, 0)
+					resume_offsets[event.file] = max(prior_offset, event.resumed_bytes)
+					if prior_offset == 0 and resume_events_sent < 5:
+						resume_events_sent += 1
+						emit_resume = True
+				if event.http_status is not None:
+					last_http_status = event.http_status
 		if previous_observer is not None:
 			previous_observer(event)
+		if emit_retry:
+			_send_depot_telemetry(
+				"download_retry",
+				severity="warning",
+				message=event.reason,
+				metadata={
+					"resource_type": (
+						"repair_file" if operation == "repair" else "game"
+					),
+					"file": event.file,
+					"attempt": event.attempt,
+					"failure_type": classify_network_failure(event.reason),
+					"http_status": event.http_status,
+					"mirror_id": _server_display_name(event.server),
+				},
+				context={"operation": operation, "stage": "download_retry"},
+				enabled=telemetry_enabled,
+			)
+		if emit_resume:
+			_send_depot_telemetry(
+				"download_resumed",
+				metadata={
+					"resource_type": (
+						"repair_file" if operation == "repair" else "game"
+					),
+					"file": event.file,
+					"resumed_bytes": event.resumed_bytes,
+					"mirror_id": _server_display_name(event.server),
+				},
+				context={"operation": operation, "stage": "download_resume"},
+				enabled=telemetry_enabled,
+			)
 		if event.kind != "chunk":
 			emit_download_progress(event.file, force=force)
 
@@ -1584,6 +1848,24 @@ def _download_plan(
 			progress=report_file_bytes if progress is not None else None,
 		)
 
+	def metrics_snapshot() -> DepotDownloadMetrics:
+		with lock:
+			duration_seconds = max(0.0, time.monotonic() - started_at)
+			primary_mirror = _server_display_name(depot_snapshot.server)
+			return DepotDownloadMetrics(
+				duration_ms=round(duration_seconds * 1000),
+				transferred_bytes=transferred_bytes,
+				retry_count=retry_count,
+				resume_used=bool(resume_offsets),
+				resumed_bytes=sum(resume_offsets.values()),
+				average_mbps=_average_megabits_per_second(
+					transferred_bytes,
+					duration_seconds,
+				),
+				mirror_id=primary_mirror,
+				http_status=last_http_status,
+			)
+
 	maximum_workers = min(options.effective_maximum_workers, len(plan.downloads))
 	# Start large transfers first so they overlap the small-file request workload
 	# instead of becoming a single-connection tail at the end of an install.
@@ -1659,10 +1941,56 @@ def _download_plan(
 				for future in future_items:
 					future.cancel()
 				raise
+	except BaseException as exc:
+		metrics = metrics_snapshot()
+		_send_depot_telemetry(
+			"download_failed",
+			severity="error",
+			message=str(exc),
+			metadata={
+				"resource_type": "repair_file" if operation == "repair" else "game",
+				"download_bytes": metrics.transferred_bytes,
+				"content_bytes": plan.bytes_total,
+				"duration_ms": metrics.duration_ms,
+				"average_mbps": metrics.average_mbps,
+				"retry_count": metrics.retry_count,
+				"resume_used": metrics.resume_used,
+				"resumed_bytes": metrics.resumed_bytes,
+				"http_status": metrics.http_status,
+				"failure_type": classify_network_failure(exc),
+				"mirror_id": metrics.mirror_id,
+				"mirrors_tried": sorted(mirrors),
+			},
+			context={"operation": operation, "stage": "download"},
+			enabled=telemetry_enabled,
+		)
+		raise
 	finally:
 		client.download_observer = previous_observer
 		client.bandwidth_limiter = previous_limiter
 
+	metrics = metrics_snapshot()
+	_send_depot_telemetry(
+		completed_event,
+		metadata={
+			"resource_type": "repair_file" if operation == "repair" else "game",
+			"download_bytes": metrics.transferred_bytes,
+			"content_bytes": plan.bytes_total,
+			"duration_ms": metrics.duration_ms,
+			"average_mbps": metrics.average_mbps,
+			"retry_count": metrics.retry_count,
+			"resume_used": metrics.resume_used,
+			"resumed_bytes": metrics.resumed_bytes,
+			"http_status": metrics.http_status,
+			"mirror_id": metrics.mirror_id,
+			"mirrors_used": sorted(mirrors),
+			"file_count": len(plan.downloads),
+		},
+		context={"operation": operation, "stage": "download"},
+		enabled=telemetry_enabled,
+	)
+	return metrics
+
 
 def _apply_deletions(root: Path, relative_paths: Iterable[str]) -> int:
 	deleted = 0
@@ -1853,10 +2181,62 @@ def _completed_depot_build(path: Path) -> int | None:
 	return build
 
 
+def _completed_depot_version(path: Path) -> str | None:
+	try:
+		value = json.loads(path.read_text(encoding="utf-8"))
+	except (OSError, UnicodeError, json.JSONDecodeError):
+		return None
+	if not isinstance(value, dict) or value.get("dry_run") is not False:
+		return None
+	version = value.get("version")
+	return version[:32] if isinstance(version, str) and version else None
+
+
 def _elapsed_milliseconds(started: float) -> int:
 	return max(0, round((time.perf_counter() - started) * 1000))
 
 
+def _average_megabits_per_second(byte_count: int, duration_seconds: float) -> float | None:
+	if byte_count <= 0 or duration_seconds <= 0:
+		return None
+	return round((byte_count * 8) / duration_seconds / 1_000_000, 3)
+
+
+def _download_event_names(operation: str) -> tuple[str, str]:
+	if operation == "install":
+		return "install_download_started", "install_download_completed"
+	if operation == "update":
+		return "update_download_started", "update_download_completed"
+	return "download_started", "download_completed"
+
+
+def _send_depot_telemetry(
+	event: str,
+	*,
+	severity: str = "info",
+	message: str | None = None,
+	metadata: Mapping[str, object] | None = None,
+	context: Mapping[str, object] | None = None,
+	enabled: bool = True,
+) -> None:
+	if not enabled:
+		return
+	telemetry = current_telemetry()
+	if telemetry is None:
+		return
+	try:
+		telemetry.send_event(
+			event,
+			severity=severity,
+			message=message,
+			metadata=metadata,
+			context=context,
+		)
+	except Exception:
+		# Telemetry must never alter verified depot behavior.
+		pass
+
+
 def _sync_result(
 	snapshot: DepotSnapshot,
 	plan: UpdatePlan,
@@ -1868,7 +2248,13 @@ def _sync_result(
 	*,
 	created: int = 0,
 	quarantine: QuarantineResult = QuarantineResult(0, None),
+	manifest_duration_ms: int = 0,
+	scan_duration_ms: int = 0,
+	apply_duration_ms: int = 0,
+	update_duration_ms: int = 0,
+	download_metrics: DepotDownloadMetrics | None = None,
 ) -> DepotSyncResult:
+	metrics = download_metrics or DepotDownloadMetrics()
 	return DepotSyncResult(
 		region=snapshot.region,
 		server=snapshot.server,
@@ -1887,6 +2273,16 @@ def _sync_result(
 		repair=repair,
 		dry_run=dry_run,
 		completed_at=datetime.now().astimezone().isoformat(),
+		manifest_duration_ms=manifest_duration_ms,
+		scan_duration_ms=scan_duration_ms,
+		download_duration_ms=metrics.duration_ms,
+		apply_duration_ms=apply_duration_ms,
+		update_duration_ms=update_duration_ms,
+		network_bytes_downloaded=metrics.transferred_bytes,
+		download_retry_count=metrics.retry_count,
+		download_resume_used=metrics.resume_used,
+		download_average_mbps=metrics.average_mbps,
+		mirror_id=metrics.mirror_id,
 	)