fix(remote): report each handled remote error once, from the code that catches it

A caught RemoteError now logs at debug under quiet(); a recovered licence prints one warning, only when the track's own key is held.

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

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

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

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

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)

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: