diff --git a/scripts/ci/contextual_orchestrator_review_sidecar.sh b/scripts/ci/contextual_orchestrator_review_sidecar.sh index a08e26297b..a5743a5222 100755 --- a/scripts/ci/contextual_orchestrator_review_sidecar.sh +++ b/scripts/ci/contextual_orchestrator_review_sidecar.sh @@ -53,7 +53,42 @@ fi log() { printf '[contextual-orchestrator-sidecar] %s\n' "$*"; } -fail() { log "error: $*" >&2; exit 1; } +# Phase receipts for gateway-performance attribution: one line per startup +# phase boundary carrying seconds elapsed on a monotonic clock (Linux +# /proc/uptime; bash $SECONDS where it is absent), the vendored orchestrator +# pin and the workflow revision. A loop or poll count is not elapsed time. +# These lines never carry prompt, credential, or provider content, and they +# change no timeout, retry, readiness, routing, or model behavior. +sidecar_clock() { + local uptime_seconds _idle + if [ -r /proc/uptime ] && read -r uptime_seconds _idle < /proc/uptime; then + printf '%s' "$uptime_seconds" + else + printf '%s' "$SECONDS" + fi +} +sidecar_clock_origin="$(sidecar_clock)" +sidecar_phase="" +phase() { + local now + now="$(sidecar_clock)" + case "$2" in + start) sidecar_phase="$1" ;; + end) sidecar_phase="" ;; + esac + log "phase=$1 event=$2 elapsed_s=$(awk -v now="$now" -v origin="$sidecar_clock_origin" 'BEGIN { printf "%.2f", now - origin }') orchestrator_sha=${ORCHESTRATOR_PIN_SHA:-unknown} workflow_sha=${GITHUB_WORKFLOW_SHA:-unknown}${3:+ ${*:3}}" +} + +# set -e can exit without calling fail(); close that phase before EXIT cleanup. +trap 'if [ -n "$sidecar_phase" ]; then phase "$sidecar_phase" end outcome=failed; fi' ERR + +fail() { + if [ -n "$sidecar_phase" ]; then + phase "$sidecar_phase" end outcome=failed + fi + log "error: $*" >&2 + exit 1 +} # Require at least one of the five provider secrets so we never boot an empty # (or mock) pool. Missing individual secrets are allowed — discovery skips the @@ -96,6 +131,7 @@ token_file="$ORCHESTRATOR_WORK/bearer.token" ) chmod 600 -- "$token_file" rm -rf "$ORCHESTRATOR_SOURCE" +phase vendoring start log "vendoring contextual-orchestrator @ ${ORCHESTRATOR_PIN_SHA}" git clone --quiet --filter=blob:none --no-checkout "$ORCHESTRATOR_GIT_URL" "$ORCHESTRATOR_SOURCE" git -C "$ORCHESTRATOR_SOURCE" -c advice.detachedHead=false checkout --quiet "$ORCHESTRATOR_PIN_SHA" @@ -107,6 +143,8 @@ requirements_lock="$ORCHESTRATOR_SOURCE/requirements.lock" if [ ! -f "$requirements_lock" ]; then fail "vendored orchestrator is missing its hash-pinned requirements.lock" fi +phase vendoring end outcome=ok +phase dependency_install start # The pinned lock includes CPython 3.12 wheels; isolate them from consumer runtimes. "$sidecar_python" -c 'import sys; sys.exit(0 if sys.version_info[:2] == (3, 12) else "sidecar requires Python 3.12 for its pinned wheel hashes")' "$sidecar_python" -m venv "$ORCHESTRATOR_WORK/.venv" @@ -118,6 +156,7 @@ log "installing hash-pinned orchestrator dependencies at ${checked_out}" -r "$requirements_lock" PYTHONPATH="$ORCHESTRATOR_SOURCE:$ORG_REPO_ROOT" "$sidecar_python" -c \ 'from contextual_orchestrator.credentials import get_credential; from contextual_orchestrator.model_discovery import discover_all_models, free_discovered_models; from contextual_orchestrator.orchestrator import ModelClient, TaskOrchestrator, load_agents; from contextual_orchestrator.review_gateway import register_review_credentials; from contextual_orchestrator.server import SecurityConfig, serve' +phase dependency_install end outcome=ok PYTHONPATH="$ORCHESTRATOR_SOURCE:$ORG_REPO_ROOT" "$sidecar_python" - <<'PY' import faulthandler @@ -314,6 +353,7 @@ case "$orchestrator_pool" in ;; esac +phase route_readiness start log "starting review sidecar on ${ORCHESTRATOR_HOST}:${ORCHESTRATOR_PORT}" cp "$ORCHESTRATOR_LAUNCHER" "$ORCHESTRATOR_WORK/launch_sidecar.py" export ORCHESTRATOR_CATALOG_LIMIT="$CATALOG_LIMIT" @@ -403,6 +443,7 @@ if [ ! -s "$preflight_report" ]; then fi publish_sidecar_evidence log "healthz and provider-route preflight confirmed after ${i}s (pid $sidecar_pid)" +phase route_readiness end outcome=ready health_polls="$i" # A successful startup never re-reads $sidecar_stderr otherwise: only the # failure branches above embed it in their ::error:: message. A partial, # non-fatal provider discovery failure (e.g. one bad credential) would @@ -434,6 +475,7 @@ fi # process can be healthy while the coordinator/model-group path still raises an # internal error, which is the failure this contract prevents from reaching the # scanner step. +phase gateway_probe start gateway_virtual_model="orchestrator/${orchestrator_pool}" # max_tokens must match REVIEW_MAX_OUTPUT_TOKENS (the launcher's own escalated # per-agent routing-probe budget, ADR-0005): observed behavior was an agent the @@ -697,6 +739,7 @@ then fail "gateway preflight returned unusable chat content" fi log "gateway chat/completions preflight confirmed (attempt ${gateway_attempt}/${REVIEW_PREFLIGHT_GATEWAY_MAX_ATTEMPTS})" +phase gateway_probe end outcome=ready attempts="$gateway_attempt" if [ -n "$ORCHESTRATOR_GITHUB_ENV" ]; then { diff --git a/tests/test_contextual_orchestrator_review_sidecar_contract.py b/tests/test_contextual_orchestrator_review_sidecar_contract.py index 9125411060..0b9687d4fe 100644 --- a/tests/test_contextual_orchestrator_review_sidecar_contract.py +++ b/tests/test_contextual_orchestrator_review_sidecar_contract.py @@ -593,6 +593,128 @@ def test_required_strix_uses_the_gateway_and_zdr_visibility_contract() -> None: assert "STRIX_FALLBACK_MODELS: \"\"" in workflow +def _phase_helpers() -> str: + """Return the sidecar's clock, phase and fail helper definitions verbatim.""" + text = _read(SIDECAR) + start = text.index("sidecar_clock() {") + end = text.index("\n}\n", text.index("fail() {")) + len("\n}\n") + return text[start:end] + + +def test_phase_receipts_report_monotonic_elapsed_and_failed_phase() -> None: + """Phase lines carry measured elapsed time and name the phase a failure ended.""" + import re + + harness = ( + "set -euo pipefail\n" + "log() { printf '[t] %s\\n' \"$*\"; }\n" + 'ORCHESTRATOR_PIN_SHA="0123456789abcdef0123456789abcdef01234567"\n' + + _phase_helpers() + + "phase alpha start\n" + "phase alpha end outcome=ok health_polls=3\n" + "phase beta start\n" + 'fail "boom"\n' + ) + result = subprocess.run( + ["bash", "-c", harness], + env={**os.environ, "GITHUB_WORKFLOW_SHA": "feedface"}, + text=True, + capture_output=True, + check=False, + ) + + assert result.returncode == 1 + assert "[t] error: boom" in result.stderr + lines = [line for line in result.stdout.splitlines() if " phase=" in line] + pattern = re.compile( + r"^\[t\] phase=(\w+) event=(start|end) elapsed_s=(\d+\.\d\d) " + r"orchestrator_sha=0123456789abcdef0123456789abcdef01234567 " + r"workflow_sha=feedface(.*)$" + ) + parsed = [pattern.match(line) for line in lines] + assert all(parsed), lines + assert [(m.group(1), m.group(2), m.group(4)) for m in parsed] == [ + ("alpha", "start", ""), + ("alpha", "end", " outcome=ok health_polls=3"), + ("beta", "start", ""), + ("beta", "end", " outcome=failed"), + ] + elapsed = [float(m.group(3)) for m in parsed] + assert elapsed == sorted(elapsed) + + +def test_fail_outside_a_phase_emits_no_phase_receipt() -> None: + """A failure before any phase starts (or after one ends) adds no phase line.""" + harness = ( + "set -euo pipefail\n" + "log() { printf '[t] %s\\n' \"$*\"; }\n" + + _phase_helpers() + + "phase alpha start\nphase alpha end outcome=ok\n" + 'fail "late"\n' + ) + result = subprocess.run(["bash", "-c", harness], text=True, capture_output=True, check=False) + + assert result.returncode == 1 + assert result.stdout.count(" phase=") == 2 + assert "orchestrator_sha=unknown" in result.stdout + + +def test_dependency_install_command_failure_closes_phase_once(tmp_path) -> None: + """A failed real install command must leave one failed phase receipt.""" + text = _read(SIDECAR) + start = text.index("phase dependency_install start") + end = text.index("phase dependency_install end outcome=ok", start) + install = text[start : end + len("phase dependency_install end outcome=ok")] + python = tmp_path / "failing-python" + python.write_text("#!/bin/sh\nexit 42\n", encoding="utf-8") + python.chmod(0o700) + harness = ( + "set -euo pipefail\n" + "log() { printf '[t] %s\\n' \"$*\"; }\n" + + _phase_helpers() + + f'sidecar_python="{python}"\n' + + 'checked_out="a"\nrequirements_lock="/missing.lock"\n' + + 'ORCHESTRATOR_SOURCE="/missing"\nORG_REPO_ROOT="/missing"\n' + + install + + "\n" + ) + result = subprocess.run(["bash", "-c", harness], text=True, capture_output=True, check=False) + + assert result.returncode == 42 + assert result.stdout.count("phase=dependency_install event=start") == 1 + assert result.stdout.count("phase=dependency_install event=end") == 1 + assert "phase=dependency_install event=end" in result.stdout + assert "outcome=failed" in result.stdout + assert "outcome=ok" not in result.stdout + + +def test_sidecar_emits_phase_receipts_in_startup_order_without_changing_gates() -> None: + """Every startup phase opens and closes once, in order, around the existing gates.""" + text = _read(SIDECAR) + markers = [ + "phase vendoring start", + 'log "vendoring contextual-orchestrator @ ${ORCHESTRATOR_PIN_SHA}"', + "phase vendoring end outcome=ok", + "phase dependency_install start", + "phase dependency_install end outcome=ok", + "phase route_readiness start", + 'log "healthz and provider-route preflight confirmed after ${i}s (pid $sidecar_pid)"', + 'phase route_readiness end outcome=ready health_polls="$i"', + "phase gateway_probe start", + 'gateway_virtual_model="orchestrator/${orchestrator_pool}"', + 'phase gateway_probe end outcome=ready attempts="$gateway_attempt"', + ] + positions = [text.index(marker) for marker in markers] + assert positions == sorted(positions) + for marker in markers: + if marker.startswith("phase "): + assert text.count(marker) == 1, marker + # The receipt format references only clock, phase and revision fields. + phase_body = _phase_helpers() + for forbidden in ("TOKEN", "token_file", "_API_KEY", "SECRET", "prompt"): + assert forbidden not in phase_body + + def test_sidecar_uses_lock_compatible_isolated_python() -> None: """Every entry point provisions the wheel ABI before an isolated installation.""" text = _read(SIDECAR)