From afaff8e0706a132a0a3b7950250bf7c24e6581d4 Mon Sep 17 00:00:00 2001 From: imSp4rky Date: Wed, 21 Oct 2026 14:39:37 -0600 Subject: [PATCH] feat(api): tag each error with a ref and count errors by service Every structured error carries a short ref, appended to its message and logged with the request; /api/dashboard/status gains per-service error counts. Gzip now compresses in place. --- docs/dev/rest-api/dashboard.md | 7 ++++- docs/dev/rest-api/errors.md | 17 +++++++++-- tests/remote/unit/test_compression.py | 2 +- tests/remote/unit/test_errors.py | 6 ++-- tests/remote/unit/test_routes.py | 31 ++++++++++++++++++- unshackle/core/api/compression.py | 12 ++------ unshackle/core/api/errors.py | 12 ++++++-- unshackle/core/api/routes.py | 5 +-- unshackle/core/api/stats.py | 44 ++++++++++++++++++++++----- 9 files changed, 107 insertions(+), 29 deletions(-) diff --git a/docs/dev/rest-api/dashboard.md b/docs/dev/rest-api/dashboard.md index 85dd7742..809a9c62 100644 --- a/docs/dev/rest-api/dashboard.md +++ b/docs/dev/rest-api/dashboard.md @@ -43,7 +43,7 @@ All are `GET`. | Path | Returns | |------|---------| -| `/api/dashboard/status` | Version, `code_hash`, bind host and port, `mode` (`full`, `api_only`, `remote_only`), uptime, `requests_total`, `requests_rejected` (401s), `requests_by_key` (label → count), configured service count (the same services as `/api/dashboard/services`), session count, `max_sessions` (`null` when the operator configured no limit), `session_ttl`, job counts by status. The service count includes services that failed to import - use `/api/dashboard/services` for the number that loaded. | +| `/api/dashboard/status` | Version, `code_hash`, bind host and port, `mode` (`full`, `api_only`, `remote_only`), uptime, `requests_total`, `requests_rejected` (401s), `requests_by_key` (label → count), `errors` (error counts by service tag, then by `error_code`), configured service count (the same services as `/api/dashboard/services`), session count, `max_sessions` (`null` when the operator configured no limit), `session_ttl`, job counts by status. The service count includes services that failed to import - use `/api/dashboard/services` for the number that loaded. | | `/api/dashboard/sessions` | Every live remote session: `id`, `owner` (username or masked key), `creator_ip`, `service`, `title_id`, `titles`, `tracks`, `title` (the display name of the title the client is on: the last one it asked tracks for, else the first resolved title), `auth_status`, `auth_error`, `server_account` (the server profile lent to the remote session, else `null`), `server_cdm` (`false` when the client's own device licenses the remote session), `server_cdm_max_height` (the tallest video the server CDM licenses live, else `null`), `client`, `actions`, `created_at` and `last_accessed` (ISO 8601) with `created_ts` and `last_accessed_ts` (Unix epoch, the same clock as log `ts`), `age_seconds`, `idle_seconds`, `log_seq`. `client` is whatever the remote client sent as `client` in its session create request. The CLI sends `version`, `code_hash` (the commit the client runs, `null` when its source cannot be read), `platform` and `argv`. `argv` is the command line the user ran: proxy and URL userinfo, secret query parameters and credential values become `***`, home and install paths shorten as in the logs, and the line is cut at 3000 characters. An older client sends less or nothing and the field is `{}`. `log_seq` is the last sequence number in the remote session's service log - poll `/api/dashboard/sessions/{id}/logs` when it changes. `actions` is the session's request log, newest last, capped at 500: `ts`, `method`, `action` (`titles`, `tracks`, `segments`, `license`, `prompt`, …), `query`, `status`, `ms`, `bytes_in`, `bytes_out`. | | `/api/dashboard/jobs` | Every download job with full detail, regardless of owner. Empty in `--remote-only` mode. | | `/api/dashboard/logs` | `{"seq": N, "records": [...]}`: the last 1000 log records. `?since=` returns only newer records; `?level=WARNING` sets the minimum level; `?logger=serve` keeps one logger and its children (`aiohttp.access` is the noisiest). `ts` is a Unix epoch in seconds. | @@ -54,6 +54,11 @@ All are `GET`. | `/api/dashboard/health` | Preflight: whether this instance could finish a download. Cached 30 seconds. | | `/api/dashboard/events` | Server-Sent Events stream. With `?since=` it returns `{"seq", "stats", "events": [...]}` instead: every event after `seq` (the server keeps the last 20000, log records included, so a poll every few seconds is safe even under a busy access log) as one JSON burst, so a UI that polls every few seconds still sees a remote session that opened and closed in between. | +`errors` counts every structured error response since the server started, for example +`{"EXAMPLE": {"SERVICE_ERROR": 4}, "-": {"SESSION_NOT_FOUND": 1}}`. The service is the one of +the remote session, else the `service` field of the JSON body. `-` holds an error with no +installed service. Each error also logs its [`ref`](errors.md#find-an-error-from-its-ref). + `requests_rejected` counts 401 responses; those never appear in `requests_by_key`. The label is the `username` from the `users` entry when one is set, else the first four characters of the API key. diff --git a/docs/dev/rest-api/errors.md b/docs/dev/rest-api/errors.md index 82ecc8c0..d50ca08d 100644 --- a/docs/dev/rest-api/errors.md +++ b/docs/dev/rest-api/errors.md @@ -25,7 +25,8 @@ A structured error is always a JSON object with `status` set to the literal stri { "status": "error", "error_code": "INVALID_PARAMETERS", - "message": "vcodec must be one of: H264, H265, ...", + "message": "vcodec must be one of: H264, H265, ... (ref 7f3a2c)", + "ref": "7f3a2c", "timestamp": "2026-07-03T12:34:56.789012+00:00", "details": { "field": "vcodec" }, "retryable": true, @@ -40,7 +41,8 @@ A structured error is always a JSON object with `status` set to the literal stri |---|---|---|---| | `status` | string | Yes | Always the literal `"error"`. Lets a client distinguish an error body from a success body at a glance. | | `error_code` | string | Yes | A stable, machine-readable code from the [catalogue below](#error-code-catalogue). Match on this, not on `message`. | -| `message` | string | Yes | A human-readable description of what went wrong. Wording may change between versions, so do not parse it. | +| `message` | string | Yes | A human-readable description of what went wrong, followed by `(ref )`. Wording may change between versions, so do not parse it. | +| `ref` | string | Yes | A short random reference for this one error. The server logs it with the request, so an operator can find the record from a user's report. | | `timestamp` | string | Yes | ISO 8601 timestamp (UTC) of when the error response was built. | | `details` | object | Only when non-empty | Structured, error-specific context (for example the invalid field, a list of available titles, or the set of currently active jobs). | | `retryable` | boolean | Only when `true` | Present and set to `true` when retrying the same request may succeed later (network blips, rate limiting, transient outages). Absent otherwise. | @@ -52,6 +54,17 @@ A structured error is always a JSON object with `status` set to the literal stri every code maps to a default status (see the catalogue), and the pairing is stable across releases. +### Find an error from its `ref` + +For each error response, the server logs one `WARNING` line on the `api` logger: + +```text +Error ref 7f3a2c: SERVICE_ERROR 422 POST /api/session//license service=EXAMPLE user=alice: Licence request failed: ... +``` + +Search the server log for `Error ref `. The handler's traceback, when there is one, +is directly above that line. The [developer dashboard](dashboard.md) log view also shows it. + ### The `details` object When present, `details` carries extra context specific to the error. It is only diff --git a/tests/remote/unit/test_compression.py b/tests/remote/unit/test_compression.py index 9139f22d..67993a29 100644 --- a/tests/remote/unit/test_compression.py +++ b/tests/remote/unit/test_compression.py @@ -61,4 +61,4 @@ def test_compresses_large_json_when_accepted() -> None: assert resp.headers.get("Content-Encoding") == "gzip" decompressed = gzip.decompress(resp.body) assert json.loads(decompressed) == big - assert resp.headers["Content-Length"] == str(len(resp.body)) + assert resp.content_length == len(resp.body) diff --git a/tests/remote/unit/test_errors.py b/tests/remote/unit/test_errors.py index 546522b1..6026281b 100644 --- a/tests/remote/unit/test_errors.py +++ b/tests/remote/unit/test_errors.py @@ -73,7 +73,7 @@ def test_build_error_response_from_api_error() -> None: body = _body(resp) assert body["status"] == "error" assert body["error_code"] == "SESSION_NOT_FOUND" - assert body["message"] == "no such session" + assert body["message"] == f"no such session (ref {body['ref']})" assert body["details"] == {"session_id": "abc"} assert "retryable" not in body assert "debug_info" not in body @@ -91,7 +91,7 @@ def test_build_error_response_from_generic_exception() -> None: assert resp.status == 500 body = _body(resp) assert body["error_code"] == "INTERNAL_ERROR" - assert body["message"] == "oops" + assert body["message"] == f"oops (ref {body['ref']})" def test_build_error_response_debug_mode_includes_traceback() -> None: @@ -188,6 +188,6 @@ def test_error_contract_apierror_passthrough_full_shape() -> None: assert resp.status == 429 body = _body(resp) assert body["error_code"] == "RATE_LIMITED" - assert body["message"] == "slow down" + assert body["message"] == f"slow down (ref {body['ref']})" assert body["details"] == {"retry_after": 5} assert body["retryable"] is True diff --git a/tests/remote/unit/test_routes.py b/tests/remote/unit/test_routes.py index cfbbb2f2..c28215c3 100644 --- a/tests/remote/unit/test_routes.py +++ b/tests/remote/unit/test_routes.py @@ -9,6 +9,7 @@ from __future__ import annotations import asyncio import json +from collections import Counter, defaultdict import pytest from aiohttp import web @@ -132,7 +133,7 @@ async def test_api_handler_maps_apierror(aiohttp_client) -> None: body = await resp.json() assert body["status"] == "error" assert body["error_code"] == "NOT_FOUND" - assert body["message"] == "nope" + assert body["message"] == f"nope (ref {body['ref']})" assert body["details"] == {"x": 1} @@ -180,6 +181,7 @@ async def test_heartbeat_late_error_counts_as_rejected(aiohttp_client, monkeypat monkeypatch.setattr(routes, "HEARTBEAT_INTERVAL", 0.05) monkeypatch.setattr(stats, "keys", {}) + monkeypatch.setattr(stats, "errors", defaultdict(Counter)) @heartbeat async def slow_fail(request: web.Request) -> web.Response: @@ -195,6 +197,33 @@ async def test_heartbeat_late_error_counts_as_rejected(aiohttp_client, monkeypat sent = len(await resp.read()) (entry,) = stats.keys.values() assert resp.status == 200 and entry.rejected == 1 and entry.bytes_out >= sent > 0 + assert stats.errors == {"-": {"SERVICE_ERROR": 1}} + + +@pytest.mark.parametrize(("service", "counted_as"), [("EXAMPLE", "EXAMPLE"), ("NOT_INSTALLED", "-")]) +async def test_error_is_counted_by_service_and_logged_with_its_ref( + aiohttp_client, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture, service: str, counted_as: str +) -> None: + """A gzipped error still reaches the stats: counted under an installed service only, and logged with its ref.""" + from unshackle.core.api.stats import stats, stats_middleware + + monkeypatch.setattr(stats, "errors", defaultdict(Counter)) + + @api_handler + async def fail(request: web.Request) -> web.Response: + await request.json() + raise APIError(APIErrorCode.SERVICE_ERROR, "denied", details={"pad": "x" * 300}) + + app = web.Application(middlewares=[stats_middleware, compression_middleware]) + app["debug_api"] = False + app.router.add_post("/fail", fail) + client = await aiohttp_client(app) + + resp = await client.post("/fail", json={"service": service}, headers={"Accept-Encoding": "gzip"}) + body = await resp.json() + assert resp.headers["Content-Encoding"] == "gzip" + assert stats.errors == {counted_as: {"SERVICE_ERROR": 1}} + assert f"Error ref {body['ref']}: SERVICE_ERROR 422 POST /fail service={counted_as}" in caplog.text async def test_heartbeat_client_disconnect_is_quiet( diff --git a/unshackle/core/api/compression.py b/unshackle/core/api/compression.py index 676c2688..2561d840 100644 --- a/unshackle/core/api/compression.py +++ b/unshackle/core/api/compression.py @@ -49,12 +49,6 @@ async def compression_middleware(request: web.Request, handler) -> web.StreamRes if not level: return response - compressed = gzip.compress(body, compresslevel=level) - headers = dict(response.headers) - headers["Content-Encoding"] = "gzip" - headers["Content-Length"] = str(len(compressed)) - return web.Response( - body=compressed, - status=response.status, - headers=headers, - ) + response.body = gzip.compress(body, compresslevel=level) + response.headers["Content-Encoding"] = "gzip" + return response diff --git a/unshackle/core/api/errors.py b/unshackle/core/api/errors.py index 4466264c..7b798ca3 100644 --- a/unshackle/core/api/errors.py +++ b/unshackle/core/api/errors.py @@ -7,6 +7,7 @@ and optional debug information for the unshackle REST API. from __future__ import annotations +import secrets import traceback from datetime import datetime, timezone from enum import Enum @@ -114,6 +115,9 @@ def build_error_response( """ Assemble a structured JSON error response. + Each error gets a short ``ref``, also appended to ``message`` so that every client prints it. + The stats middleware logs the ref with the request, so a reported ref finds the server-side record. + Args: error: APIError or generic Exception to convert to response debug_mode: Whether to include technical debug information @@ -135,10 +139,12 @@ def build_error_response( http_status = 500 retryable = False + ref = secrets.token_hex(3) response_data: dict[str, Any] = { "status": "error", "error_code": error_code, - "message": message, + "message": f"{message} (ref {ref})", + "ref": ref, "timestamp": datetime.now(timezone.utc).isoformat(), } @@ -161,7 +167,9 @@ def build_error_response( response_data["debug_info"] = debug_info - return web.json_response(response_data, status=http_status) + response = web.json_response(response_data, status=http_status) + response["error"] = {"code": error_code, "ref": ref, "message": message} + return response def categorize_exception( diff --git a/unshackle/core/api/routes.py b/unshackle/core/api/routes.py index d605be85..57f9934e 100644 --- a/unshackle/core/api/routes.py +++ b/unshackle/core/api/routes.py @@ -147,6 +147,7 @@ def heartbeat(handler: Handler) -> Handler: log.exception(f"Error in {request.path}") result = handle_api_exception(e, debug_mode=debug_mode) response["late_status"] = result.status + response["error"] = result.get("error") body = result.body if isinstance(result, web.Response) else None await response.write(bytes(body) if isinstance(body, (bytes, bytearray)) else b"{}") await response.write_eof() @@ -2581,8 +2582,8 @@ async def dashboard_status(request: web.Request) -> web.Response: --- summary: Dashboard server status description: > - Version, uptime, bind address, mode, request counters per API key, and counts of - services, remote sessions and jobs. Every /api/dashboard/ route needs + Version, uptime, bind address, mode, request counters per API key, error counts by + service and error code, and counts of services, remote sessions and jobs. Every /api/dashboard/ route needs `serve.dashboard.key` in X-Secret-Key; a user key never passes, and the routes do not exist without a dashboard key. tags: [Dashboard] diff --git a/unshackle/core/api/stats.py b/unshackle/core/api/stats.py index 3b150510..1d09ce19 100644 --- a/unshackle/core/api/stats.py +++ b/unshackle/core/api/stats.py @@ -7,7 +7,7 @@ import hashlib import json import logging import time -from collections import Counter, deque +from collections import Counter, defaultdict, deque from dataclasses import dataclass, field from functools import lru_cache from typing import Any, Deque, Dict, List, Optional, Tuple @@ -143,6 +143,7 @@ class ServerStats: requests_total: int = 0 requests_rejected: int = 0 keys: Dict[str, KeyStats] = field(default_factory=dict) + errors: Dict[str, Counter] = field(default_factory=lambda: defaultdict(Counter)) # service -> error_code -> count def key_stats(self, key: Optional[str]) -> KeyStats: """The counters for an API key, created on first sight.""" @@ -194,6 +195,7 @@ class ServerStats: "requests_total": self.requests_total, "requests_rejected": self.requests_rejected, "requests_by_key": dict(self.requests_by_key), + "errors": {service: dict(codes) for service, codes in self.errors.items()}, } @@ -203,16 +205,18 @@ stats = ServerStats() @web.middleware async def stats_middleware(request: web.Request, handler: Any) -> web.StreamResponse: from unshackle.core.api.handlers import request_secret_key + from unshackle.core.api.sanitize import sanitize_log stats.requests_total += 1 started = time.perf_counter() response = await handler(request) status = response.get("late_status", response.status) bytes_out = getattr(response, "content_length", None) or response.body_length + key = None if status == 401 else configured_key(request_secret_key(request)) if status == 401: stats.requests_rejected += 1 else: - entry = stats.key_stats(configured_key(request_secret_key(request))) + entry = stats.key_stats(key) entry.requests += 1 entry.last_seen = time.time() entry.bytes_out += bytes_out @@ -235,9 +239,33 @@ async def stats_middleware(request: web.Request, handler: Any) -> web.StreamResp "bytes_out": bytes_out, }, ) + error = response.get("error") + if error: + service = await _request_service(request, session_id) + stats.errors[service][error["code"]] += 1 + logging.getLogger("api").warning( + f"Error ref {error['ref']}: {error['code']} {status} {request.method} {sanitize_log(request.path)} " + f"service={service} user={sanitize_log(mask_key(key))}: {sanitize_log(error['message'])}" + ) return response +async def _request_service(request: web.Request, session_id: Optional[str]) -> str: + """The installed service tag a request is for, from its remote session or its JSON body; ``-`` if none. + + Only an installed tag counts, so a caller cannot grow ``stats.errors`` with made-up names. + """ + from unshackle.core.api.session_store import get_session_store + from unshackle.core.services import Services + + entry = get_session_store().peek(session_id) if session_id else None + service = entry.service_tag if entry is not None else (await _consumed_json(request)).get("service") + if not isinstance(service, str): + return "-" + tag = Services.get_tag(service) + return tag if tag in Services.get_tags() else "-" + + class SeqRing: """Keep the last N records in memory, each with a ``seq`` one above the record before it.""" @@ -347,20 +375,20 @@ def _reply_json(response: Any) -> Dict[str, Any]: return data if isinstance(data, dict) else {} -async def _request_session_id(request: web.Request) -> Any: - """The ``session_id`` of the JSON request body, when the handler consumed it: aiohttp caches that read. +async def _consumed_json(request: web.Request) -> Dict[str, Any]: + """The JSON object of the request body when the handler consumed it (aiohttp caches that read), else ``{}``. A body nobody read belongs to a call refused before the handler, a 401 or a 429. It stays unread: reading it would spend time and memory on an unauthenticated caller, and wait on a body that never finishes arriving. """ if not request.content.at_eof(): - return None + return {} try: body = await request.json() except Exception: - return None - return body.get("session_id") if isinstance(body, dict) else None + return {} + return body if isinstance(body, dict) else {} async def _cdm_record(request: web.Request, drm: str, op: str, outcome: Any) -> Dict[str, Any]: @@ -388,7 +416,7 @@ async def _cdm_record(request: web.Request, drm: str, op: str, outcome: Any) -> elif op == "close": session_id = request.match_info.get("session_id") else: - session_id = await _request_session_id(request) + session_id = (await _consumed_json(request)).get("session_id") return { "drm": drm, "op": op,