From dc18b23b9155bc597d67ed3d7b84b3e84ff0f9ed Mon Sep 17 00:00:00 2001 From: imSp4rky Date: Thu, 12 Nov 2026 16:14:34 -0700 Subject: [PATCH] fix(remote): keep vault keys when a relayed licence is refused proxy_license now raises ClickException instead of RemoteError (a SystemExit), so dl falls back to the track's vault key; licence messages name the track ("video 360p DV (592464997)"). --- tests/core/test_licence_turns.py | 15 ++++++++++++ tests/remote/unit/test_progress_sink.py | 8 +++++++ .../test_remote_service_server_cdm_license.py | 19 +++++++++++++++ .../unit/test_server_cdm_key_verification.py | 2 +- unshackle/commands/dl.py | 23 ++++++++++--------- unshackle/core/api/handlers.py | 23 ++++++++++--------- unshackle/core/api/progress.py | 6 +++++ unshackle/core/remote_service.py | 16 ++++++++++--- 8 files changed, 86 insertions(+), 26 deletions(-) diff --git a/tests/core/test_licence_turns.py b/tests/core/test_licence_turns.py index ff7443d9..bf61235b 100644 --- a/tests/core/test_licence_turns.py +++ b/tests/core/test_licence_turns.py @@ -9,6 +9,7 @@ from types import SimpleNamespace from typing import Any, Callable, Optional from uuid import UUID +import click import pytest from pywidevine.pssh import PSSH from rich.table import Table @@ -197,3 +198,17 @@ def test_vaults_only_stops_at_the_first_kid_no_vault_holds(cmd: dl, licences: li assert asked == [KID_A] assert licences == [] + + +def test_a_refused_licence_keeps_the_known_track_key(cmd: dl, monkeypatch: pytest.MonkeyPatch) -> None: + def refuse(self: Widevine, **_: Any) -> None: + raise click.ClickException("Licence request failed") + + monkeypatch.setattr(Widevine, "get_content_keys", refuse) + monkeypatch.setattr(dl, "LICENSE_KEY_CACHE", {KID_A: KEYS[KID_A]}) + monkeypatch.setattr(dl, "DRM_LOCKS", {}) + drm = widevine(KID_A, KID_B) + + prepare(cmd, drm, KID_A, new_table()) + + assert drm.content_keys == {KID_A: KEYS[KID_A]} diff --git a/tests/remote/unit/test_progress_sink.py b/tests/remote/unit/test_progress_sink.py index e0886365..53295836 100644 --- a/tests/remote/unit/test_progress_sink.py +++ b/tests/remote/unit/test_progress_sink.py @@ -12,6 +12,7 @@ import pytest from unshackle.core.api.progress import ( DOWNLOAD_PROGRESS_CEILING, build_job_progress_callables, + track_log_label, track_progress_label, track_progress_weight, ) @@ -48,6 +49,13 @@ def noop(**kwargs): pass +def test_track_log_label_adds_the_track_id(): + video = Video(2160, "DV") + video.id = "592464997" + + assert track_log_label(video) == "video 2160p DV (592464997)" + + def test_track_progress_label(): assert track_progress_label(Video(2160, "DV")) == "video 2160p DV" assert track_progress_label(Video(1080, "HDR10+")) == "video 1080p HDR10+" diff --git a/tests/remote/unit/test_remote_service_server_cdm_license.py b/tests/remote/unit/test_remote_service_server_cdm_license.py index 890b3ab2..a41137fa 100644 --- a/tests/remote/unit/test_remote_service_server_cdm_license.py +++ b/tests/remote/unit/test_remote_service_server_cdm_license.py @@ -96,3 +96,22 @@ def test_proxy_mode_keeps_the_callers_type(): assert licence == b"lic" assert svc.client.posts[0]["drm_type"] == "playready" assert svc.client.posts[0]["pssh"] == "PR" + + +def test_a_refused_relayed_licence_raises_a_click_exception_with_the_server_message(): + import click + + from unshackle.core.remote_service import RemoteError + + svc = _service("widevine", {}) + svc._server_cdm = False + svc.drain_server_logs = lambda: None + + def refuse(endpoint, payload, expect=()): + raise RemoteError("Licence request failed: refused", "SERVICE_ERROR") + + svc.client.post = refuse + track = SimpleNamespace(id="vid", drm=[_PlayReady()]) + + with pytest.raises(click.ClickException, match="^Licence request failed: refused$"): + svc.proxy_license(b"chal", track, "playready") diff --git a/tests/remote/unit/test_server_cdm_key_verification.py b/tests/remote/unit/test_server_cdm_key_verification.py index 3c2a6e6e..7481cd05 100644 --- a/tests/remote/unit/test_server_cdm_key_verification.py +++ b/tests/remote/unit/test_server_cdm_key_verification.py @@ -182,7 +182,7 @@ def test_resolve_server_keys_does_not_warn_for_clear_tracks(monkeypatch): svc.resolve_server_keys(SimpleNamespace(tracks=Tracks([video_track, audio_track]))) - assert warnings == ["Server CDM returned no content keys for track v-1"] + assert warnings == ["Server CDM returned no content keys for track simplenamespace (v-1)"] def resolve(manifest_drm, drm_type="widevine"): diff --git a/unshackle/commands/dl.py b/unshackle/commands/dl.py index e1941873..35af97fd 100644 --- a/unshackle/commands/dl.py +++ b/unshackle/commands/dl.py @@ -5102,18 +5102,19 @@ class dl: ) show_error(msg) raise + else: + log_event( + "license_keys_retrieved", + level="INFO", + service=self.service, + context={ + "track": str(track), + "drm_type": type(drm).__name__, + "keys_count": len(drm.content_keys), + "kids": [k.hex for k in drm.content_keys.keys()], + }, + ) - log_event( - "license_keys_retrieved", - level="INFO", - service=self.service, - context={ - "track": str(track), - "drm_type": type(drm).__name__, - "keys_count": len(drm.content_keys), - "kids": [k.hex for k in drm.content_keys.keys()], - }, - ) for kid, key in drm.content_keys.items(): self.add_key_label(cek_tree, kid, f"[red]{key}[/]" if is_null_key(key) else key, track_kid) drop_null_keys(drm) diff --git a/unshackle/core/api/handlers.py b/unshackle/core/api/handlers.py index fd0034a0..72c14d46 100644 --- a/unshackle/core/api/handlers.py +++ b/unshackle/core/api/handlers.py @@ -27,6 +27,7 @@ from aiohttp import web from unshackle.core.api.compression import safe_inflate from unshackle.core.api.errors import APIError, APIErrorCode, categorize_exception, handle_api_exception from unshackle.core.api.input_bridge import AuthStatus, InputBridge, NoUserBridge +from unshackle.core.api.progress import track_log_label from unshackle.core.api.sanitize import MAX_SESSION_CACHE_KEYS, safe_cache_key, safe_cache_payload, sanitize_log from unshackle.core.api.session_log import SessionLogBuffer, SessionLogMirror, capture_service_logs from unshackle.core.api.session_store import SessionStore @@ -4804,7 +4805,7 @@ def server_drm_candidates( candidates.insert(0, preferred) else: warn( - f"Track {sanitize_log(str(track.id)[:12])} wants {preferred} DRM " + f"Track {track_log_label(track)} wants {preferred} DRM " "but the server has no device for it, using the configured DRM instead" ) return candidates @@ -4822,7 +4823,7 @@ def pick_server_pssh(track: Any, candidates: List[str]) -> Optional[tuple[str, s pssh_str = extract_pssh_from_track(track, "playready") if pssh_str: log.info( - f"Track {sanitize_log(str(track.id)[:12])} has only a PlayReady PSSH, licensing it with the Widevine device" + f"Track {track_log_label(track)} has only a PlayReady PSSH, licensing it with the Widevine device" ) if pssh_str: return candidate, pssh_str @@ -5361,7 +5362,7 @@ def license_response( """ picked = pick_server_pssh(track, candidates) if not picked: - warn(f"No PSSH on track {sanitize_log(str(track.id)[:12])} for {', '.join(candidates) or 'any CDM'}") + warn(f"No PSSH on track {track_log_label(track)} for {', '.join(candidates) or 'any CDM'}") return {}, None, None candidate, pssh_str = picked @@ -5386,13 +5387,13 @@ def license_response( keys_by_pssh[cache_key] = keys drm_type_by_pssh[cache_key] = candidate except SystemExit: - warn(f"Service exited while resolving keys for track {sanitize_log(str(track.id)[:12])}, skipping") + warn(f"Service exited while resolving keys for track {track_log_label(track)}, skipping") except (Exception, SystemExit) as e: if isinstance(e, APIError) and e.error_code is APIErrorCode.SERVER_CDM_CAPPED: del keys_by_pssh[cache_key], sources_by_pssh[cache_key] capped_tracks[str(track.id)] = e.details return {}, None, pssh_str - warn(f"Failed to resolve keys for track {sanitize_log(str(track.id)[:12])}: {redact_all(str(e))}") + warn(f"Failed to resolve keys for track {track_log_label(track)}: {redact_all(str(e))}") return keys_by_pssh[cache_key], drm_type_by_pssh.get(cache_key), pssh_str for tid in track_ids: @@ -5404,7 +5405,7 @@ def license_response( init_data = fetch_init_segment(track, svc_session) ensure_track_drm(track, svc_session, init_data) if not track.drm or all(isinstance(d, BlowfishStripe) for d in track.drm): - log.info(f"Track {sanitize_log(tid[:12])} needs no licence, so it has no keys to resolve") + log.info(f"Track {track_log_label(track)} needs no licence, so it has no keys to resolve") clear_tracks.append(tid) continue @@ -5434,7 +5435,7 @@ def license_response( if init_pssh != pssh_str: log.info( f"The manifest PSSH gave no content key for KID {track_kid.hex} of track " - f"{sanitize_log(tid[:12])}, tried the init segment PSSH" + f"{track_log_label(track)}, tried the init segment PSSH" ) if track_kid.hex in init_keys: keys, track_drm_type, pssh_str = init_keys, init_drm_type, init_pssh @@ -5443,7 +5444,7 @@ def license_response( track.drm = manifest_drm refusal = refusal or init_refusal if not refusal: - warn(f"No content key for KID {track_kid.hex} of track {sanitize_log(tid[:12])}") + warn(f"No content key for KID {track_kid.hex} of track {track_log_label(track)}") if refusal: capped_tracks[tid] = refusal continue @@ -5503,12 +5504,12 @@ def license_response( if not picked: raise APIError( APIErrorCode.INVALID_INPUT, - f"No PSSH on track {sanitize_log(track_id[:12])} for {', '.join(candidates) or 'any CDM'}", + f"No PSSH on track {track_log_label(track)} for {', '.join(candidates) or 'any CDM'}", ) server_drm_type, server_pssh = picked if pssh_b64 and server_drm_type != drm_type: log.info( - f"Client asked for {sanitize_log(drm_type)} on track {sanitize_log(track_id[:12])}, " + f"Client asked for {sanitize_log(drm_type)} on track {track_log_label(track)}, " f"licensing with the server's {server_drm_type} CDM" ) pssh_b64 = None @@ -5528,7 +5529,7 @@ def license_response( live_licence_refusal(session, track), vault_only=vault_only, ) - log.info(f"Server CDM resolved {len(keys)} key(s) for track {sanitize_log(track_id[:12])}") + log.info(f"Server CDM resolved {len(keys)} key(s) for track {track_log_label(track)}") note_served_keys(session, keys, key_sources) return web.json_response({"keys": keys, "vault_keys": list(key_sources), "drm_type": server_drm_type}) diff --git a/unshackle/core/api/progress.py b/unshackle/core/api/progress.py index 350a8216..291f0710 100644 --- a/unshackle/core/api/progress.py +++ b/unshackle/core/api/progress.py @@ -9,6 +9,7 @@ from __future__ import annotations import time from typing import Any, Callable, Optional +from unshackle.core.api.sanitize import sanitize_log from unshackle.core.constants import AnyTrack from unshackle.core.utilities import standard_resolution @@ -49,6 +50,11 @@ def track_progress_label(track: AnyTrack) -> str: return track_type.lower() +def track_log_label(track: AnyTrack) -> str: + """Track label for a log line: its short label and its ID, e.g. "video 360p DV (592464997)".""" + return f"{track_progress_label(track)} ({sanitize_log(str(track.id)[:12])})" + + def track_progress_weight(track: AnyTrack) -> float: """Track weight in the aggregate (its bitrate in bits/s), so video/audio dominate subtitles.""" bitrate = getattr(track, "bitrate", None) diff --git a/unshackle/core/remote_service.py b/unshackle/core/remote_service.py index 1fd977d9..ae0f4010 100644 --- a/unshackle/core/remote_service.py +++ b/unshackle/core/remote_service.py @@ -130,6 +130,9 @@ class RemoteError(SystemExit): quiet = getattr(_recovering, "on", False) and kind in RECOVERABLE (log.debug if quiet else log.error)(message) + def __str__(self) -> str: + return self.message + @property def session_broke(self) -> bool: """Whether the remote session itself is gone, not only this one call.""" @@ -1893,7 +1896,9 @@ class RemoteService: track_keys = keys_by_track.get(server_id, {}) if not track_keys: if server_id in track_ids and server_id not in clear_tracks | set(capped): - self.log.warning(f"Server CDM returned no content keys for track {track.id}") + from unshackle.core.api.progress import track_log_label + + self.log.warning(f"Server CDM returned no content keys for track {track_log_label(track)}") continue named = {kid.hex for drm in track.drm or [] for kid in real_kids(drm)} & track_keys.keys() @@ -1964,7 +1969,9 @@ class RemoteService: drm_class = other track.drm_preference = drm_class.lower() self.client_licensed.add(str(track.id)) - self.log.info(f"{why}; licensing {track.id} with your own {drm_class} device") + from unshackle.core.api.progress import track_log_label + + self.log.info(f"{why}; licensing track {track_log_label(track)} with your own {drm_class} device") @property def server_cdm(self) -> bool: @@ -1995,7 +2002,7 @@ class RemoteService: lambda sid: self.client.post_optional(f"/api/session/{sid}/keys/bad", {"kid": kid.hex, "key": key}) ) except (Exception, RemoteError) as e: - self.log.warning(f"Could not report the bad content key to the server: {e!r}") + self.log.warning(f"Could not report the bad content key to the server: {e}") @staticmethod def create_drm_stub(drm_type: str, kid_hexes: list[str]) -> Any: @@ -2085,6 +2092,7 @@ class RemoteService: return base64.b64decode(resp["license"]) if resp.get("license") else None def proxy_license(self, challenge: Union[bytes, str], track: AnyTrack, drm_type: str) -> bytes: + """Relay a licence challenge to the server. A failed relay raises ClickException, so dl's licence fallbacks see it.""" if isinstance(challenge, str): challenge = challenge.encode("utf-8") @@ -2146,6 +2154,8 @@ class RemoteService: f"/api/session/{sid}/license", {**payload, "track_id": self.server_track_id(track.id)} ) ) + except RemoteError as e: + raise click.ClickException(e.message) from None finally: self.drain_server_logs() return base64.b64decode(resp["license"])