diff --git a/tests/core/test_licence_turns.py b/tests/core/test_licence_turns.py index bf61235b..ba2fd9dd 100644 --- a/tests/core/test_licence_turns.py +++ b/tests/core/test_licence_turns.py @@ -200,11 +200,30 @@ def test_vaults_only_stops_at_the_first_kid_no_vault_holds(cmd: dl, licences: li 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") +def refuse_licence(self: Widevine, **_: Any) -> None: + raise click.ClickException("Licence request failed") - monkeypatch.setattr(Widevine, "get_content_keys", refuse) + +def test_a_refused_licence_without_the_track_key_reports_the_licence_error( + cmd: dl, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture +) -> None: + monkeypatch.setattr(Widevine, "get_content_keys", refuse_licence) + monkeypatch.setattr(dl, "LICENSE_KEY_CACHE", {KID_B: KEYS[KID_B]}) + monkeypatch.setattr(dl, "DRM_LOCKS", {}) + table = new_table() + + with pytest.raises(click.ClickException, match="^Licence request failed$"): + prepare(cmd, widevine(KID_A, KID_B), KID_A, table) + + assert not [r for r in caplog.records if r.levelname == "WARNING"] + tree = list(table.columns[0].cells)[-1] + assert "Licence request failed" in str(tree.children[-1].label) + + +def test_a_refused_licence_keeps_the_known_track_key( + cmd: dl, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture +) -> None: + monkeypatch.setattr(Widevine, "get_content_keys", refuse_licence) monkeypatch.setattr(dl, "LICENSE_KEY_CACHE", {KID_A: KEYS[KID_A]}) monkeypatch.setattr(dl, "DRM_LOCKS", {}) drm = widevine(KID_A, KID_B) @@ -212,3 +231,6 @@ def test_a_refused_licence_keeps_the_known_track_key(cmd: dl, monkeypatch: pytes prepare(cmd, drm, KID_A, new_table()) assert drm.content_keys == {KID_A: KEYS[KID_A]} + assert [r.getMessage() for r in caplog.records if r.levelname == "WARNING"] == [ + "Licence failed, using the 1 known key(s): Licence request failed" + ] diff --git a/tests/remote/unit/test_remote_relay.py b/tests/remote/unit/test_remote_relay.py index aee8ba71..351a9f9d 100644 --- a/tests/remote/unit/test_remote_relay.py +++ b/tests/remote/unit/test_remote_relay.py @@ -169,6 +169,32 @@ def test_remote_error_carries_its_reason_and_exits_a_cli_run(): assert not remote_service.RemoteError("Server error [NOT_FOUND]: no title", "NOT_FOUND").session_broke +def test_quiet_mutes_a_remote_error_the_caller_reports(caplog): + with caplog.at_level("DEBUG", logger="remote_service"), remote_service.quiet(): + with remote_service.quiet(): + remote_service.RemoteError("Server error [SERVICE_ERROR]: refused", "SERVICE_ERROR") + remote_service.RemoteError("Remote auth failed: bad key", "AUTH") + remote_service.RemoteError("Server error [NOT_FOUND]: outside", "NOT_FOUND") + + assert [(r.levelname, r.getMessage()) for r in caplog.records] == [ + ("DEBUG", "Server error [SERVICE_ERROR]: refused"), + ("DEBUG", "Remote auth failed: bad key"), + ("ERROR", "Server error [NOT_FOUND]: outside"), + ] + + +def test_an_unreachable_server_list_logs_one_warning(monkeypatch, caplog): + class Down: + def get(self, endpoint): + raise remote_service.RemoteError("Could not connect to remote server at http://srv", "CONNECT") + + monkeypatch.setattr(remote_service, "remote_client", lambda name: Down()) + monkeypatch.setattr(remote_service, "_remote_lists", {}) + + assert remote_service.remote_service_list("down") is None + assert [r.levelname for r in caplog.records if r.levelname in ("WARNING", "ERROR")] == ["WARNING"] + + def test_a_geofenced_remote_service_gets_its_first_allowed_region_as_proxy(monkeypatch): monkeypatch.setattr(handlers, "server_proxy_allowed", lambda request=None: True) fenced = {"tag": "EXAMPLE", "geofence": ["US", "ca"], "geoblock": ["us"]} 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 a41137fa..80302d48 100644 --- a/tests/remote/unit/test_remote_service_server_cdm_license.py +++ b/tests/remote/unit/test_remote_service_server_cdm_license.py @@ -98,7 +98,7 @@ def test_proxy_mode_keeps_the_callers_type(): assert svc.client.posts[0]["pssh"] == "PR" -def test_a_refused_relayed_licence_raises_a_click_exception_with_the_server_message(): +def test_a_refused_relayed_licence_raises_a_click_exception_with_the_server_message(caplog): import click from unshackle.core.remote_service import RemoteError @@ -115,3 +115,20 @@ def test_a_refused_relayed_licence_raises_a_click_exception_with_the_server_mess with pytest.raises(click.ClickException, match="^Licence request failed: refused$"): svc.proxy_license(b"chal", track, "playready") + + assert not [r for r in caplog.records if r.levelname == "ERROR"] + + +def test_a_refused_server_cdm_licence_logs_one_warning(caplog): + from unshackle.core.remote_service import RemoteError + + svc = _service("widevine", {}) + + def refuse(endpoint, payload, expect=()): + raise RemoteError("Server error [SERVICE_ERROR]: refused", "SERVICE_ERROR") + + svc.client.post = refuse + track = SimpleNamespace(id="vid", drm=[_Widevine()]) + + assert svc.proxy_license(b"chal", track, "widevine") == b"chal" + assert [r.levelname for r in caplog.records if r.levelname in ("WARNING", "ERROR")] == ["WARNING"] diff --git a/tests/remote/unit/test_session_reopen.py b/tests/remote/unit/test_session_reopen.py index 0d89fea7..8af1a572 100644 --- a/tests/remote/unit/test_session_reopen.py +++ b/tests/remote/unit/test_session_reopen.py @@ -11,7 +11,7 @@ import requests import responses from langcodes import Language -from unshackle.core.remote_service import RemoteClient, RemoteError, RemoteService, build_title +from unshackle.core.remote_service import RemoteClient, RemoteError, RemoteService, build_title, quiet from unshackle.core.tracks import Audio from unshackle.core.tracks.track import Track @@ -124,3 +124,31 @@ def test_a_gateway_error_page_counts_as_an_unreachable_server(): client.get("/api/session/s1/titles") assert exc.value.kind == "CONNECT" + + +def fail_reopen(session_id, kind): + raise RemoteError("Server error [NOT_FOUND]: no title", "NOT_FOUND") + + +@pytest.mark.parametrize("recover", [lambda session_id, kind: False, fail_reopen], ids=["lost", "reopen-failed"]) +@responses.activate +def test_a_session_lost_under_quiet_is_left_to_the_caller(monkeypatch, caplog, recover): + service = make_service() + monkeypatch.setattr(service, "recover", recover) + responses.add(responses.POST, f"{SERVER}/api/session/s1/license", json=GONE, status=404) + + with quiet(), pytest.raises(RemoteError): + license_call(service, audio("a-old")) + + assert not [r for r in caplog.records if r.levelname == "ERROR"] + + +@responses.activate +def test_closing_a_session_the_server_lost_logs_no_error(caplog): + service = make_service() + responses.add(responses.DELETE, f"{SERVER}/api/session/s1", json=GONE, status=404) + + service.close() + + assert service._session_id is None + assert not [r for r in caplog.records if r.levelname in ("WARNING", "ERROR")] diff --git a/unshackle/commands/dl.py b/unshackle/commands/dl.py index 35af97fd..ea7d6865 100644 --- a/unshackle/commands/dl.py +++ b/unshackle/commands/dl.py @@ -146,7 +146,7 @@ from unshackle.core.utils.click_types import ( from unshackle.core.utils.collections import ci_get, merge_dict from unshackle.core.utils.hdr10plus import probed_tracks from unshackle.core.utils.post_scripts import NO_POST_SCRIPTS, build_context, dispatch, season_context -from unshackle.core.utils.redact import mask_proxy +from unshackle.core.utils.redact import mask_proxy, redact_secrets from unshackle.core.utils.selector import select_multiple from unshackle.core.utils.subprocess import ffmpeg_decodes, ffprobe, run_step from unshackle.core.vault import Vault @@ -5082,8 +5082,10 @@ class dl: try: get_keys() except Exception as e: - if drm.content_keys: - self.log.debug(f"License call failed but keys already in content_keys: {e}") + if drm.content_keys and (not track_kid or track_kid in drm.content_keys): + self.log.warning( + f"Licence failed, using the {len(drm.content_keys)} known key(s): {redact_secrets(str(e))}" + ) else: if isinstance(e, (drm.Exceptions.EmptyLicense, drm.Exceptions.CEKNotFound)): msg = str(e) diff --git a/unshackle/core/remote_service.py b/unshackle/core/remote_service.py index ae0f4010..6aa76d87 100644 --- a/unshackle/core/remote_service.py +++ b/unshackle/core/remote_service.py @@ -77,7 +77,15 @@ RATE_LIMIT_TRIES = 3 TUNNEL_SLOT_POLL = 15 REOPEN_WAIT = 1800.0 # seconds a lost session waits for its server to come back; covers a deploy's whole drain -_recovering = local() + +class _Mute(local): + """This thread's RemoteError log state: inside ``session_call`` (``recovering``) and under ``quiet()``.""" + + recovering = False + quiet = False + + +_mute = _Mute() T = TypeVar("T") @@ -85,11 +93,22 @@ T = TypeVar("T") @contextlib.contextmanager def recovering() -> Iterator[None]: """Mark this thread's remote calls as recoverable, so a RECOVERABLE error logs at debug level.""" - _recovering.on = True + _mute.recovering = True try: yield finally: - _recovering.on = False + _mute.recovering = False + + +@contextlib.contextmanager +def quiet() -> Iterator[None]: + """Log this thread's RemoteErrors at debug level, because the caller reports them.""" + before = _mute.quiet + _mute.quiet = True + try: + yield + finally: + _mute.quiet = before def redact_secrets(text: str, data: Optional[Dict[str, Any]] = None) -> str: @@ -127,8 +146,8 @@ class RemoteError(SystemExit): super().__init__(1) self.message = message self.kind = kind - quiet = getattr(_recovering, "on", False) and kind in RECOVERABLE - (log.debug if quiet else log.error)(message) + muted = _mute.quiet or (_mute.recovering and kind in RECOVERABLE) + (log.debug if muted else log.error)(message) def __str__(self) -> str: return self.message @@ -744,7 +763,8 @@ def remote_service_list(server_name: Optional[str]) -> Optional[list[dict]]: return hit[1] services: Optional[list[dict]] = None try: - services = remote_client(server_name).get("/api/services").get("services") or [] + with quiet(): + services = remote_client(server_name).get("/api/services").get("services") or [] except (Exception, SystemExit) as e: log.warning(f"Could not list the services of remote server '{server_name}': {e}") _remote_lists[server_name] = (time.monotonic(), services) @@ -1463,7 +1483,7 @@ class RemoteService: def session_call(self, call: Callable[[Optional[str]], T]) -> T: """Run ``call`` with the session id, and once more on a new session when the server lost the old one.""" session_id = self._session_id - if getattr(_recovering, "on", False): + if _mute.recovering: return call(session_id) try: with recovering(): @@ -1473,7 +1493,8 @@ class RemoteService: raise lost = e if not self.recover(session_id, lost.kind): - log.error(lost.message) + if not _mute.quiet: + log.error(lost.message) raise lost return call(self._session_id) @@ -1595,7 +1616,8 @@ class RemoteService: return with self._log_drain_lock: try: - resp = self.client.get_optional(f"/api/session/{self._session_id}/logs?since={self._log_seq}") + with quiet(): + resp = self.client.get_optional(f"/api/session/{self._session_id}/logs?since={self._log_seq}") except (Exception, SystemExit): return if not resp: @@ -1704,7 +1726,8 @@ class RemoteService: try: call = self.client.session.get(url, timeout=30).json().get("cdm_call") if isinstance(call, dict): - self.answer_cdm_call(call, sessions) + with quiet(): + self.answer_cdm_call(call, sessions) except (requests.RequestException, ValueError, SystemExit) as e: self.log.debug(f"CDM call poll failed: {e}") self.close_cdm_sessions(sessions) @@ -1998,11 +2021,12 @@ class RemoteService: def report_bad_key(self, kid: UUID, key: str) -> None: """Tell the server a vault key it served did not decrypt, so it flags its own row.""" try: - self.session_call( - lambda sid: self.client.post_optional(f"/api/session/{sid}/keys/bad", {"kid": kid.hex, "key": key}) - ) + with quiet(): + self.session_call( + 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}") + self.log.debug(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: @@ -2112,13 +2136,14 @@ class RemoteService: if pssh_b64: try: request = {"drm_type": drm_type, "mode": "server_cdm", "pssh": pssh_b64} - resp = self.session_call( - lambda sid: self.client.post( - f"/api/session/{sid}/license", - {**request, "track_id": self.server_track_id(track.id)}, - expect=("SERVER_CDM_CAPPED",), + with quiet(): + resp = self.session_call( + lambda sid: self.client.post( + f"/api/session/{sid}/license", + {**request, "track_id": self.server_track_id(track.id)}, + expect=("SERVER_CDM_CAPPED",), + ) ) - ) if resp.get("error_code") == "SERVER_CDM_CAPPED": refusal = resp.get("details") or {} self.server_cdm_type = resp.get("drm_type", server_type) @@ -2149,11 +2174,12 @@ class RemoteService: payload["pssh"] = pssh_b64 try: - resp = self.session_call( - lambda sid: self.client.post( - f"/api/session/{sid}/license", {**payload, "track_id": self.server_track_id(track.id)} + with quiet(): + resp = self.session_call( + lambda sid: self.client.post( + 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: @@ -2182,7 +2208,8 @@ class RemoteService: session_id, self._session_id = self._session_id, None if session_id: try: - result = self.client.delete(f"/api/session/{session_id}") + with quiet(): + result = self.client.delete(f"/api/session/{session_id}") profile = self.ctx.parent.params.get("profile") if self.ctx.parent else None self.save_returned_cache(result.get("cache", {}), profile) except SystemExit: