From 1d61e859e6f8d83df67f354ac1af06588b337352 Mon Sep 17 00:00:00 2001 From: Anatolii Date: Tue, 21 Jul 2026 13:09:28 +0400 Subject: [PATCH] =?UTF-8?q?fix(sdk):=20read=20approval=5Ftimeout=5Fseconds?= =?UTF-8?q?=20from=20/gate=20response=20(=D0=A0=D0=B0=D0=B7=D1=80=D1=8B?= =?UTF-8?q?=D0=B2=201c=20SDK=20sync)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Backend commit 0ad03b9 (Разрыв 1c, gate hot-path trigger) added `approval_timeout_seconds: Option` and `approval_expires_at: Option` to the GateResponse wire format. Before this SDK fix, the approval wait path used `NULLRUN_APPROVAL_TIMEOUT_SECONDS` env default (default 300s) as the ONLY source of wait duration — which is exactly the Разрыв 3 class of bug that the backend sweeper was written to prevent on the backend side. Concretely: a backend approval rule configured with `expires_in_seconds=20` (short-approval use case) would have the backend's expiry sweeper close the row at 20s, but the SDK would have timed out the parked gate call at 300s — a silent desync. The 300s/300s coincidence worked only because no UI-1 yet exists to set non-default expirations, and because the env default matched the backend default. This commit closes the SDK side of the Разрыв 1c contract: ## Changes ### `_wait_for_approval_resolution` (runtime.py:1225) New optional kwarg `timeout_seconds: float | None = None`: - When set to a positive number, used as the event.wait() timeout (server-authoritative, takes precedence over the env default). - When `None` (legacy backend without Разрыв 1c field, or malformed response), falls back to `self._approval_timeout_seconds` (the env default) — pre-Разрыв 1c behaviour preserved. - When set to a non-positive number (0 or negative), also falls back to env default; we explicitly reject these because `event.wait(timeout=0)` deadlocks on the very first call. The effective timeout is also stored on the pending entry as `entry["timeout_seconds"]` so callers / tests can inspect which value actually drove the wait. When the server value diverges from the env default, a DEBUG log line is emitted ("approval {id}: using server timeout={X}s (env default would have been {Y}s)") so an operator inspecting logs can see which value actually drove the wait — useful for diagnosing 'why did this approval time out earlier than I configured' tickets. ### `check_workflow_budget` (runtime.py:1611) Reads `response["approval_timeout_seconds"]` (server value), validates the type (must be a number) and sign (must be positive), and falls back to `None` (which then triggers env-default in _wait_for_approval_resolution) on any validation failure. The existing env-default path is preserved as the explicit fallback contract. `approval_expires_at` is intentionally not parsed in the SDK: the field is documented as informational (UI/logs) and isn't required for the SDK's wait math. If a future backend draft sends only the ISO8601 string, the SDK will fall through to the env default — same behaviour as the field being absent. The approval-required INFO log line now includes which timeout drove the wait ("env-default" vs the server value) for diagnostic visibility. ## Tests (6 new in tests/test_approval_timeout_field.py) - `test_server_timeout_used_when_response_has_valid_value`: server timeout=15s is stored on the entry, env default 300s is NOT used. - `test_env_fallback_when_response_omits_field`: pre-Разрыв 1c behaviour preserved when server sends no timeout field. - `test_env_fallback_when_server_value_is_zero`: 0/0.0/-1/-100.0 all fall back to env default (regression guard against the `event.wait(timeout=0)` deadlock footgun). - `test_env_fallback_when_server_value_is_non_numeric`: pre- validated None falls back to env default. - `test_timeout_sentinel_returned_when_no_ws_push`: timeout fires at the SERVER timeout, not the env default (0.1s server, 300s env, 300s timeout would mean a 5-min test run). - `test_diverging_server_value_logs_at_debug`: caplog captures the 'using server timeout=Xs (env default would have been Ys)' DEBUG line when values diverge. ## Verification ``` pytest tests/test_approval_timeout_field.py → 6 passed pytest -n auto --cov=src/nullrun --cov-branch --cov-report=xml --cov-fail-under=0 → 1243 passed, 7 skipped, 28 warnings in 34.44s (coverage 80.92%) ``` No public API change (new optional kwarg, backward compatible). No SDK_MIN_VERSION bump. No on-wire change. ## SDK release note (for CHANGELOG.md follow-up) When the SDK version is bumped, add: ``` ### Fixed - approval wait: SDK now uses server-authoritative `approval_timeout_seconds` from the /gate response when available, falling back to `NULLRUN_APPROVAL_TIMEOUT_SECONDS` env default only on missing/non-positive/non-numeric values (Разрыв 1c SDK sync; matches backend commit 0ad03b9). ``` (CHANGELOG.md edit deferred to release PR — this commit is behaviour-only.) --- src/nullrun/runtime.py | 121 ++++++++++-- tests/test_approval_timeout_field.py | 282 +++++++++++++++++++++++++++ 2 files changed, 385 insertions(+), 18 deletions(-) create mode 100644 tests/test_approval_timeout_field.py diff --git a/src/nullrun/runtime.py b/src/nullrun/runtime.py index 65f4e5c..12cefc1 100644 --- a/src/nullrun/runtime.py +++ b/src/nullrun/runtime.py @@ -1227,17 +1227,31 @@ def _wait_for_approval_resolution( approval_id: str, workflow_id: str, execution_id: str, + timeout_seconds: float | None = None, ) -> dict[str, Any]: - """Drift section 7 (2026-07-06): block the calling thread - until the WS approval push arrives (or the per-approval - timeout elapses). The WS handler - (``_handle_approval_resolved`` above) sets the threading - Event when the push lands; this method waits on it. + """Drift section 7 (2026-07-06) + Разрыв 1c (2026-07-21): + block the calling thread until the WS approval push + arrives (or the per-approval timeout elapses). The WS + handler (``_handle_approval_resolved`` above) sets the + threading Event when the push lands; this method waits + on it. Args: approval_id: The approval id from the /gate response. workflow_id: Workflow the approval gates. execution_id: Execution the approval gates. + timeout_seconds: Server-authoritative wait duration + from the /gate response field + ``approval_timeout_seconds`` (added in Разрыв 1c, + 2026-07-21). When set, this overrides + ``self._approval_timeout_seconds`` (the + ``NULLRUN_APPROVAL_TIMEOUT_SECONDS`` env + default) so the SDK can never silently desync + from the backend row's actual expiry. When + ``None`` (legacy backend without Разрыв 1c + field, or malformed response), falls back to the + env-derived default — same behavior as pre-Разрыв + 1c SDKs. Returns: The entry dict, with ``outcome`` populated (either @@ -1252,24 +1266,55 @@ def _wait_for_approval_resolution( (raise WorkflowKilledInterrupt on denied, resume on approved, fall back to poll on timeout). """ + # Per-approval timeout resolution (Разрыв 1c, 2026-07-21): + # prefer the server-authoritative value from the /gate + # response so the SDK never times out before the + # backend's expiry sweeper (Разрыв 3 class of bug). + # Fall back to the env default only on missing or + # non-positive value — both signal "backend didn't send + # the field" and we preserve the pre-Разрыв 1c behaviour. + effective_timeout = ( + timeout_seconds + if (timeout_seconds is not None and timeout_seconds > 0) + else self._approval_timeout_seconds + ) + if ( + timeout_seconds is not None + and timeout_seconds > 0 + and timeout_seconds != self._approval_timeout_seconds + ): + # Log when the server value diverges from the env + # default so an operator inspecting logs can see + # which value actually drove the wait — useful for + # diagnosing "why did this approval time out + # earlier than I configured" tickets. + logger.debug( + "approval %s: using server timeout=%.1fs " + "(env default would have been %.1fs)", + approval_id, + effective_timeout, + self._approval_timeout_seconds, + ) + event = threading.Event() entry: dict[str, Any] = { "approval_id": approval_id, "workflow_id": workflow_id, "execution_id": execution_id, "event": event, + "timeout_seconds": effective_timeout, } with self._approval_lock: self._approval_pending[approval_id] = entry try: - signaled = event.wait(timeout=self._approval_timeout_seconds) + signaled = event.wait(timeout=effective_timeout) if not signaled: logger.warning( "approval %s: WS push silent for %.1fs -- " "falling back to /status poll", approval_id, - self._approval_timeout_seconds, + effective_timeout, ) with self._approval_lock: self._approval_pending.pop(approval_id, None) @@ -1609,16 +1654,26 @@ def check_workflow_budget(self) -> None: ) if decision == "require_approval": - # Drift section 7 (2026-07-06): the gate requires a - # human-approval before the call may proceed. Block - # the calling thread on the WS push (handled in - # _handle_approval_resolved) and let the operator - # click Approve/Deny on the dashboard. On timeout - # (WS push silent for the configured - # _approval_timeout_seconds) we fall through and - # the caller is expected to treat the call as - # blocked -- the same fail-CLOSED semantics as a - # regular block. + # Drift section 7 (2026-07-06) + Разрыв 1c (2026-07-21): + # the gate requires a human-approval before the call + # may proceed. Block the calling thread on the WS push + # (handled in _handle_approval_resolved) and let the + # operator click Approve/Deny on the dashboard. On + # timeout (WS push silent for the configured duration) + # we fall through and the caller is expected to treat + # the call as blocked — the same fail-CLOSED semantics + # as a regular block. + # + # Разрыв 1c: prefer the server-authoritative + # `approval_timeout_seconds` value from the response + # (added in commit 0ad03b9) over the env default + # `NULLRUN_APPROVAL_TIMEOUT_SECONDS`. This prevents the + # SDK/backend desync that the Разрыв 3 sweeper was + # written to fix on the backend side. We fall back to + # the env default only when the field is missing or + # non-positive — both signal "backend without Разрыв 1c + # field" and we preserve the pre-Разрыв 1c behaviour + # for those callers. approval_id = response.get("approval_id", "") or "" if not approval_id: logger.warning( @@ -1628,13 +1683,43 @@ def check_workflow_budget(self) -> None: workflow_id=workflow_id, reason="approval_id missing in require_approval response", ) + # Read the per-approval timeout from the response. Both + # `approval_timeout_seconds` (i64) and + # `approval_expires_at` (ISO8601 string) are exposed; + # we prefer the integer field because it's directly + # usable in `event.wait(timeout=...)`. If the backend + # only sent the ISO8601 string (e.g. older Разрыв 1c + # draft or proxy rewriting the field), fall through to + # the env default rather than try to parse it inline — + # the field is documented as informational for UI/logs + # and isn't required for the SDK's wait math. + server_timeout = response.get("approval_timeout_seconds") + if server_timeout is not None: + try: + server_timeout = float(server_timeout) + except (TypeError, ValueError): + logger.warning( + "check_workflow_budget: approval_timeout_seconds=%r " + "is not a number; falling back to env default", + response.get("approval_timeout_seconds"), + ) + server_timeout = None + if server_timeout is not None and server_timeout <= 0: + logger.warning( + "check_workflow_budget: approval_timeout_seconds=%r " + "is non-positive; falling back to env default", + server_timeout, + ) + server_timeout = None logger.info( - f"check_workflow_budget: require_approval id={approval_id} -- waiting for WS push" + f"check_workflow_budget: require_approval id={approval_id} -- " + f"waiting for WS push (timeout={server_timeout if server_timeout is not None else 'env-default'})" ) result = self._wait_for_approval_resolution( approval_id=approval_id, workflow_id=workflow_id, execution_id=str(self.organization_id or "local"), + timeout_seconds=server_timeout, ) outcome = (result.get("outcome") or "").lower() if outcome == "approved": diff --git a/tests/test_approval_timeout_field.py b/tests/test_approval_timeout_field.py new file mode 100644 index 0000000..b1e495a --- /dev/null +++ b/tests/test_approval_timeout_field.py @@ -0,0 +1,282 @@ +""" +Разрыв 1c (2026-07-21) — SDK reads `approval_timeout_seconds` +from the /gate response, not its own env default. + +До этой правки SDK использовал `NULLRUN_APPROVAL_TIMEOUT_SECONDS` +env default (300s) как единственный источник wait duration. Если +backend row имел другой `expires_in_seconds` (например, 20s для +коротких approval-правил или 1800s для длинных), SDK timeout'ил +раньше или позже чем backend sweeper — exactly the Разрыв 3 desync +class of bug. + +Backend commit 0ad03b9 добавил `approval_timeout_seconds: Option` +поле в `GateResponse`. SDK теперь: +- prefers `response["approval_timeout_seconds"]` (server-authoritative) +- falls back to env default только когда поле отсутствует/невалидно + +Тесты ниже пинят этот контракт: при валидном server timeout +используется он, при отсутствующем — env default, при +невалидном — env default + WARN log. + +# Test mechanics (Разрыв 1c, 2026-07-21) + +`_wait_for_approval_resolution` creates a NEW `threading.Event()` +inside the function and waits on it. Pre-setting an event from +the outside does not work — the function replaces it. The only +way to release the wait from a test is to call +`_handle_approval_resolved` (the WS push handler), which pops +the pending entry AND sets the event. We exercise this in +every test below: register entry, start a thread that calls +the wait, then from the main thread call +`_handle_approval_resolved` to release. +""" + +from __future__ import annotations + +import os +import threading +import time +from typing import Any + +import pytest + +from nullrun.runtime import NullRunRuntime + + +def _make_runtime(env_timeout: float | None) -> NullRunRuntime: + """Build a runtime with a specific env default timeout. + + Mirrors the `_test_mode=True` pattern from + test_init_contract.py — skips auth but lets us exercise the + approval wait path without a real backend. + """ + if env_timeout is None: + os.environ.pop("NULLRUN_APPROVAL_TIMEOUT_SECONDS", None) + else: + os.environ["NULLRUN_APPROVAL_TIMEOUT_SECONDS"] = str(env_timeout) + return NullRunRuntime( + api_key="test-key-razriv1c-12345678", + _test_mode=True, + polling=False, + ) + + +def _run_wait_and_release( + rt: NullRunRuntime, + approval_id: str, + timeout_seconds: float | None, + release_after_ms: int = 50, + outcome: str = "approved", +) -> dict[str, Any]: + """Spawn a thread that calls _wait_for_approval_resolution; + from the main thread, simulate the WS push by calling + _handle_approval_resolved after ``release_after_ms`` ms. + + Returns the entry dict (with ``outcome`` populated) if the + wait released on the signal, or a ``{timed_out: True, ...}`` + sentinel if the timeout fired first. + """ + result_box: dict[str, Any] = {} + + def target() -> None: + result_box["result"] = rt._wait_for_approval_resolution( + approval_id=approval_id, + workflow_id="wf-1", + execution_id="exec-1", + timeout_seconds=timeout_seconds, + ) + + t = threading.Thread(target=target, daemon=True) + started = time.monotonic() + t.start() + # Release the wait via the WS push handler. This is what + # would happen in production when the operator clicks + # Approve/Deny on the dashboard. + time.sleep(release_after_ms / 1000.0) + rt._handle_approval_resolved( + { + "approval_id": approval_id, + "outcome": outcome, + "note": "test release", + "resolved_at": 1700000000, + } + ) + t.join(timeout=5.0) + result_box["elapsed"] = time.monotonic() - started + return result_box + + +def _run_wait_and_timeout( + rt: NullRunRuntime, + approval_id: str, + timeout_seconds: float | None, +) -> dict[str, Any]: + """Spawn a thread that calls _wait_for_approval_resolution; + do NOT release the event — let the timeout fire.""" + result_box: dict[str, Any] = {} + + def target() -> None: + result_box["result"] = rt._wait_for_approval_resolution( + approval_id=approval_id, + workflow_id="wf-1", + execution_id="exec-1", + timeout_seconds=timeout_seconds, + ) + + t = threading.Thread(target=target, daemon=True) + started = time.monotonic() + t.start() + t.join(timeout=5.0) + result_box["elapsed"] = time.monotonic() - started + return result_box + + +class TestApprovalTimeoutResolution: + """Pin the Разрыв 1c contract: server timeout wins, env is fallback.""" + + def test_server_timeout_used_when_response_has_valid_value(self): + """DoD #1: server-supplied timeout=15s is the value passed + to event.wait(), NOT the env default 300s. We assert by + releasing the event and checking the entry's stored + timeout_seconds field — this is what `_wait_for_approval_resolution` + would have passed to event.wait(). + """ + rt = _make_runtime(env_timeout=300.0) + try: + assert rt._approval_timeout_seconds == 300.0 + + result_box = _run_wait_and_release( + rt, "appr-server-15", timeout_seconds=15.0, + release_after_ms=50, + ) + + assert result_box.get("result") is not None + assert result_box["result"].get("outcome") == "approved", ( + "wait should have released on the WS push, not timed out" + ) + assert result_box["result"]["timeout_seconds"] == 15.0, ( + "Разрыв 1c: server timeout (15s) must be stored on the " + f"entry; got {result_box['result']['timeout_seconds']}" + ) + # Sanity: the wait did NOT consume 15s. + assert result_box["elapsed"] < 1.0, ( + f"wait took {result_box['elapsed']:.2f}s; expected near-instant" + ) + finally: + rt.shutdown(flush=False) + + def test_env_fallback_when_response_omits_field(self): + """DoD #2 (regression): legacy /gate response WITHOUT + approval_timeout_seconds -> SDK falls back to env default. + """ + rt = _make_runtime(env_timeout=42.0) + try: + assert rt._approval_timeout_seconds == 42.0 + + result_box = _run_wait_and_release( + rt, "appr-legacy", timeout_seconds=None, + release_after_ms=50, + ) + + assert result_box.get("result") is not None + assert result_box["result"]["timeout_seconds"] == 42.0, ( + "Missing server timeout must fall back to env default; " + f"got {result_box['result']['timeout_seconds']}" + ) + finally: + rt.shutdown(flush=False) + + def test_env_fallback_when_server_value_is_zero(self): + """DoD #3 (regression): response with + approval_timeout_seconds=0 or negative -> treat as + "missing" and fall back. A zero would deadlock the SDK + on the very first event.wait(), so we explicitly reject + non-positive values. + """ + rt = _make_runtime(env_timeout=120.0) + try: + for bad_value in (0, 0.0, -1, -100.0): + result_box = _run_wait_and_release( + rt, "appr-zero", timeout_seconds=bad_value, + release_after_ms=50, + ) + assert result_box.get("result") is not None + assert result_box["result"]["timeout_seconds"] == 120.0, ( + f"Non-positive server timeout ({bad_value}) must fall " + f"back to env default 120; got " + f"{result_box['result']['timeout_seconds']}" + ) + finally: + rt.shutdown(flush=False) + + def test_env_fallback_when_server_value_is_non_numeric(self): + """DoD #4: malformed server value -> fall back to env + default. The check_workflow_budget caller in + runtime.py:1710-1718 logs a warning and sets + server_timeout=None before calling + _wait_for_approval_resolution; this test pins that + contract from the callee side. + """ + rt = _make_runtime(env_timeout=90.0) + try: + result_box = _run_wait_and_release( + rt, "appr-bad", timeout_seconds=None, # pre-validated to None + release_after_ms=50, + ) + assert result_box["result"]["timeout_seconds"] == 90.0 + finally: + rt.shutdown(flush=False) + + def test_timeout_sentinel_returned_when_no_ws_push(self): + """Regression: when the WS push never arrives, the wait + hits the timeout and returns the ``{outcome: 'timeout', + timed_out: True}`` sentinel — NOT raise, NOT block + forever. The test verifies that with a small + server_timeout (0.1s) and NO release, the function + returns the sentinel within ~0.1s + overhead. Note that + the timeout sentinel does NOT carry `timeout_seconds` + (it's a fresh dict, not the entry) — only `outcome`, + `timed_out`, `approval_id`. + """ + rt = _make_runtime(env_timeout=300.0) + try: + result_box = _run_wait_and_timeout( + rt, "appr-silent", timeout_seconds=0.1, + ) + assert result_box.get("result") is not None + assert result_box["result"]["outcome"] == "timeout" + assert result_box["result"]["timed_out"] is True + assert result_box["result"]["approval_id"] == "appr-silent" + # Sanity: the wait elapsed near the configured 0.1s, + # not the env default 300s — proving the server + # timeout was the one passed to event.wait(). + assert 0.05 < result_box["elapsed"] < 1.0, ( + f"timeout took {result_box['elapsed']:.2f}s; " + "expected near 0.1s (server timeout), not 300s (env)" + ) + finally: + rt.shutdown(flush=False) + + def test_diverging_server_value_logs_at_debug(self, caplog): + """When the server timeout diverges from the env + default, _wait_for_approval_resolution logs a DEBUG + line so an operator inspecting logs can see which value + drove the wait. + """ + rt = _make_runtime(env_timeout=300.0) + try: + with caplog.at_level("DEBUG", logger="nullrun.runtime"): + _run_wait_and_release( + rt, "appr-debug", timeout_seconds=15.0, + release_after_ms=50, + ) + debug_messages = [ + r.message for r in caplog.records + if r.levelname == "DEBUG" and "using server timeout" in r.message + ] + assert len(debug_messages) >= 1, ( + "Разрыв 1c: diverging server timeout should emit a DEBUG log. " + f"Got caplog records: {[r.message for r in caplog.records]}" + ) + finally: + rt.shutdown(flush=False)