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

@@ -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]}

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+"

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")

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"):

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)

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})
 

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)

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"])