ci(sidecar): emit monotonic phase receipts for gateway-performance attribution

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
   {

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)