Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 14 additions & 0 deletions docs/latency-observability.md
Original file line number Diff line number Diff line change
Expand Up @@ -500,6 +500,20 @@ still has the anchor. `elapsed_ms` and every `interview_ms` read the same clock,
which a socket replacement does not reset, so a long harness can verify the
full duration from the last sample.

#### Emission clock samples

Each new `reply_latency` record also carries a `clock` object containing
`start_unix_ms`, `emitted_unix_ms`, `emitted_ms` and `clock_uncertainty_ms`.
These additive fields keep the existing record version. The wall time is
sampled afresh, bracketed by monotonic reads; uncertainty includes the anchor
sample, current sampling and millisecond rounding. An absent wall reading or
anchor remains null, never zero. The event's `interview_ms` is distinct from
the emission sample: a provider event may have waited in the handler's queue.
These samples support detecting wall-clock drift in a short replay without
waiting for a minute clock line; they do not measure browser or network delay.
The [floor observation contract](turn-timing.md#opening-and-resolution-clocks)
defines the additional floor times and tool-gate invalidation diagnostics.

#### Microphone dequeue gaps

Each `interview clock:` line also carries `mic_gap_max_ms=`,
Expand Down
258 changes: 258 additions & 0 deletions docs/observational-replay.md

Large diffs are not rendered by default.

103 changes: 85 additions & 18 deletions docs/turn-timing.md
Original file line number Diff line number Diff line change
Expand Up @@ -186,26 +186,90 @@ logged. Activity is eligible only with a candidate audio track, outside a
thinking hold and discarded output. PCM levels and transcripts cannot open
records.

### Opening and resolution clocks

Floor lines append `opened_ms`, `resolved_ms`, `activity_end_ms`, `emitted_ms`,
`emitted_unix_ms`, `start_unix_ms`, `clock_uncertainty_ms` and process `pid`. Event offsets use
the same anchored monotonic clock as latency records. Missing anchors stay
`unknown`; the runtime state's coarse display clock is never a substitute.
`resolved_ms` is set once when the outcome leaves unresolved, not when a
buffered record emits. For an overlap, `activity_end_ms` records candidate END
separately: END may precede or follow interruption/drain. Reset/lost activity
that turns an unended overlap back into unresolved clears its resolution.
These fields do not alter any observation outcome, flag or interview action.

The emission clock pairs a fresh wall reading with monotonic sampling bounds.
`clock_uncertainty_ms` includes the original anchor's sampling duration, the
current sample's duration and whole-millisecond rounding. It does not bound
wall-clock steps/slew, network, provider, browser scheduling or handler lag. A consumer must retain
its own injection bracket and uncertainty, verify anchor identity and clock
drift, and reject ambiguous or out-of-window attribution. Emission order and
max emitted sequence remain insufficient for joining an injection to a record.

Tool-response latency records include allowlisted `accepted_tool_names`,
`hint_given` and `closing`, separate from `sent`. `closing` observes the existing
end-requested or ended state after the batch; it does not end the session. Accepted means no tool error, not that a
response was delivered. `hint_given` means this batch advanced an authored hint
rung or recorded a volunteered hint; withheld/exhausted requests cannot supply
hint context merely because their tool response has no error. It establishes
server tool context, never the content or audibility of a generated phrase.

`codetrial replay_gate` JSON lines carry `event=gate_boundary`, version 1,
room/process/session/socket identity, optional turn, stage, event `interview_ms`
and an emission `clock` sample. `event_end_ms` is the upper bound of the
observed transition. For an ordinary provider boundary, `interview_ms` is when
the event arrived and `event_end_ms` is when the room loop handled it, so a
boundary queued behind a tool send spans that wait; only records without the
field have equal endpoints. A boundary may also appear as a latency record of
the same stage, and a consumer treats the pair as one event.
A `close_requested` observation brackets the tool call that first requests an
end, before any asynchronous response/board work. A `closing` observation
brackets the control reduction that first ends the session, before farewell or
report work. These observations leave reply traces intact. A consumer must
retain the interval rather than assigning a delayed transition to its emission
time. Missing interval fields on older ordinary boundaries mean their original
single event offset. Each invocation of the latency boundary handler
emits one, even without an open reply trace: accepted turn completion or
interruption, hold, and socket replacement cannot silently leave an old tool
gate eligible. Provider events rejected by existing acceptance, hold or discard
guards do not create new boundaries; the hold/replacement that invalidated
context is already authoritative. These diagnostics change neither provider
acceptance nor the room's state transitions.

### Retaining browser-check evidence

For Rust and dispatch modes, `scripts/browser-check.sh` creates a private
`codetrial-floor.*` file outside its temporary server directory and prints its
path during cleanup. `BROWSER_CHECK_FLOOR_LOG` is an internal handoff to the
harness, not a caller-selected destination. The Node harness captures each
complete floor line before trimming its stderr buffer. A separate follower
reads dispatched-agent diagnostics from server byte zero, and uses a completion
marker to drain the server log after server teardown before the temporary
directory is deleted. Each line is appended with one synchronous write and is
not fsynced, so it survives a killed process but not power loss. On group
signals the follower waits for the completion marker, with a five-second
fallback; if its parent disappears it drains once and exits instead of polling
forever. Lines split across reads are joined; oversized lines and unrelated
output are excluded. Review and remove retained artifacts when no longer
needed. These diagnostics contain identifiers but no interview content.

`BROWSER_CHECK_CAPTURE`, when provided, includes `floorLogPath`, a snapshot of
record fields (including socket and sequence ids), and barge replay
state/timestamp metadata. Refused injections record an exclusion category and
For Rust and dispatch modes, `scripts/browser-check.sh` creates private
`codetrial-floor.*` and `codetrial-latency.*` files outside its temporary server
directory and prints both paths during cleanup. `BROWSER_CHECK_FLOOR_LOG` and
`BROWSER_CHECK_LATENCY_LOG` are internal handoffs, not caller-selected paths.
The Node harness retains complete floor and latency lines before trimming its
stderr tail. The latency file also keeps `interview clock:`, `replacement start:`,
`replacement end:` and `codetrial replay_gate` lines. In dispatch mode a single follower reads server
diagnostics from byte zero and uses a completion marker to drain the server log
after teardown before the temporary directory is deleted. Rust mode captures
its own agent's pipes instead, including their final close after group shutdown.

Each retained line is appended with one synchronous write and is not fsynced:
it survives a killed process but not power loss. Each pipe has a separate UTF-8
line buffer; complete lines are capped at 4,096 bytes including the newline.
Unrelated output is excluded. Oversized, unterminated, malformed UTF-8 or
unframed diagnostics leave a content-free `codetrial capture_incomplete` marker
in the relevant file, with its family and reason. A pipe error, failed write,
missed drain deadline or observed source-file replacement/shrink also leaves
incomplete evidence or a nonzero harness exit. An observational judge must
classify these as incomplete, never passing evidence; the legacy barge smoke
still checks only for its measured interrupted overlap. No dropped stderr
content is copied into a marker. Dispatch against an external server marks
both artifacts unavailable because this runner cannot follow that server's log.

On group signals the dispatched follower waits for the completion marker with
a five-second fallback; if its parent disappears it drains once and exits.
Review and remove retained artifacts when no longer needed. These diagnostics
contain identifiers but no interview content.

`BROWSER_CHECK_CAPTURE`, when provided, includes `floorLogPath`, `latencyLogPath`
and a snapshot of floor record fields (including socket and sequence ids), plus
barge replay state/timestamp metadata. Refused injections record an exclusion category and
observed state, so a misaligned trial stays distinct from a provider failure.
Files survive failed and interrupted runs. Abrupt process termination cannot
synthesize terminal records for still-open provider observations; missing END
Expand All @@ -220,6 +284,9 @@ for its room in the durable file; transcript order alone cannot pass the smoke.
This proves neither hint/tool-state alignment nor physical audibility. H-3/TT-2
still need separately digested WAV and headerless 16 kHz mono s16le PCM
fixtures, a replay pilot and explicit exclusion counts for misaligned trials.
The [observational replay contract](observational-replay.md) defines the named
fixture format and offline validator; its transport and evidence requirements
remain prerequisites for that pilot.

## Continuity gaps

Expand Down
37 changes: 37 additions & 0 deletions scripts/browser-check-cleanup.cjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
const { drainDiagnosticStreams } = require("./floor-capture.cjs");

// Attempt every owned-resource cleanup; a secondary failure cannot replace
// the run's budget/soak outcome, and the first cleanup failure keeps its cause.
async function cleanupBrowserCheck({
stopAgent,
streams,
browser,
compilerExplorerMock,
operationFailed,
}) {
let failure;
for (const close of [
stopAgent,
() => drainDiagnosticStreams(streams),
() =>
compilerExplorerMock &&
new Promise((resolve, reject) => {
compilerExplorerMock.server.close((error) =>
error ? reject(error) : resolve(),
);
}),
() => browser.close(),
]) {
try {
await close();
} catch (error) {
failure ??= error;
}
}
if (failure) {
if (!operationFailed) throw failure;
console.error("browser check cleanup also failed after the run failed");
}
}

module.exports = { cleanupBrowserCheck };
41 changes: 28 additions & 13 deletions scripts/browser-check.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -19,10 +19,12 @@ const fs = require("fs");
const { mediaProbeSource, assertJimAudio } = require("./media-probe.cjs");
const { installBargeReplay } = require("./barge-replay.cjs");
const {
FloorCapture,
captureDiagnosticStream,
drainDiagnosticStreams,
assertInterruptedOverlap,
readFloorRecords,
} = require("./floor-capture.cjs");
const { cleanupBrowserCheck } = require("./browser-check-cleanup.cjs");
const http = require("http");
const { spawn } = require("child_process");
const {
Expand Down Expand Up @@ -79,6 +81,7 @@ const {
} = require("./soak-judge.cjs");

const floorLogPath = process.env.BROWSER_CHECK_FLOOR_LOG || null;
const latencyLogPath = process.env.BROWSER_CHECK_LATENCY_LOG || null;

// Written before the run can fail, so an aborted run still points at its
// retained floor log.
Expand All @@ -91,6 +94,7 @@ function writeIncompleteCapture(fields) {
flow: process.env.BROWSER_CHECK_FLOW,
status: "incomplete",
floorLogPath,
latencyLogPath,
...(soakSummary ? { soak: soakSummary } : {}),
...fields,
},
Expand Down Expand Up @@ -1255,6 +1259,7 @@ async function isolateRustAgent(
let rustAgent;
let compilerExplorerMock;
let agentDone = false;
const diagnosticStreams = [];

// Before a browser or an agent exists: a run launched by
// scripts/interview-run-budget.py joins its budget here, and a manifest the
Expand Down Expand Up @@ -1291,7 +1296,10 @@ async function isolateRustAgent(
console.error("run budget launcher is gone; stopping the check");
// The agent is detached, so neither this exit nor the shell reaches
// it, and the launcher that would have reaped it is the one that died.
await stopAgentGroup(rustAgent, 1500, true);
await stopAgentGroup(rustAgent, 1500, true).catch(() =>
console.error("agent stop failed during launcher cleanup"),
);
await drainDiagnosticStreams(diagnosticStreams, 1500).catch(() => {});
const closing = browser ? browser.close().catch(() => {}) : null;
await Promise.race([closing, new Promise((r) => setTimeout(r, 2000))]);
process.exit(4);
Expand Down Expand Up @@ -1346,6 +1354,7 @@ async function isolateRustAgent(
process.exit(1);
}

let operationFailed = false;
try {
const page = await browser.newPage();
let bargeReplay = null;
Expand Down Expand Up @@ -1540,11 +1549,13 @@ async function isolateRustAgent(
},
);
for (const stream of [rustAgent.stdout, rustAgent.stderr]) {
const streamCapture = floorLogPath
? new FloorCapture(floorLogPath)
: null;
diagnosticStreams.push(
captureDiagnosticStream(stream, {
floor: floorLogPath,
latency: latencyLogPath,
}),
);
stream.on("data", (chunk) => {
streamCapture?.push(chunk);
const text = redact(chunk);
if (
text.includes(
Expand All @@ -1555,7 +1566,6 @@ async function isolateRustAgent(
agentOutput.push(text);
while (agentOutput.join("").length > 12000) agentOutput.shift();
});
stream.once("close", () => streamCapture?.close());
}
agentFailure = new Promise((_, reject) => {
rustAgent.once("exit", (code, signal) => {
Expand Down Expand Up @@ -3290,6 +3300,7 @@ PatternLexicon.prototype.search = function(word) {
agentAfterCandidate,
rustAgentParticipants,
floorLogPath,
latencyLogPath,
floorRecords: floorLogPath
? readFloorRecords(floorLogPath)
: [],
Expand Down Expand Up @@ -3347,14 +3358,18 @@ PatternLexicon.prototype.search = function(word) {
throw error;
});
agentDone = true;
} catch (error) {
operationFailed = true;
throw error;
} finally {
agentDone = true;
await stopAgentGroup(rustAgent, 5000, false);
if (compilerExplorerMock)
await new Promise((resolve) =>
compilerExplorerMock.server.close(resolve),
);
await browser.close();
await cleanupBrowserCheck({
stopAgent: () => stopAgentGroup(rustAgent, 5000, false),
streams: diagnosticStreams,
browser,
compilerExplorerMock,
operationFailed,
});
}
})().catch((error) => {
// Redacted like every other error path in this file. This one is the last
Expand Down
15 changes: 11 additions & 4 deletions scripts/browser-check.sh
Original file line number Diff line number Diff line change
Expand Up @@ -152,6 +152,9 @@ cleanup()
if [ "${BROWSER_CHECK_FLOOR_LOG:-}" ]; then
echo "Floor diagnostics retained at $BROWSER_CHECK_FLOOR_LOG" >&2
fi
if [ "${BROWSER_CHECK_LATENCY_LOG:-}" ]; then
echo "Latency diagnostics retained at $BROWSER_CHECK_LATENCY_LOG" >&2
fi
rm -r "$TMP" 2> /dev/null || true
exit "$cleanup_status"
}
Expand Down Expand Up @@ -340,11 +343,15 @@ fi
if [ "$BROWSER_CHECK_AGENT" = rust ] || [ "$BROWSER_CHECK_AGENT" = dispatch ]; then
# Outside TMP: failure and signal cleanup must preserve early observations.
BROWSER_CHECK_FLOOR_LOG=$(mktemp "${TMPDIR:-/tmp}/codetrial-floor.XXXXXX")
export BROWSER_CHECK_FLOOR_LOG
# Only a server this script launches writes SERVER_LOG.
if [ -z "${CODETRIAL_WEB_URL:-}" ]; then
node "$ROOT/scripts/floor-capture.cjs" "$SERVER_LOG" "$BROWSER_CHECK_FLOOR_LOG" "$TMP/floor.done" &
BROWSER_CHECK_LATENCY_LOG=$(mktemp "${TMPDIR:-/tmp}/codetrial-latency.XXXXXX")
export BROWSER_CHECK_FLOOR_LOG BROWSER_CHECK_LATENCY_LOG
# Dispatched agents log to this server; a Rust-mode agent has its own pipes.
if [ "$BROWSER_CHECK_AGENT" = dispatch ] && [ -z "${CODETRIAL_WEB_URL:-}" ]; then
node "$ROOT/scripts/floor-capture.cjs" "$SERVER_LOG" "$BROWSER_CHECK_FLOOR_LOG" "$TMP/floor.done" "$BROWSER_CHECK_LATENCY_LOG" &
FLOOR_CAPTURE_PID=$!
elif [ "$BROWSER_CHECK_AGENT" = dispatch ]; then
printf '%s\n' 'codetrial capture_incomplete family=floor reason=external-server-log-unavailable' >> "$BROWSER_CHECK_FLOOR_LOG"
printf '%s\n' 'codetrial capture_incomplete family=latency reason=external-server-log-unavailable' >> "$BROWSER_CHECK_LATENCY_LOG"
fi
fi

Expand Down
Loading