diff --git a/docs/hermes_suite_failure_diagnosis_20260929.md b/docs/hermes_suite_failure_diagnosis_20260929.md new file mode 100644 index 00000000..022b3570 --- /dev/null +++ b/docs/hermes_suite_failure_diagnosis_20260929.md @@ -0,0 +1,135 @@ +# Suite planner failure diagnosis, 2026-09-29 + +## Established facts and the historical limit of the evidence + +The exact failed job is `40f473da1bd8495180a6cd7aff30c801`. +Its saved metadata reports 14 cases and **70.201 seconds**, not the OCR estimate. +It used configuration `suite-v6-20260929`, prompt +`implementation-proximity-v2-20260929`, and the selected Claude route. +The saved error is `incomplete_generation` with empty details. + +The historical terminal condition is **unknown**. The old adapter discarded +exit status and final-event diagnostics when raising that error. The per-job +tmpfs directory was then deleted on all exit paths; `/jobs` contained zero +remaining suite directories. Stderr was discarded during execution. The worker +had not restarted. No valid result was stored for this failed job. Cleanup was +intentional for data minimization; the diagnostic loss was an adapter defect. +No request, source text, real generated descriptions, or raw provider error was +read as part of this investigation. + +## Exact original code paths + +In `suite_backends.parse_claude`, `incomplete_generation` could mean: + +1. No recognized initialization event or no terminal `type=result` event. +2. A terminal result with `is_error=true` or `subtype` other than `success` + (except recognized provider authentication/rate-limit errors). +3. A successful-looking final event with `stop_reason=max_tokens` or + `model_context_window_exceeded`. + +In `suite_backends.claude_generate`, it also meant a nonzero subprocess exit +**after** parsing a otherwise acceptable structured result. Thus a valid payload +could have existed on that branch, but the historical artifact needed to prove +or validate it no longer exists. + +Missing/non-object `result.structured_output` and malformed stream JSON were +`invalid_json_result`, not `incomplete_generation`. Normal schema and exactly-once +membership checks run afterwards in `Jobs.run`, with distinct +`invalid_json_result`, `invalid_case_assignments`, or `duplicate_family_name` +errors. Those validation failures were not relabeled as incomplete generation. +Subprocess deadline, cancellation, output-byte overflow, and worker restart also +had distinct error codes. A CLI-internal execution error could still have entered +path 2, and a signal/nonzero exit could enter paths 1 or 4. + +## Historical operational metadata + +| Item | Failed job evidence | +| --- | --- | +| CLI exit code / terminating signal | Unknown; discarded | +| Actual final event subtype / error indicator | Unknown; deleted | +| Actual CLI turns / configured ceiling | Unknown / 3 | +| Structured-output retry limit and outcome | Unknown | +| Provider stop reason | Unknown | +| Actual input/output/reasoning token usage | Unknown; saved usage is null | +| Structured output present / location | Unknown; artifact deleted | +| Exact remaining subprocess deadline | Unknown; normally request max_seconds minus routing time, at most 900 seconds | +| Provider-internal execution timeout | Unknown | +| Compaction / truncation | Unknown; both saved null | +| Configured output / reasoning | 64,000 per-call output ceiling; medium effort; separate reasoning-token budget unknown | +| Preflight output_reservation_verified | False; an estimate, not a runtime stop indication | +| Selected versus observed model | Selected `claude-opus-4-8`; failed job's terminal runtime model metadata unavailable | + +The same installed Claude Code 2.1.226 binary's loopback request included +`max_tokens=64000` and `x-stainless-timeout: 600`. The latter is an observed SDK +request header, not a measurement or guarantee of a provider-internal timeout, +and it cannot establish the historical failure's cause. Successful jobs report +context 1,000,000 and output ceiling 64,000; those numbers do not establish actual +usage or the stop condition in the failed job. + +## Comparison with successful runs + +The original 14/75/363 acceptance jobs each reported two CLI turns. The earlier +successful real 14-case job `276720d47aa541038237e284e2058533` reported three turns, +70.2 seconds, and 16,947 input / 5,656 output tokens. The revised-prompt synthetic +job `661aefd2d1f14579a264a34d64bf704b` also reported three turns, 20.544 seconds, +and 11,010 input / 1,833 output tokens. Only their operational metadata was read. + +The prompt update expanded the implementation-effort instructions and added prompt +provenance. It did not change the CLI invocation, three-turn ceiling, model, +reasoning effort, output ceiling, parser, or result schema. Successful runs already +reached the configured ceiling before this failure, including one before the new +prompt. A three-turn assumption was therefore fragile; the new prompt is not an +established unique cause. + +## Deterministic synthetic reproduction and change + +`scripts/ops/hermes_suite_cli_probe.py` runs the installed native binary against a +loopback mock using a fake OAuth value, with no hosted inference. The mock sends +three invalid StructuredOutput tool arguments, then a valid complete synthetic +result. The system prompt and complete input remain in every captured request. + +| Ceiling | CLI exit | Final subtype | CLI-reported turns | Actual mock generation calls | Structured output | +| ---: | ---: | --- | ---: | ---: | --- | +| 3 | 1 | error_max_turns | 4 | 3 | Absent | +| 6 | 0 | success | 5 | 4 | Present; schema and exact membership pass | + +The CLI's turn counter can include the next/terminal loop iteration. It is +recorded as reported, not interpreted as a count of paid provider calls. This +reproduces a concrete failure class that the old adapter collapsed into the +historical error label; it does **not** prove the historical job took that branch. + +Execution revision `claude-diagnostics-turns-v1-20260929`: + +- Adds allowlisted failure-stage, exit/signal, final-event, turn/retry-limit, + stop-reason, usage, timing, and structured-output-presence/location diagnostics. +- Detects possible JSON in final text or StructuredOutput assistant tool arguments + without accepting those candidates or retaining their contents. +- Preserves safe usage/diagnostics on schema and membership failures. +- Allows six CLI turns within the existing deadline and estimated-cost ceiling; + preflight reserves six possible outputs against context. No automatic job retry. +- Keeps input/output cleanup and content-free routine logs. No raw CLI errors, + prompts, response descriptions, or credentials are added to persisted metadata. + +The configuration revision, prompt revision/hash, model, medium effort, token +ceiling, schema, authentication, provider restrictions, and coverage checks are +unchanged. Historical jobs retain their old metadata. The new execution revision +is additive metadata in capabilities, preflight, and new jobs. + +65 focused tests pass, covering turn/structured-retry/budget errors, explicit +provider stops, missing/malformed terminal events, candidate output locations, +nonzero exits with valid output, actual subprocess signals/timeouts/cancellation, +cleanup, privacy canaries, exact membership, and idempotency. Native loopback +reproduction also passes. Kustomize rendering and client dry-run passed; Flux diff +shows only the planner ConfigMap and planner restart annotation. + +## Recovery and the laptop's next attempt + +The old answer cannot be recovered or validated after cleanup. No assignments +will be fabricated. No real suite has been rerun. The laptop must intentionally +create a **new attempt with a new Idempotency-Key** after deployment verification; +reusing the old key correctly returns the same failed job. The input/request +schema and Python parsing contract do not require a change for this fix. + +Rollback only this diagnostic/turn-limit commit through Git and Flux. Keep the +prior implementation-proximity prompt commit. Rollouts should occur with no active +jobs; in-memory completed results expire on a worker restart. diff --git a/docs/hermes_suite_planning.md b/docs/hermes_suite_planning.md index 20d75a72..b87b4c42 100644 --- a/docs/hermes_suite_planning.md +++ b/docs/hermes_suite_planning.md @@ -4,6 +4,32 @@ This optional API groups one complete campaign/suite into implementation familie The existing `/local-model` API, GPU allocation, serving model, and limits are unchanged. Deployment uses Flux; the application and workbook stay on the laptop. +## CLI failure diagnostics update + +Execution revision `claude-diagnostics-turns-v1-20260929` adds content-free +`cli_diagnostics` and failure-stage details, including exit/signal, final subtype, +reported turns, observed stop reason, token counts, and structured-output location. +Unknown measurements remain null. Source, generated descriptions, raw provider +errors, and transcripts are not retained. The normal schema and exact membership +checks still gate completion. Failed validation now preserves operational usage. + +The CLI turn ceiling is six, with the same model, medium effort, 64,000 per-call +output ceiling, maximum 900-second job deadline, and USD 5 CLI estimated-cost cap. +Preflight reserves all six possible outputs against context. This is headroom +within one fresh job, not an automatic job retry or a fallback. The historical +three-turn ceiling was exhausted by a deterministic synthetic structured-output +repair test; six turns completed that same test. This does not establish the +cause of a historical failure whose terminal event was deleted. + +The HTTP configuration revision and implementation-proximity prompt revision/hash +are unchanged. `execution_revision` records the new behavior in capability, +preflight, and job metadata. Use a new idempotency key only when intentionally +starting a new attempt; the failed historical job is never automatically rerun. +See [the diagnosis and verification record](hermes_suite_failure_diagnosis_20260929.md). +Rollback this update by reverting its Git commit and reconciling the Hermes Flux +Kustomization; do not revert the earlier prompt commit. Wait for no active jobs +before rollout because results are held in memory. + ## Implementation-proximity prompt update New jobs use prompt revision `implementation-proximity-v2-20260929`. The HTTP @@ -383,7 +409,7 @@ Claude invocation, with the schema supplied by the server: --strict-mcp-config --mcp-config '{"mcpServers":{}}' \ --setting-sources '' --disable-slash-commands --permission-mode dontAsk \ --no-chrome --model 'claude-opus-4-8[1m]' --effort medium \ - --max-budget-usd 5 --max-turns 3 \ + --max-budget-usd 5 --max-turns 6 \ --system-prompt '' --json-schema '' ``` @@ -414,7 +440,7 @@ results to 1 MiB. Names are at most 80 characters, descriptions at most 240. Preflight includes the entire serialized suite, fixed instructions, schema, reserved harness overhead, and output space. There is no accurate account-specific tokenizer. The input check uses UTF-8 byte count plus 8,192 reserved harness tokens, with the -64,000 output ceiling reserved for each of at most three turns against context. This is a conservative bound, +64,000 output ceiling reserved for each of at most six turns against context. This is a conservative bound, not a measured token count. The output reservation is an explicit estimate allowing a family per case and 8,192 reasoning tokens; it is not a verified bound on arbitrary generated wording. Medium adaptive reasoning can consume output budget. Incomplete diff --git a/scripts/ops/hermes_suite_cli_probe.py b/scripts/ops/hermes_suite_cli_probe.py new file mode 100755 index 00000000..8f52c5c2 --- /dev/null +++ b/scripts/ops/hermes_suite_cli_probe.py @@ -0,0 +1,73 @@ +#!/usr/bin/env python3 +"""Synthetic native CLI turn-limit probe; all model HTTP goes to loopback. + +Run inside the planner with: kubectl exec -i ... -- python < this-file +No hosted inference or live account credential is used. +""" +import json, threading, tempfile, pathlib, subprocess, sys, time +from http.server import HTTPServer, BaseHTTPRequestHandler +sys.path.insert(0, '/opt/planner') +from suite_backends import claude_environment, claude_command +from suite_contract import SYSTEM, prompt, validate_result +from suite_synthetic import fixture +seen = [] +request = fixture(14)[0] +source = prompt(request) +def strings(value): + if isinstance(value, str): yield value + elif isinstance(value, list): + for item in value: yield from strings(item) + elif isinstance(value, dict): + for item in value.values(): yield from strings(item) +class Mock(BaseHTTPRequestHandler): + def log_message(self, *args): pass + def do_POST(self): + body = json.loads(self.rfile.read(int(self.headers['Content-Length']))) + seen.append({'stream': body.get('stream'), 'max_tokens': body.get('max_tokens'), + 'http_timeout_header': self.headers.get('x-stainless-timeout'), + 'whole_input': source in list(strings(body.get('messages', []))), + 'system_preserved': any(SYSTEM in s for s in strings(body.get('system', [])))}) + value = {} if len(seen) <= 3 else {'groups': [{'name': 'Synthetic', 'description': 'Mock only', 'members': [c['alias'] for c in request['cases']]}]} + block = {'type': 'tool_use', 'id': 'mock-' + str(len(seen)), 'name': 'StructuredOutput', 'input': value} + message = {'id': 'mock', 'type': 'message', 'role': 'assistant', 'model': 'claude-opus-4-8', + 'content': [block], 'stop_reason': 'tool_use', 'stop_sequence': None, + 'usage': {'input_tokens': 10, 'output_tokens': 5}} + if body.get('stream'): + initial = {**message, 'content': [], 'stop_reason': None, 'usage': {'input_tokens': 10, 'output_tokens': 0}} + events = [('message_start', {'type': 'message_start', 'message': initial}), + ('content_block_start', {'type': 'content_block_start', 'index': 0, 'content_block': {**block, 'input': {}}}), + ('content_block_delta', {'type': 'content_block_delta', 'index': 0, 'delta': {'type': 'input_json_delta', 'partial_json': json.dumps(value)}}), + ('content_block_stop', {'type': 'content_block_stop', 'index': 0}), + ('message_delta', {'type': 'message_delta', 'delta': {'stop_reason': 'tool_use', 'stop_sequence': None}, 'usage': {'output_tokens': 5}}), + ('message_stop', {'type': 'message_stop'})] + out = ''.join('event: ' + k + '\ndata: ' + json.dumps(v) + '\n\n' for k, v in events).encode() + content_type = 'text/event-stream' + else: + out = json.dumps(message).encode(); content_type = 'application/json' + self.send_response(200); self.send_header('Content-Type', content_type) + self.send_header('Content-Length', str(len(out))); self.end_headers(); self.wfile.write(out) +server = HTTPServer(('127.0.0.1', 0), Mock) +threading.Thread(target=server.serve_forever, daemon=True).start() +for limit in [3, 6]: + seen.clear() + with tempfile.TemporaryDirectory(dir='/jobs') as directory: + env = claude_environment(directory, 'synthetic-unused-oauth-token') + env['ANTHROPIC_BASE_URL'] = 'http://127.0.0.1:' + str(server.server_port) + cmd = claude_command('claude-opus-4-8', 5) + cmd[cmd.index('--max-turns') + 1] = str(limit) + started = time.monotonic() + p = subprocess.run(cmd, input=source, capture_output=True, text=True, env=env, cwd=directory, timeout=45) + events = [json.loads(line) for line in p.stdout.splitlines()] + final = next((e for e in reversed(events) if e.get('type') == 'result'), {}) + if limit == 3: + assert p.returncode == 1 and final.get('subtype') == 'error_max_turns' + assert not final.get('structured_output') + else: + assert p.returncode == 0 and final.get('subtype') == 'success' + validate_result(final['structured_output'], request) + assert all(item['whole_input'] and item['system_preserved'] for item in seen) + print(json.dumps({'max_turns': limit, 'exit_code': p.returncode, 'wall_seconds': round(time.monotonic()-started, 3), + 'final': {k: final.get(k) for k in ('type', 'subtype', 'is_error', 'num_turns', 'stop_reason', 'usage')}, + 'structured_output_present': isinstance(final.get('structured_output'), dict), + 'requests': seen}), flush=True) +server.shutdown() diff --git a/services/hermes/kustomization.yaml b/services/hermes/kustomization.yaml index ded3a288..5ff42f41 100644 --- a/services/hermes/kustomization.yaml +++ b/services/hermes/kustomization.yaml @@ -60,6 +60,7 @@ configMapGenerator: - suite_api.py=scripts/suite_api.py - suite_jobs.py=scripts/suite_jobs.py - suite_backends.py=scripts/suite_backends.py + - suite_cli_diagnostics.py=scripts/suite_cli_diagnostics.py - suite_contract.py=scripts/suite_contract.py - suite_synthetic.py=scripts/suite_synthetic.py options: diff --git a/services/hermes/scripts/suite_api.py b/services/hermes/scripts/suite_api.py index a5499513..d62ac5d4 100644 --- a/services/hermes/scripts/suite_api.py +++ b/services/hermes/scripts/suite_api.py @@ -12,7 +12,7 @@ import re import subprocess import threading -from suite_contract import (MAX_BODY, MAX_CASES, MAX_RESULT, MODELS, PROMPT_REVISION, +from suite_contract import (EXECUTION_REVISION, MAX_BODY, MAX_CASES, MAX_RESULT, MODELS, PROMPT_REVISION, PROMPT_SHA256, REVISION, TIMEOUT, Problem, encoded, preflight, validate_request) from suite_jobs import Jobs @@ -118,9 +118,11 @@ class Handler(BaseHTTPRequestHandler): jobs = self.server.jobs if method == "GET" and self.path == "/healthz": return self.send(200, {"status": "ready", "configuration_revision": REVISION, + "execution_revision": EXECUTION_REVISION, "prompt_revision": PROMPT_REVISION, "prompt_sha256": PROMPT_SHA256}) if method == "GET" and self.path == "/v1/capabilities": return self.send(200, {"configuration_revision": REVISION, "models": MODELS, + "execution_revision": EXECUTION_REVISION, "prompt_revision": PROMPT_REVISION, "prompt_sha256": PROMPT_SHA256, "allowed_external_providers": providers, "external_scope": "generalized_claude_and_exact_synthetic_fixtures" diff --git a/services/hermes/scripts/suite_backends.py b/services/hermes/scripts/suite_backends.py index 19da59b7..35a6dbcd 100644 --- a/services/hermes/scripts/suite_backends.py +++ b/services/hermes/scripts/suite_backends.py @@ -4,7 +4,6 @@ from __future__ import annotations import json import os from pathlib import Path -import re import signal import subprocess import tempfile @@ -12,7 +11,8 @@ import time from urllib.error import HTTPError, URLError from urllib.request import HTTPRedirectHandler, ProxyHandler, Request, build_opener -from suite_contract import MODELS, SCHEMA, SYSTEM, Problem, encoded, prompt +from suite_contract import CLAUDE_MAX_TURNS, MODELS, SCHEMA, SYSTEM, Problem, encoded, prompt +from suite_cli_diagnostics import snapshot SWITCHYARD = "http://hermes-switchyard.hermes.svc.cluster.local:9005/v1/chat/completions" LOCAL = "http://hermes-model-gate-lan-api.hermes.svc.cluster.local:8082" @@ -102,7 +102,7 @@ def claude_command(model, max_cost): "--setting-sources", "", "--disable-slash-commands", "--permission-mode", "dontAsk", "--no-chrome", "--model", MODELS["claude"]["cli_model"], "--effort", "medium", "--max-budget-usd", str(max_cost), - "--max-turns", "3", "--system-prompt", SYSTEM, + "--max-turns", str(CLAUDE_MAX_TURNS), "--system-prompt", SYSTEM, "--json-schema", encoded(SCHEMA).decode()] @@ -124,69 +124,83 @@ def claude_environment(directory, token): def stop(process): """Terminate the complete CLI process group and reap it on every exit path.""" if process.poll() is None: - os.killpg(process.pid, signal.SIGTERM) + try: + os.killpg(process.pid, signal.SIGTERM) + except ProcessLookupError: + pass # The process can exit between poll and kill; still reap it. try: process.wait(timeout=2) except subprocess.TimeoutExpired: - os.killpg(process.pid, signal.SIGKILL) + try: + os.killpg(process.pid, signal.SIGKILL) + except ProcessLookupError: + pass process.wait(timeout=5) -def parse_claude(raw, expected_model): +def parse_claude(raw, expected_model, **process_info): """Normalize only a completed, uncompacted CLI result with a pinned model.""" + diagnostics = snapshot(raw, **process_info) + + def fail(code, stage): + raise Problem(code, 502, **diagnostics, failure_stage=stage) + final, initialized = None, False aliases = {expected_model, expected_model + "[1m]"} for line in raw.splitlines(): try: event = json.loads(line) except ValueError: - raise Problem("invalid_json_result", 502) from None + fail("invalid_json_result", "cli_event_json") if not isinstance(event, dict): - raise Problem("invalid_json_result", 502) + fail("invalid_json_result", "cli_event_json") if "compact" in str(event.get("subtype", "")): - raise Problem("compaction_detected", 502) + fail("compaction_detected", "cli_events") if event.get("type") == "system" and event.get("subtype") == "init": initialized = True if (event.get("model") not in aliases or event.get("mcp_servers") or event.get("plugins") or set(event.get("tools", [])) - {"StructuredOutput"}): - raise Problem("worker_isolation_failed", 502) + fail("worker_isolation_failed", "cli_initialization") if event.get("type") == "result": final = event if not initialized or not final: - raise Problem("incomplete_generation", 502) + fail("incomplete_generation", "missing_init_or_final_event") if final.get("is_error") or final.get("subtype") != "success": status = final.get("api_error_status") code = "rate_limit" if status == 429 else "incomplete_generation" if status in (401, 403): code = "provider_authentication" - raise Problem(code, 502) + fail(code, "cli_final_result") if final.get("stop_reason") in {"max_tokens", "model_context_window_exceeded"}: - raise Problem("incomplete_generation", 502) + fail("incomplete_generation", "provider_stop") models = final.get("modelUsage", {}) - if not models or set(models) - aliases: - observed = [name if re.fullmatch(r"claude-[a-z0-9.-]+(?:\[1m\])?", name) - else "unrecognized" for name in models] - limits_seen = [{k: v for k, v in entry.items() - if k in {"contextWindow", "maxOutputTokens"} and type(v) is int} - for entry in models.values() if isinstance(entry, dict)] - raise Problem("model_changed", 502, observed_models=observed, limits=limits_seen) + if not isinstance(models, dict) or not models or set(models) - aliases: + fail("model_changed", "runtime_model") for limits in models.values(): - if (limits.get("contextWindow") != 1000000 or limits.get("maxOutputTokens") != 64000 + if (not isinstance(limits, dict) or limits.get("contextWindow") != 1000000 or limits.get("maxOutputTokens") != 64000 or limits.get("canonicalModel") != expected_model or limits.get("provider") != "firstParty"): - raise Problem("backend_capabilities_changed", 502) + fail("backend_capabilities_changed", "runtime_model_limits") usage = final.get("usage", {}) + if not isinstance(usage, dict) or not isinstance(usage.get("server_tool_use", {}), dict): + fail("invalid_json_result", "cli_usage") if any(usage.get("server_tool_use", {}).values()): - raise Problem("worker_isolation_failed", 502) + fail("worker_isolation_failed", "provider_tools") result = final.get("structured_output") if not isinstance(result, dict): - raise Problem("invalid_json_result", 502) + fail("invalid_json_result", "structured_output_extraction") + if process_info.get("exit_code"): + fail("incomplete_generation", "process_exit") + # Persist measured metadata only, including on later schema/coverage failure. + safe_models = {name: {"canonicalModel": expected_model, "provider": "firstParty", + "contextWindow": 1000000, "maxOutputTokens": 64000} + for name in models} return result, {"model": expected_model, "compaction": False, "truncation": False, "compaction_signal": "CLI events and disabled compaction", - "usage": usage, "model_usage": models, - "duration_api_ms": final.get("duration_api_ms"), - "cost_usd_estimate": final.get("total_cost_usd"), - "turns": final.get("num_turns")} + "usage": diagnostics["usage"], "model_usage": safe_models, + "duration_api_ms": diagnostics["duration_api_ms"], + "cost_usd_estimate": diagnostics["cost_usd_estimate"], + "turns": diagnostics["turns"], "cli_diagnostics": diagnostics} def claude_generate(request, cancel): @@ -199,11 +213,17 @@ def claude_generate(request, cancel): root = Path(directory) (root / "input").write_text(prompt(request)) env = claude_environment(directory, token) + seconds = request["execution"]["max_seconds"] + failure = None with (root / "input").open("rb") as source, (root / "output").open("wb") as output: - process = subprocess.Popen(claude_command(model, request["execution"]["max_cost_usd"]), - stdin=source, stdout=output, stderr=subprocess.DEVNULL, - env=env, cwd=directory, start_new_session=True) - deadline = time.monotonic() + request["execution"]["max_seconds"] + try: + process = subprocess.Popen(claude_command(model, request["execution"]["max_cost_usd"]), + stdin=source, stdout=output, stderr=subprocess.DEVNULL, + env=env, cwd=directory, start_new_session=True) + except OSError: + raise Problem("backend_unavailable", 503, failure_stage="process_start", + **snapshot("", subprocess_timeout_seconds=seconds)) from None + deadline = time.monotonic() + seconds try: while process.poll() is None: if cancel.wait(0.1): @@ -212,15 +232,23 @@ def claude_generate(request, cancel): raise Problem("timeout", 504) if (root / "output").stat().st_size > OUTPUT_BYTES: raise Problem("response_too_large", 502) + except Problem as exc: + failure = exc finally: stop(process) if (root / "output").stat().st_size > OUTPUT_BYTES: - raise Problem("response_too_large", 502) - raw = (root / "output").read_text() + failure = failure or Problem("response_too_large", 502) + # Read only a bounded prefix even if the CLI exits between size checks. + with (root / "output").open("rb") as output: + raw = output.read(OUTPUT_BYTES).decode("utf-8", errors="replace") + info = {"exit_code": process.returncode, "subprocess_timeout_seconds": seconds, + "termination_reason": failure.code if failure else None} + if failure: + raise Problem(failure.code, failure.status, failure_stage="subprocess", + **snapshot(raw, **info)) if process.returncode and not raw.strip(): - raise Problem("backend_unavailable", 503) - result, metadata = parse_claude(raw, model) - if process.returncode: - raise Problem("incomplete_generation", 502) + raise Problem("backend_unavailable", 503, failure_stage="process_exit", + **snapshot(raw, **info)) + result, metadata = parse_claude(raw, model, **info) metadata["temporary_files_deleted"] = True return result, metadata diff --git a/services/hermes/scripts/suite_cli_diagnostics.py b/services/hermes/scripts/suite_cli_diagnostics.py new file mode 100644 index 00000000..bfd55c81 --- /dev/null +++ b/services/hermes/scripts/suite_cli_diagnostics.py @@ -0,0 +1,118 @@ +"""Allowlisted CLI metadata; never persist event bodies or provider error text.""" +from __future__ import annotations + +import json +import math + +from suite_contract import CLAUDE_MAX_TURNS, EXECUTION_REVISION + +SUBTYPES = {"success", "error_max_turns", "error_max_structured_output_retries", + "error_max_budget_usd", "error_during_execution"} +STOP_REASONS = {"end_turn", "tool_use", "max_tokens", "stop_sequence", "refusal", + "pause_turn", "model_context_window_exceeded"} + + +def number(value): + """Retain finite nonnegative measurements, excluding booleans and strings.""" + return value if type(value) in (int, float) and 0 <= value <= 2**63 and math.isfinite(value) else None + + +def enum(value, allowed): + """Unknown labels are not safe strings: they can contain provider content.""" + return value if isinstance(value, str) and value in allowed else (None if value is None else "other") + + +def usage_counts(value): + """Project token counts without carrying arbitrary provider dictionary keys.""" + if not isinstance(value, dict): + return None + result = {key: number(value[key]) for key in ( + "input_tokens", "output_tokens", "cache_read_input_tokens", "cache_creation_input_tokens") + if key in value} + for key, fields in (("server_tool_use", ("web_search_requests", "web_fetch_requests")), + ("cache_creation", ("ephemeral_1h_input_tokens", "ephemeral_5m_input_tokens"))): + if isinstance(value.get(key), dict): + result[key] = {field: number(value[key][field]) for field in fields if field in value[key]} + return result + + +def object_text(value): + """Report a possible JSON envelope mismatch without retaining its contents.""" + if not isinstance(value, str): + return False + try: + return isinstance(json.loads(value), dict) + except ValueError: + return False + + +def snapshot(raw, *, exit_code=None, subprocess_timeout_seconds=None, termination_reason=None): + """Return bounded diagnostic fields from a CLI stream, including failed runs.""" + final, last_assistant = None, {} + initialized = compacted = tool_candidate = text_candidate = False + invalid_events = 0 + for line in raw.splitlines(): + try: + event = json.loads(line) + except ValueError: + invalid_events += 1 + continue + if not isinstance(event, dict): + invalid_events += 1 + continue + initialized |= event.get("type") == "system" and event.get("subtype") == "init" + compacted |= "compact" in str(event.get("subtype", "")) + if event.get("type") == "result": + final = event + if event.get("type") == "assistant" and isinstance(event.get("message"), dict): + last_assistant = event["message"] + content = last_assistant.get("content", []) + for block in content if isinstance(content, list) else []: + if isinstance(block, dict): + tool_candidate |= (block.get("type") == "tool_use" and + block.get("name") == "StructuredOutput" and + isinstance(block.get("input"), dict)) + text_candidate |= block.get("type") == "text" and object_text(block.get("text")) + result = final or {} + subtype = enum(result.get("subtype"), SUBTYPES) + stop_reason = enum(result.get("stop_reason"), STOP_REASONS) + limits = result.get("modelUsage", {}) + limits = [{key: number(entry.get(key)) for key in ("contextWindow", "maxOutputTokens")} + for entry in limits.values() if isinstance(entry, dict)] if isinstance(limits, dict) else [] + return { + "execution_revision": EXECUTION_REVISION, + "exit_code": exit_code if type(exit_code) is int and exit_code >= 0 else None, + "termination_signal": -exit_code if type(exit_code) is int and exit_code < 0 else None, + "termination_reason": termination_reason or ( + "signal" if type(exit_code) is int and exit_code < 0 else + "nonzero_exit" if exit_code else "exited" if exit_code == 0 else None), + "subprocess_timeout_seconds": number(subprocess_timeout_seconds), + "provider_timeout_seconds": None, + "max_turns": CLAUDE_MAX_TURNS, + "turns": number(result.get("num_turns")), + "turn_limit_reached": subtype == "error_max_turns" if subtype in SUBTYPES else None, + "structured_retry_limit_reached": subtype == "error_max_structured_output_retries" if subtype in SUBTYPES else None, + "init_event_seen": initialized, + "final_event_seen": final is not None, + "final_event_type": "result" if final is not None else None, + "final_event_subtype": subtype, + "final_is_error": result.get("is_error") if type(result.get("is_error")) is bool else None, + "provider_stop_reason": stop_reason, + "last_assistant_stop_reason": enum(last_assistant.get("stop_reason"), STOP_REASONS), + "api_error_status": number(result.get("api_error_status")), + "invalid_event_count": invalid_events, + "structured_output_present": result.get("structured_output") is not None if final is not None else None, + "structured_output_is_object": isinstance(result.get("structured_output"), dict) if final is not None else None, + "structured_output_location": "result.structured_output" if result.get("structured_output") is not None else None, + "assistant_structured_tool_input_present": tool_candidate, + "assistant_json_text_present": text_candidate, + "final_json_text_present": object_text(result.get("result")), + "compaction_event_seen": compacted, + "usage": usage_counts(result.get("usage")), + "duration_api_ms": number(result.get("duration_api_ms")), + "cost_usd_estimate": number(result.get("total_cost_usd")), + "observed_model_limits": limits[:8], + "configured_max_output_tokens": 64000, + "reasoning_effort": "medium", + "reasoning_token_limit": None, + } diff --git a/services/hermes/scripts/suite_contract.py b/services/hermes/scripts/suite_contract.py index e881ace8..ca085cd5 100644 --- a/services/hermes/scripts/suite_contract.py +++ b/services/hermes/scripts/suite_contract.py @@ -8,6 +8,8 @@ from collections import Counter REVISION = "suite-v6-20260929" PROMPT_REVISION = "implementation-proximity-v2-20260929" +EXECUTION_REVISION = "claude-diagnostics-turns-v1-20260929" +CLAUDE_MAX_TURNS = 6 MAX_BODY = 1 << 20 MAX_RESULT = 1 << 20 MAX_CASES = 400 @@ -23,7 +25,7 @@ MODELS = { "claude": {"model": "claude-opus-4-8", "context": 1000000, "cli_model": "claude-opus-4-8[1m]", "output": 64000, "overhead": 8192, "backend": "claude-code-2.1.226", - "enabled": True, "reasoning": "medium"}, + "enabled": True, "reasoning": "medium", "max_turns": CLAUDE_MAX_TURNS}, "codex": {"model": "gpt-6-astra", "context": 258400, "output": None, "overhead": None, "backend": "codex-subscription-broker", "enabled": False, "reasoning": "medium", @@ -194,10 +196,11 @@ def preflight(request): reserve = output_estimate + (8192 if provider == "claude" else 0) schema_extra = len(encoded([c["alias"] for c in request["cases"]])) + 16 if provider == "local" else 0 total_input = input_bytes + schema_extra - if reserve > model["output"] or total_input + model["overhead"] + model["output"] * (3 if provider == "claude" else 1) > model["context"]: + if reserve > model["output"] or total_input + model["overhead"] + model["output"] * model.get("max_turns", 1) > model["context"]: reasons[provider] = "capacity" continue return {"provider": provider, **model, "configuration_revision": REVISION, + "execution_revision": EXECUTION_REVISION, "prompt_revision": PROMPT_REVISION, "prompt_sha256": PROMPT_SHA256, "input_bytes": total_input, "input_token_count": None, "input_token_bound": total_input + model["overhead"], diff --git a/services/hermes/scripts/suite_jobs.py b/services/hermes/scripts/suite_jobs.py index 7ac3acba..2bc01d83 100644 --- a/services/hermes/scripts/suite_jobs.py +++ b/services/hermes/scripts/suite_jobs.py @@ -8,7 +8,7 @@ import time import uuid import suite_backends -from suite_contract import (PROMPT_REVISION, PROMPT_SHA256, Problem, RESULT_TTL, +from suite_contract import (EXECUTION_REVISION, PROMPT_REVISION, PROMPT_SHA256, Problem, RESULT_TTL, REVISION, digest, validate_result) IDEMPOTENCY_TTL = 7 * 86400 @@ -77,6 +77,7 @@ class Jobs: job_id = uuid.uuid4().hex document = {"job_id": job_id, "status": "accepted", "configuration_revision": REVISION, "routing": request["routing"], + "execution_revision": EXECUTION_REVISION, "prompt_revision": PROMPT_REVISION, "prompt_sha256": PROMPT_SHA256, "selection": selected, "attempted_destinations": [], "compaction": None, "truncation": None, "usage": None, @@ -134,7 +135,12 @@ class Jobs: result, metadata = suite_backends.local_generate(effective, event, client_ip) else: result, metadata = suite_backends.claude_generate(effective, event) - validate_result(result, request) + document.update(metadata) + try: + validate_result(result, request) + except Problem as exc: + raise Problem(exc.code, exc.status, **metadata.get("cli_diagnostics", {}), + failure_stage="result_validation") from None if event.is_set(): raise Problem("cancelled", 409) document.update(metadata, status="completed") @@ -143,6 +149,11 @@ class Jobs: del self.results[min(self.results, key=lambda key: self.results[key][0])] self.results[job_id] = (time.time() + RESULT_TTL, result) except Problem as exc: + if "final_event_seen" in exc.details: + document.update(cli_diagnostics=exc.details, + usage=exc.details.get("usage"), turns=exc.details.get("turns"), + duration_api_ms=exc.details.get("duration_api_ms"), + cost_usd_estimate=exc.details.get("cost_usd_estimate")) document.update(status="cancelled" if exc.code == "cancelled" else "failed", **exc.document()) except Exception: diff --git a/services/hermes/suite-planner-deployment.yaml b/services/hermes/suite-planner-deployment.yaml index 24914128..286f03fb 100644 --- a/services/hermes/suite-planner-deployment.yaml +++ b/services/hermes/suite-planner-deployment.yaml @@ -36,7 +36,7 @@ spec: app: hermes-suite-planner annotations: fluentbit.io/exclude: "true" - ai.bstein.dev/config-rev: suite-v6-prompt-v2-20260929 + ai.bstein.dev/config-rev: suite-v6-prompt-v2-diagnostics-v1-20260929 vault.hashicorp.com/agent-inject: "true" vault.hashicorp.com/agent-pre-populate-only: "true" vault.hashicorp.com/agent-init-first: "true" diff --git a/testing/tests/test_suite_cli_diagnostics.py b/testing/tests/test_suite_cli_diagnostics.py new file mode 100644 index 00000000..f3f8e192 --- /dev/null +++ b/testing/tests/test_suite_cli_diagnostics.py @@ -0,0 +1,230 @@ +"""Failure-stage, subprocess cleanup, and metadata privacy regression tests.""" +import json +from pathlib import Path +import signal +import sys +import threading + +import pytest + +sys.path.insert(0, str(Path(__file__).resolve().parents[2] / "services/hermes/scripts")) +import suite_backends +from suite_cli_diagnostics import snapshot +from suite_contract import CLAUDE_MAX_TURNS, MODELS, Problem, preflight, validate_request +from suite_jobs import Jobs + +MODEL = MODELS["claude"]["model"] +CANARY = "PRIVATE_SOURCE_OR_PROVIDER_ERROR_MUST_NOT_ESCAPE" + + +def envelope(**changes): + """Construct synthetic native CLI events, with content canaries.""" + init = {"type": "system", "subtype": "init", "model": MODEL, + "tools": ["StructuredOutput"], "mcp_servers": [], "plugins": []} + final = {"type": "result", "subtype": "success", "is_error": False, + "num_turns": 2, "stop_reason": "tool_use", + "usage": {"input_tokens": 120, "output_tokens": 50, CANARY: CANARY}, + "modelUsage": {MODEL: {"contextWindow": 1000000, "maxOutputTokens": 64000, + "canonicalModel": MODEL, "provider": "firstParty", CANARY: CANARY}}, + "structured_output": {"groups": [{"name": "Synthetic", "description": CANARY, + "members": ["CASE-1"]}]}, + "errors": [CANARY], "result": CANARY, **changes} + return "\n".join(json.dumps(event) for event in (init, final)) + + +def request(): + """Force the approved Claude route with synthetic input too large for local.""" + return validate_request({"campaign": "SYNTHETIC", "suite": "DIAGNOSTICS", + "cases": [{"alias": "CASE-1", "description": "Synthetic example. " * 500}], + "routing": {"allow_external": True, "allowed_external_providers": ["claude"]}}, ["claude"]) + + +@pytest.mark.parametrize("subtype,code", [ + ("error_max_turns", "incomplete_generation"), + ("error_max_structured_output_retries", "incomplete_generation"), + ("error_max_budget_usd", "incomplete_generation"), + ("error_during_execution", "incomplete_generation"), + (CANARY, "incomplete_generation"), +]) +def test_unsuccessful_final_is_specific_and_content_free(subtype, code): + raw = envelope(subtype=subtype, is_error=True, num_turns=4, structured_output=None) + with pytest.raises(Problem, match=code) as raised: + suite_backends.parse_claude(raw, MODEL, exit_code=1, subprocess_timeout_seconds=899.5) + details = raised.value.details + assert details["failure_stage"] == "cli_final_result" + assert details["exit_code"] == 1 and details["turns"] == 4 + assert details["max_turns"] == CLAUDE_MAX_TURNS == 6 + assert details["turn_limit_reached"] == (None if subtype == CANARY else subtype == "error_max_turns") + assert details["structured_retry_limit_reached"] == (None if subtype == CANARY else subtype == "error_max_structured_output_retries") + assert details["usage"] == {"input_tokens": 120, "output_tokens": 50} + assert details["structured_output_present"] is False + assert CANARY not in json.dumps(raised.value.document()) + + +@pytest.mark.parametrize("status,code", [(429, "rate_limit"), (401, "provider_authentication"), (403, "provider_authentication")]) +def test_provider_error_status_is_preserved(status, code): + with pytest.raises(Problem, match=code) as raised: + suite_backends.parse_claude(envelope(subtype="error_during_execution", is_error=True, + api_error_status=status), MODEL, exit_code=1) + assert raised.value.details["api_error_status"] == status + + +@pytest.mark.parametrize("reason", ["max_tokens", "model_context_window_exceeded"]) +def test_explicit_provider_stop_distinct_from_turn_limit(reason): + with pytest.raises(Problem, match="incomplete_generation") as raised: + suite_backends.parse_claude(envelope(stop_reason=reason), MODEL, exit_code=0) + assert raised.value.details["failure_stage"] == "provider_stop" + assert raised.value.details["provider_stop_reason"] == reason + assert raised.value.details["turn_limit_reached"] is False + + +@pytest.mark.parametrize("raw,stage,code", [ + ("", "missing_init_or_final_event", "incomplete_generation"), + ('{"type":"system","subtype":"init","model":"claude-opus-4-8"}', "missing_init_or_final_event", "incomplete_generation"), + ("not json " + CANARY, "cli_event_json", "invalid_json_result"), + ("[]", "cli_event_json", "invalid_json_result"), +]) +def test_missing_final_and_malformed_stream_are_distinct(raw, stage, code): + with pytest.raises(Problem, match=code) as raised: + suite_backends.parse_claude(raw, MODEL, exit_code=0) + assert raised.value.details["failure_stage"] == stage + assert CANARY not in json.dumps(raised.value.document()) + + +def test_text_or_tool_candidate_is_detected_but_not_silently_accepted(): + value = json.loads(envelope().splitlines()[-1])["structured_output"] + assistant = {"type": "assistant", "message": {"stop_reason": "end_turn", "content": [ + {"type": "tool_use", "name": "StructuredOutput", "input": value}, + {"type": "text", "text": json.dumps(value)}]}} + raw = json.dumps(assistant) + "\n" + envelope(structured_output=None, result=json.dumps(value)) + with pytest.raises(Problem, match="invalid_json_result") as raised: + suite_backends.parse_claude(raw, MODEL, exit_code=0) + details = raised.value.details + assert details["failure_stage"] == "structured_output_extraction" + assert details["assistant_structured_tool_input_present"] is True + assert details["assistant_json_text_present"] is True + assert details["final_json_text_present"] is True + assert CANARY not in json.dumps(details) + + +def test_valid_structured_result_and_exit_status_both_checked(): + raw = envelope() + result, metadata = suite_backends.parse_claude(raw, MODEL, exit_code=0) + assert result["groups"][0]["description"] == CANARY + assert CANARY not in json.dumps(metadata) + for code in (1, -signal.SIGKILL): + with pytest.raises(Problem, match="incomplete_generation") as raised: + suite_backends.parse_claude(raw, MODEL, exit_code=code) + assert raised.value.details["failure_stage"] == "process_exit" + assert raised.value.details["structured_output_present"] is True + assert raised.value.details["termination_signal"] == (signal.SIGKILL if code < 0 else None) + + +def test_unknown_measurements_never_become_content_or_fabricated_zeroes(): + details = snapshot(envelope(num_turns=CANARY, usage={"input_tokens": True, "output_tokens": float("nan")}, + duration_api_ms=CANARY, total_cost_usd=float("inf"), stop_reason=CANARY)) + assert details["turns"] is None and details["duration_api_ms"] is None + assert details["usage"] == {"input_tokens": None, "output_tokens": None} + assert details["provider_stop_reason"] == "other" + assert details["provider_timeout_seconds"] is None and details["reasoning_token_limit"] is None + assert CANARY not in json.dumps(details, allow_nan=False) + + +@pytest.mark.parametrize("mutation,code", [("schema", "invalid_json_result"), ("coverage", "invalid_case_assignments")]) +def test_validation_failure_retains_usage_without_accepting_content(tmp_path, monkeypatch, capsys, mutation, code): + value = request() + selected = preflight(value) + result, metadata = suite_backends.parse_claude(envelope(), MODEL, exit_code=0) + if mutation == "schema": + result["groups"][0]["description"] = "x" * 241 + else: + result["groups"][0]["members"].append("CASE-1") + monkeypatch.setattr(suite_backends, "switchyard_decision", lambda *_: None) + monkeypatch.setattr(suite_backends, "claude_generate", lambda *_: (result, metadata)) + jobs = Jobs(tmp_path / "jobs.sqlite") + job, _ = jobs.submit("owner", "synthetic-validation", value, selected, "192.168.22.8", launch=False) + jobs.run(job["job_id"], "owner", value, selected, "192.168.22.8") + failed = jobs.get(job["job_id"], "owner") + assert failed["error"]["code"] == code + assert failed["error"]["details"]["failure_stage"] == "result_validation" + assert failed["usage"]["output_tokens"] == 50 and failed["turns"] == 2 + assert not jobs.results + assert CANARY not in json.dumps(failed) + capsys.readouterr().out + + +@pytest.mark.parametrize("mode,code,stage", [ + ("success", None, None), ("nonzero", "incomplete_generation", "process_exit"), + ("signal", "incomplete_generation", "process_exit"), + ("empty", "backend_unavailable", "process_exit"), + ("timeout", "timeout", "subprocess"), ("cancel", "cancelled", "subprocess"), + ("oversize", "response_too_large", "subprocess"), + ("start", "backend_unavailable", "process_start"), +]) +def test_actual_subprocess_paths_cleanup_and_safe_metadata(tmp_path, monkeypatch, mode, code, stage): + real_tempdir = suite_backends.tempfile.TemporaryDirectory + real_read = Path.read_text + monkeypatch.setattr(suite_backends.tempfile, "TemporaryDirectory", + lambda **_: real_tempdir(prefix="suite-", dir=tmp_path)) + monkeypatch.setattr(Path, "read_text", lambda p, *a, **k: "fake-token" if str(p) == "/vault/secrets/claude-token" else real_read(p, *a, **k)) + script = "import os,signal,time; print(" + repr(envelope()) + ",flush=True); " + if mode in {"timeout", "cancel"}: + script += "time.sleep(30)" + elif mode == "signal": + script += "os.kill(os.getpid(),signal.SIGKILL)" + elif mode == "nonzero": + script += "raise SystemExit(1)" + elif mode == "empty": + script = "raise SystemExit(1)" + elif mode == "oversize": + monkeypatch.setattr(suite_backends, "OUTPUT_BYTES", 64) + command = ["/not-installed-synthetic-cli"] if mode == "start" else [sys.executable, "-c", script] + monkeypatch.setattr(suite_backends, "claude_command", lambda *_: command) + value, cancel = request(), threading.Event() + if mode == "timeout": + value["execution"]["max_seconds"] = 0.02 + if mode == "cancel": + cancel.set() + if code: + with pytest.raises(Problem, match=code) as raised: + suite_backends.claude_generate(value, cancel) + details = raised.value.details + assert details["failure_stage"] == stage + if mode in {"timeout", "cancel"}: + assert details["termination_signal"] == signal.SIGTERM + assert details["termination_reason"] == mode.replace("cancel", "cancelled") + assert CANARY not in json.dumps(details) + else: + _, metadata = suite_backends.claude_generate(value, cancel) + assert metadata["cli_diagnostics"]["exit_code"] == 0 + assert metadata["temporary_files_deleted"] is True + assert list(tmp_path.iterdir()) == [] + + +def test_failed_cli_usage_survives_job_cleanup_without_content(tmp_path, monkeypatch, capsys): + value, jobs = request(), Jobs(tmp_path / "jobs.sqlite") + selected = preflight(value) + monkeypatch.setattr(suite_backends, "switchyard_decision", lambda *_: None) + def fail(*_): + suite_backends.parse_claude(envelope(subtype="error_max_turns", is_error=True, + structured_output=None), MODEL, exit_code=1) + monkeypatch.setattr(suite_backends, "claude_generate", fail) + document, _ = jobs.submit("owner", "synthetic-failure", value, selected, "192.168.22.8", launch=False) + jobs.run(document["job_id"], "owner", value, selected, "192.168.22.8") + failed = jobs.get(document["job_id"], "owner") + assert failed["error"]["details"]["turn_limit_reached"] is True + assert failed["usage"]["output_tokens"] == 50 + assert not jobs.results and not jobs.active + replay, created = jobs.submit("owner", "synthetic-failure", value, selected, "192.168.22.8", launch=False) + assert not created and replay["job_id"] == document["job_id"] + assert CANARY not in json.dumps(failed) + capsys.readouterr().out + + +def test_process_exit_race_still_reaps(monkeypatch): + from types import SimpleNamespace + waited = [] + def exited(*_): + raise ProcessLookupError() + monkeypatch.setattr(suite_backends.os, "killpg", exited) + process = SimpleNamespace(pid=1, poll=lambda: None, wait=lambda **_: waited.append(True)) + suite_backends.stop(process) + assert waited == [True]