From 978442aba25992c40fb7246995ef5e3e44ed90f8 Mon Sep 17 00:00:00 2001 From: Seongho Bae Date: Sat, 26 Sep 2026 10:36:29 +0900 Subject: [PATCH] fix(review): report the full orchestrator/free candidate trail on failure When every orchestrator/free candidate fails, Noema and Strix only see the gateway's final HTTP status, which is the last candidate's error. Noema run 36166447802 reported "HTTP 429 provider_capacity_unavailable" after 1041.5 s, yet its sidecar log shows six ready NVIDIA routes failing first (disconnect, 504, four unusable responses) and only the two deferred OpenRouter routes answering 429. Add scripts/ci/sidecar_route_trail.py, which reads the already-sanitized sidecar stderr log and prints one SIDECAR_CANDIDATE_TRAIL notice with every candidate of the last serving request in order, a bounded outcome label and elapsed seconds. noema-review.yml runs it in a failure-only step and strix.yml runs it before STRIX_PROVIDER_UNAVAILABLE, both from the trusted base copy and never failing the job. Gate verdicts, exit codes and transport-retry eligibility are unchanged. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01EAXNYEtrwwF5dLCZb7Bx2V --- .github/workflows/noema-review.yml | 9 + .github/workflows/strix.yml | 7 + .../20260926-sidecar-candidate-trail.md | 14 ++ scripts/ci/sidecar_route_trail.py | 164 ++++++++++++++++++ tests/test_sidecar_route_trail.py | 111 ++++++++++++ 5 files changed, 305 insertions(+) create mode 100644 CHANGELOG.d/20260926-sidecar-candidate-trail.md create mode 100644 scripts/ci/sidecar_route_trail.py create mode 100644 tests/test_sidecar_route_trail.py diff --git a/.github/workflows/noema-review.yml b/.github/workflows/noema-review.yml index 9be705a50c..593be74ff1 100644 --- a/.github/workflows/noema-review.yml +++ b/.github/workflows/noema-review.yml @@ -841,6 +841,15 @@ jobs: }' | gh api -X POST "repos/${TARGET_REPOSITORY}/dispatches" --input - echo "::notice::Scheduled Noema transport continuation re-dispatch for ${TARGET_REPOSITORY}#${PR_NUMBER} at ${EXPECTED_HEAD_SHA} (attempt ${NEXT_ATTEMPT})." + - name: Summarize contextual-orchestrator candidate trail on failure + # Diagnostic only: the gate sees just the last candidate's HTTP status. + if: failure() && env.PR_NUMBER != '' + run: | + trail_script="$GITHUB_WORKSPACE/scripts/ci/sidecar_route_trail.py" + if [ -f "$trail_script" ] && [ ! -L "$trail_script" ]; then + python3 "$trail_script" strix_runs/contextual-orchestrator-sidecar.stderr.log || true + fi + - name: Upload contextual-orchestrator sidecar evidence on failure if: failure() && env.PR_NUMBER != '' uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 diff --git a/.github/workflows/strix.yml b/.github/workflows/strix.yml index f15b29f564..c5c4ea5b5f 100644 --- a/.github/workflows/strix.yml +++ b/.github/workflows/strix.yml @@ -1032,6 +1032,13 @@ jobs: if ( grep -Eiq "$backend_unavailable_signal" "$strix_neutralization_scope_log" \ || grep -Eq "$model_behavior_error_signal" "$strix_neutralization_scope_log" ) \ && ! grep -Eiq "$reported_vulnerability_signal" "$strix_neutralization_scope_log"; then + # Diagnostic only: list every orchestrator/free candidate the last + # serving request tried, so the final status is not read as the cause. + trail_script="${TRUSTED_STRIX_SOURCE:-}/scripts/ci/sidecar_route_trail.py" + if [ -f "$trail_script" ] && [ ! -L "$trail_script" ]; then + python3 "$trail_script" \ + "${GITHUB_WORKSPACE:-.}/strix_runs/contextual-orchestrator-sidecar.stderr.log" || true + fi echo "::error title=STRIX_PROVIDER_UNAVAILABLE::Strix could not complete authoritative vulnerability analysis because its provider/backend was unavailable (rate limit, token cap, connection, warm-up, or model-behavior failure). See the strix-reports artifact and run log." exit "$strix_rc" fi diff --git a/CHANGELOG.d/20260926-sidecar-candidate-trail.md b/CHANGELOG.d/20260926-sidecar-candidate-trail.md new file mode 100644 index 0000000000..87582403d4 --- /dev/null +++ b/CHANGELOG.d/20260926-sidecar-candidate-trail.md @@ -0,0 +1,14 @@ +### Noema and Strix report the full orchestrator/free candidate trail on failure + +- New `scripts/ci/sidecar_route_trail.py` reads the already-sanitized sidecar stderr log and prints + one `SIDECAR_CANDIDATE_TRAIL` notice listing every candidate the last serving request tried, in + order, with a bounded outcome label (`http_`, `timeout`, `disconnect`, `invalid_response`) + and elapsed seconds. Noema run 36166447802 reported `HTTP 429 provider_capacity_unavailable` after + 1041.5 s, but its trail was: two NVIDIA gemma-4-31b routes (disconnect after 526.9 s, 504 after + 302.1 s), four NVIDIA llama/muse routes with unusable responses, and only then the two deferred + OpenRouter routes that answered 429. The gateway's final status reflects only the last candidate. +- `noema-review.yml` runs the summary in a failure-only step before the sidecar evidence upload; + `strix.yml` runs it just before `STRIX_PROVIDER_UNAVAILABLE`. Both call the trusted base copy, + skip a missing or symlinked script, and ignore its exit status. +- Diagnostic only: gate verdicts, exit codes, and the transport-retry eligibility derived from the + gateway HTTP status are unchanged. diff --git a/scripts/ci/sidecar_route_trail.py b/scripts/ci/sidecar_route_trail.py new file mode 100644 index 0000000000..bef7463e39 --- /dev/null +++ b/scripts/ci/sidecar_route_trail.py @@ -0,0 +1,164 @@ +"""Summarize the per-candidate trail of the last serving request in a sidecar log. + +When every ``orchestrator/free`` candidate fails, the review gate only sees the +gateway's final HTTP status -- the *last* candidate's error. On 2026-09-25 a +Noema run (Actions run 36166447802) reported ``HTTP 429 +provider_capacity_unavailable`` after 1041.5 s although six ready NVIDIA routes +had first failed with a disconnect, a 504 and four unusable responses; only the +two deferred OpenRouter routes tried last answered 429. This module reads the +already-sanitized sidecar stderr log and prints one annotation listing every +candidate the last serving request tried, in order, with its outcome and +elapsed time, so the final status is not mistaken for the dominant cause. + +It is diagnostic only: it never changes a gate verdict, exit status, or the +transport-retry eligibility the gate derives from the HTTP status. +""" + +from __future__ import annotations + +import re +import sys +from collections import Counter +from datetime import datetime +from pathlib import Path + +_LINE_RE = re.compile( + r"^(?P\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3}) (?P[a-z_]+) (?P.*)$" +) +_FIELD_RE = re.compile(r"(?P[a-z_]+)=(?P\S+)") +_AGENT_RE = re.compile(r"^[a-z][a-z0-9_]{0,127}$") +_REQUEST_ID_RE = re.compile(r"^[0-9a-f]{32}$") +_ERROR_TYPE_RE = re.compile(r"^[A-Za-z][A-Za-z0-9_]{0,63}$") +MAX_LISTED_CANDIDATES = 24 + + +def _parse_line(line: str) -> tuple[datetime, str, dict[str, str]] | None: + """Return ``(timestamp, event, fields)`` for a sidecar log line, else ``None``.""" + + match = _LINE_RE.match(line.strip()) + if match is None: + return None + timestamp = datetime.strptime(match["ts"], "%Y-%m-%d %H:%M:%S,%f") + fields = {m["key"]: m["value"] for m in _FIELD_RE.finditer(match["rest"])} + return timestamp, match["event"], fields + + +def _failure_outcome(fields: dict[str, str]) -> str: + """Classify one ``provider_attempt_failed`` line into a bounded outcome label.""" + + status = fields.get("provider_status", "") + if status.isdigit(): + return f"http_{status}" + error_type = fields.get("error_type", "") + if not _ERROR_TYPE_RE.match(error_type): + return "transport_error" + lowered = error_type.lower() + if "timeout" in lowered: + return "timeout" + if "disconnect" in lowered or "reset" in lowered: + return "disconnect" + return lowered + + +def summarize(lines: list[str]) -> tuple[str, list[dict[str, object]]] | None: + """Return the last serving request id and its ordered candidate trail. + + Preflight probes carry ``request_id=-`` and are ignored; a serving request + carries a 32-hex request id. ``circuit_failure`` lines carry no request id + and are attributed to the agent's most recent attempt. A candidate whose + circuit tripped without a transport failure is labelled + ``invalid_response``; one with no recorded failure keeps + ``no_failure_recorded``. + """ + + trails: dict[str, list[dict[str, object]]] = {} + entries: dict[tuple[str, str], dict[str, object]] = {} + last_request_for_agent: dict[str, str] = {} + last_request: str | None = None + for line in lines: + parsed = _parse_line(line) + if parsed is None: + continue + timestamp, event, fields = parsed + agent = fields.get("agent_id", "") + if not _AGENT_RE.match(agent): + continue + request_id = fields.get("request_id", "") + if not _REQUEST_ID_RE.match(request_id): + request_id = last_request_for_agent.get(agent, "") if event == "circuit_failure" else "" + if not request_id: + continue + key = (request_id, agent) + entry = entries.get(key) + if event == "provider_attempt": + last_request_for_agent[agent] = request_id + last_request = request_id + if entry is None: + entry = {"agent_id": agent, "started": timestamp, "ended": None, "outcome": None} + entries[key] = entry + trails.setdefault(request_id, []).append(entry) + continue + if entry is None: + continue + if event == "provider_attempt_failed": + entry["outcome"] = _failure_outcome(fields) + entry["ended"] = timestamp + elif event == "circuit_failure": + if entry["outcome"] is None: + entry["outcome"] = "invalid_response" + entry["ended"] = timestamp + if last_request is None: + return None + return last_request, trails[last_request] + + +def format_annotation(request_id: str, trail: list[dict[str, object]]) -> str: + """Render one GitHub Actions ``::notice`` line for a candidate trail.""" + + first_start = trail[0]["started"] + steps: list[str] = [] + counts: Counter[str] = Counter() + last_end = first_start + for index, entry in enumerate(trail, start=1): + outcome = str(entry["outcome"] or "no_failure_recorded") + counts[outcome] += 1 + ended = entry["ended"] or entry["started"] + last_end = max(last_end, ended) # type: ignore[type-var] + if index <= MAX_LISTED_CANDIDATES: + elapsed = (ended - entry["started"]).total_seconds() # type: ignore[operator] + steps.append(f"{index}) {entry['agent_id']} {outcome} after {elapsed:.1f}s") + if len(trail) > MAX_LISTED_CANDIDATES: + steps.append(f"... {len(trail) - MAX_LISTED_CANDIDATES} more") + total = (last_end - first_start).total_seconds() # type: ignore[operator] + tally = ", ".join(f"{name}={count}" for name, count in sorted(counts.items())) + return ( + "::notice title=SIDECAR_CANDIDATE_TRAIL::" + f"request {request_id[:8]} tried {len(trail)} candidate(s) over {total:.1f}s: " + + "; ".join(steps) + + f". Outcomes: {tally}. The gateway's final status reflects only the last candidate." + ) + + +def main(argv: list[str]) -> int: + """Print the candidate-trail annotation for the sidecar log at ``argv[1]``. + + Always returns 0: a missing or unreadable log, or one with no serving + request, prints nothing because this summary must never fail a job. + """ + + if len(argv) != 2: + print("usage: sidecar_route_trail.py ", file=sys.stderr) + return 0 + path = Path(argv[1]) + try: + lines = path.read_text(encoding="utf-8", errors="replace").splitlines() + except OSError: + return 0 + result = summarize(lines) + if result is not None: + print(format_annotation(*result)) + return 0 + + +if __name__ == "__main__": # pragma: no cover - thin CLI wrapper + raise SystemExit(main(sys.argv)) diff --git a/tests/test_sidecar_route_trail.py b/tests/test_sidecar_route_trail.py new file mode 100644 index 0000000000..f5c6f07150 --- /dev/null +++ b/tests/test_sidecar_route_trail.py @@ -0,0 +1,111 @@ +"""Regression tests for the sidecar candidate-trail summary.""" + +from __future__ import annotations + +from pathlib import Path + +from scripts.ci import sidecar_route_trail as trail + +REQ = "b838563db7f541a7a32ba4e335291bd9" + +# Synthetic replica of Actions run 36166447802's serving trail (no secrets, +# no request content): preflight probes carry request_id=-, the serving +# request tries six ready NVIDIA routes before the two deferred OpenRouter +# routes that answer 429. +RUN_36166447802_SHAPE = f"""\ +provider_discovery_failed provider=bytez code=http_status_500 +2026-09-25 23:27:39,816 provider_attempt agent_id=openrouter_ling_fin_free model=m attempt=1/1 request_id=- +2026-09-25 23:27:39,862 provider_attempt_failed agent_id=openrouter_ling_fin_free model=m attempt=1 error_type=HTTPError transient=True provider_status=429 request_id=- error_message= +2026-09-25 23:38:20,229 provider_attempt agent_id=nvidia_nim_gemma_4_31b model=m attempt=1/1 request_id={REQ} +2026-09-25 23:42:29,182 provider_attempt agent_id=nvidia_nim_gemma_4_31b model=m attempt=1/1 request_id={REQ} +2026-09-25 23:47:07,175 provider_attempt_failed agent_id=nvidia_nim_gemma_4_31b model=m attempt=1 error_type=RemoteDisconnected transient=True provider_status=None request_id={REQ} error_message= +2026-09-25 23:47:07,175 provider_one_shot_call_failed agent_id=nvidia_nim_gemma_4_31b model=m attempts=1 final_error_type=RemoteDisconnected transient=True request_id={REQ} +2026-09-25 23:47:07,176 circuit_failure agent_id=nvidia_nim_gemma_4_31b failures=1.0 threshold=3 +2026-09-25 23:47:07,190 provider_attempt agent_id=nvidia_nim_sub_gemma_4_31b model=m attempt=1/1 request_id={REQ} +2026-09-25 23:52:09,251 provider_attempt_failed agent_id=nvidia_nim_sub_gemma_4_31b model=m attempt=1 error_type=HTTPError transient=True provider_status=504 request_id={REQ} error_message= +2026-09-25 23:52:09,321 provider_attempt agent_id=nvidia_nim_llama_vision model=m attempt=1/1 request_id={REQ} +2026-09-25 23:52:21,097 circuit_failure agent_id=nvidia_nim_llama_vision failures=1.0 threshold=3 +2026-09-25 23:55:41,514 provider_attempt agent_id=openrouter_ling_fin_free model=m attempt=1/1 request_id={REQ} +2026-09-25 23:55:41,625 provider_attempt_failed agent_id=openrouter_ling_fin_free model=m attempt=1 error_type=HTTPError transient=True provider_status=429 request_id={REQ} error_message= +2026-09-25 23:55:41,625 circuit_failure agent_id=openrouter_ling_fin_free failures=1.0 threshold=3 +""" + + +def test_run_shape_reports_every_candidate_not_only_the_final_429() -> None: + """The annotation lists each serving candidate in order with its own outcome.""" + + request_id, entries = trail.summarize(RUN_36166447802_SHAPE.splitlines()) + assert request_id == REQ + assert [e["agent_id"] for e in entries] == [ + "nvidia_nim_gemma_4_31b", + "nvidia_nim_sub_gemma_4_31b", + "nvidia_nim_llama_vision", + "openrouter_ling_fin_free", + ] + assert [e["outcome"] for e in entries] == [ + "disconnect", + "http_504", + "invalid_response", + "http_429", + ] + line = trail.format_annotation(request_id, entries) + assert line.startswith("::notice title=SIDECAR_CANDIDATE_TRAIL::request b838563d tried 4 candidate(s)") + assert "1) nvidia_nim_gemma_4_31b disconnect after 526.9s" in line + assert "2) nvidia_nim_sub_gemma_4_31b http_504 after 302.1s" in line + assert "3) nvidia_nim_llama_vision invalid_response after 11.8s" in line + assert "4) openrouter_ling_fin_free http_429 after 0.1s" in line + assert "over 1041.4s" in line + assert "Outcomes: disconnect=1, http_429=1, http_504=1, invalid_response=1." in line + + +def test_failure_outcome_labels_are_bounded() -> None: + """Transport errors map to fixed labels and never echo arbitrary text.""" + + assert trail._failure_outcome({"provider_status": "503"}) == "http_503" + assert trail._failure_outcome({"error_type": "ReadTimeout"}) == "timeout" + assert trail._failure_outcome({"error_type": "ConnectionResetError"}) == "disconnect" + assert trail._failure_outcome({"error_type": "URLError"}) == "urlerror" + assert trail._failure_outcome({"error_type": "