diff --git a/src/api/analysis_summary.py b/src/api/analysis_summary.py index b47ea2d..662ceb9 100644 --- a/src/api/analysis_summary.py +++ b/src/api/analysis_summary.py @@ -38,7 +38,12 @@ VERDICT_INSTRUCTION, prompt_input, ) -from util.caller_token import TokenRejectedError, human_presence_reason, verify +from util.caller_token import ( + TokenRejectedError, + human_presence_detail, + human_presence_reason, + verify, +) from util.logging import logging from util.rate_limit import identity_of, limiter_from_env @@ -123,7 +128,14 @@ async def analysis_summary(body: SummaryRequest, request: Request) -> StreamingR # Stricter than the answer endpoint, and checked before any model call. presence = human_presence_reason(claims, time.time()) if presence: - return _refusal(presence, presence) + # The caller gets the coarse reason; the log gets the specific one, + # so an integrator's "we get no_human" is answerable by looking. + detail = ( + human_presence_detail(claims, time.time()) + if presence == "no_human" + else presence + ) + return _refusal(presence, detail) if body.disclosure not in IMPLEMENTED_TIERS: return _refusal("unsupported_tier", f"tier {body.disclosure} is not built") diff --git a/src/util/caller_token.py b/src/util/caller_token.py index 96a7493..7d697ab 100644 --- a/src/util/caller_token.py +++ b/src/util/caller_token.py @@ -172,6 +172,55 @@ def verify(token: str, verifying_key: str, *, audience: str | None = None) -> di HUMAN_MAX_AGE_SECONDS = 1800 +def human_presence_detail(claims: dict, now: float) -> str: + """Why the presence claim failed, **for our logs only**. + + The reason returned to the caller is deliberately coarse: `no_human` + whether the claim was absent, malformed or from the future, so this side + cannot be used to probe what a valid claim looks like. + + That coarseness has a cost, and it was paid on 2026-09-21. The website + hand-built a test claim using their cookie's internal field names + (`subject`, `solvedAt`) rather than the agreed JWT claims, got `no_human` + twice, and was one step from concluding this gate was rejecting their + valid tokens. + + Takes the same `now` as `human_presence_reason`, because the two must + agree about the present as well as about the causes. Two identical wrong answers read as a finding rather than + as one mistake made twice. + + So the distinction lives here, in the log, where an integrator's "we get + no_human" can be answered by looking rather than by guessing. Never put + this in the response. + """ + if "human" not in claims: + return "no `human` claim present" + if claims.get("human") is not True: + # Truncated: this is a signed claim so the value is the website's, + # but an unbounded repr in a log line is a bad habit to keep. + return f"`human` present but not true ({claims.get('human')!r:.80})" + if "human_iat" not in claims: + return "`human` true but no `human_iat`" + issued = claims.get("human_iat") + if not isinstance(issued, int | float) or isinstance(issued, bool): + return f"`human_iat` is not a number ({type(issued).__name__})" + # The same clock the reason used. Taking `time()` here instead was an + # inconsistency that only showed when a caller supplied a different + # `now` -- the two functions disagreeing about the present, in the + # function written to stop them disagreeing. + if int(issued) > int(now) + 60: + return "`human_iat` is in the future; clocks disagree" + # Reached only if `human_presence_reason` has grown a `no_human` branch + # this function does not know about. Saying so is the honest answer; the + # previous version returned the clock message as a catch-all, which would + # have sent an integrator confidently after the wrong cause -- the exact + # failure this whole function exists to prevent, one level in. + return ( + "no known cause matched; human_presence_detail is out of step with " + "human_presence_reason" + ) + + def human_presence_reason(claims: dict, now: float) -> str | None: """None when a person is vouched for; otherwise why not. diff --git a/tests/api/test_analysis_summary.py b/tests/api/test_analysis_summary.py index da2514f..54251f8 100644 --- a/tests/api/test_analysis_summary.py +++ b/tests/api/test_analysis_summary.py @@ -121,7 +121,9 @@ def _client(public_pem: str) -> TestClient: return TestClient(app) -def _token(private_pem: str, **claims: object) -> str: +def _token(private_pem: str, omit: tuple[str, ...] = (), **claims: object) -> str: + """`omit` removes a claim entirely, which is different from setting it to + None -- and the difference is the whole point of the absence cases.""" payload: dict[str, object] = { "iss": "reactome-website", "aud": DEFAULT_AUDIENCE, @@ -131,6 +133,8 @@ def _token(private_pem: str, **claims: object) -> str: "human_iat": int(time.time()) - 10, } payload.update(claims) + for key in omit: + payload.pop(key, None) return jwt.encode(payload, private_pem, algorithm="EdDSA") @@ -747,3 +751,42 @@ async def astream(self, messages: Any) -> AsyncIterator[Any]: # this assertion first passed review while testing nothing. assert "expression_columns" in prompt assert re.search(r'expression_columns\\?":\s*3', prompt), prompt[-200:] + + +@pytest.mark.parametrize( + ("omit", "claims", "expected_log"), + [ + # Absent, which is what the website's hand-built claim effectively + # was: they sent `subject` and `solvedAt`, so neither agreed claim + # was there at all. + (("human",), {}, "no `human` claim present"), + ((), {"human": "yes"}, "present but not true"), + (("human_iat",), {"human": True}, "no `human_iat`"), + ((), {"human": True, "human_iat": "solvedAt"}, "not a number"), + ], +) +def test_the_specific_presence_failure_is_logged_but_never_returned( + keys: tuple[str, str], + caplog: pytest.LogCaptureFixture, + omit: tuple[str, ...], + claims: dict[str, Any], + expected_log: str, +) -> None: + # The caller gets a coarse `no_human` whatever went wrong, so this side + # cannot be probed for what a valid claim looks like. The cost of that + # was paid on 2026-09-21: the website hand-built a claim with their + # cookie's field names, got `no_human` twice, and nearly concluded our + # gate was rejecting their valid tokens. + # + # So the distinction lives in the log. Both halves are asserted, because + # either alone is the bug: a coarse log is undiagnosable and a detailed + # response is a probe. + private, public = keys + with caplog.at_level("INFO", logger="api.analysis_summary"): + response = _post(public, caller_token=_token(private, omit=omit, **claims)) + + payload = _events(response.text)[-1][1] + assert payload["reason"] == "no_human" + logged = " ".join(r.getMessage() for r in caplog.records) + assert expected_log in logged, f"not diagnosable from the log: {logged}" + assert expected_log not in response.text, "the detail reached the caller" diff --git a/tests/util/test_caller_token.py b/tests/util/test_caller_token.py index 3fec656..df747e9 100644 --- a/tests/util/test_caller_token.py +++ b/tests/util/test_caller_token.py @@ -26,6 +26,8 @@ KEY_PATH_ENV, TokenRejectedError, expected_audience, + human_presence_detail, + human_presence_reason, load_verifying_key, verify, ) @@ -202,3 +204,57 @@ def test_the_key_is_read_from_the_configured_path( path = tmp_path / "public.pem" path.write_text(public_pem) assert load_verifying_key(str(path)).startswith("-----BEGIN PUBLIC KEY-----") + + +def test_every_no_human_cause_has_a_matching_detail() -> None: + """The two functions must agree on what produces `no_human`. + + They are separate, with nothing linking them. The detail function used to + end with the clock message as a catch-all, so a new `no_human` branch in + `human_presence_reason` would have been reported confidently as a clock + disagreement -- sending an integrator after the wrong cause, which is the + failure the detail exists to prevent. + + Enumerated rather than asserted in prose, so adding a cause without a + detail fails here. + """ + now = 1_700_000_000 + causes: list[dict[str, object]] = [ + {}, + {"human": False}, + {"human": "yes"}, + {"human": True}, + {"human": True, "human_iat": None}, + {"human": True, "human_iat": "solvedAt"}, + {"human": True, "human_iat": True}, + {"human": True, "human_iat": now + 3600}, + ] + for claims in causes: + assert human_presence_reason(claims, now) == "no_human", claims + detail = human_presence_detail(claims, now) + assert "out of step" not in detail, f"no detail for {claims}: {detail}" + + +def test_a_long_human_value_is_not_logged_whole() -> None: + # A signed claim, so the value is the website's -- but an unbounded repr + # in a log line is a habit worth not having. + detail = human_presence_detail({"human": "x" * 5000}, 1_700_000_000) + assert len(detail) < 200 + + +def test_the_detail_admits_when_it_has_no_cause_rather_than_inventing_one() -> None: + """Called on claims that are not a failure, it must say so. + + This is the guard the enumeration above cannot provide. That test checks + every *known* cause has a detail, which passes just as well if the + function ends with a plausible catch-all -- and a catch-all is exactly + the bug: a new `no_human` branch would then be reported confidently as + whatever the last line happens to say. + + A valid claim reaches the end of the function, so it is the one input + that distinguishes an honest fallback from a confident one. + """ + now = 1_700_000_000 + valid = {"human": True, "human_iat": now - 10} + assert human_presence_reason(valid, now) is None + assert "out of step" in human_presence_detail(valid, now)