From dba8a9679be05de27157c942bc21d35936f9f631 Mon Sep 17 00:00:00 2001 From: guantou Date: Wed, 7 Oct 2026 18:19:17 +0800 Subject: [PATCH 1/2] feat(052): lose the recording, never the shell (T036-T038) The rule the whole feature is subordinate to. The adapter now sits in preexec on every command of an engagement, holding the shell's descriptors, so every way it can fail is a way the operator's shell can fail -- in the middle of work that may not be repeatable. Unrecorded is bad; a wedged prompt, a lost reverse shell or a command reporting someone else's exit status is worse. T036, FR-009: with RedLog unreachable the commands already ran. Silently, which is the bug -- an operator whose RedLog crashed two hours ago has been working unrecorded with no way to know. They are now told, once, on the way in, and told again only if it comes back and goes away. A warning on every prompt is one an operator learns to read past, and then the one that matters is read past too. The startup banner said "command metadata will be logged" and offered redlog-run as the way to get output. Both stopped being true at T020, so the zsh adapter now announces "commands and their output" and bash announces "commands" -- a banner that overstates what is recorded is worse than none, because an operator who believes the output is in the record stops checking. T037 turned out to be a characterisation test: killing the relay underneath a running command already leaves the shell alive and already reports the command's own status to both the shell and the record. That is the T020 design working, and it is now pinned. T038, FR-029: the relay declines the shapes it cannot hold, before the command runs rather than noticing afterwards. cat log | less relayed on `cat`, the pager's stdout becomes a pipe and it stops being a pager. Any native or pty stage anywhere in a pipeline stands the whole line down. nmap | tee f not a hazard, and worth capturing: the last stage still writes to the terminal, which is what the relay holds. nmap -oN f > out stdout is already pointed elsewhere, so two processes are not started to watch an empty descriptor. The record says `redirected` either way (FR-008). One test needed a note of its own: `pkill -f` matches full command lines, so a command that kills its own relay matches itself and reports 143 -- which looks exactly like the bug being tested for. And RedLog cannot be made unreachable by omitting the credential files on this machine, because under WSL the adapter deliberately falls back to the Windows profile's .redlog, which is a real install. Co-Authored-By: Claude Opus 5 --- hooks/redlog-relay.py | 122 ++++++++++++++++++--- hooks/shell-bash-hook.sh | 5 +- hooks/shell-common.sh | 23 ++-- hooks/shell-zsh-hook.zsh | 32 +++++- test/zsh-degradation.pty.test.ts | 179 +++++++++++++++++++++++++++++++ 5 files changed, 336 insertions(+), 25 deletions(-) create mode 100644 test/zsh-degradation.pty.test.ts diff --git a/hooks/redlog-relay.py b/hooks/redlog-relay.py index e09794de..ba0019bd 100644 --- a/hooks/redlog-relay.py +++ b/hooks/redlog-relay.py @@ -39,6 +39,7 @@ import os import re import select +import shlex import subprocess import sys import time @@ -428,22 +429,10 @@ def classify(argv): # including `nc`. opts, command = parse(argv) policy = load_policy(terminal_home(opts)) - i = walk_wrappers(command, policy) - program = basename(command[i] if i < len(command) else "") - if program == "": - # Not a command. `native` and not `relayed`, so a bare Enter does not - # route the prompt itself through a relay. - result = "native" - elif program in policy["pty"]: - result = "pty" - elif program in policy["native"]: - result = "native" - elif program in policy["repl"]: - rest = command[i + 1:] - given = any(a in policy["replScriptFlags"] or not a.startswith("-") for a in rest) - result = "relayed" if given else "native" - else: - result = "relayed" + line = opts["command_line"] + result = classify_line(line, policy) if line else None + if result is None: + result = classify_argv(command, policy) sys.stdout.write(result) return 0 @@ -688,6 +677,107 @@ def read_overlay(opts): return value if isinstance(value, dict) else {} +def classify_argv(command, policy): + i = walk_wrappers(command, policy) + program = basename(command[i] if i < len(command) else "") + if program == "": + # Not a command. `native` and not `relayed`, so a bare Enter does not + # route the prompt itself through a relay. + return "native" + if program in policy["pty"]: + return "pty" + if program in policy["native"]: + return "native" + if program in policy["repl"]: + rest = command[i + 1:] + given = any(a in policy["replScriptFlags"] or not a.startswith("-") for a in rest) + return "relayed" if given else "native" + return "relayed" + + +def classify_line(line, policy): + """The shapes the relay has to decline, decided from the whole line. + + FR-029. The relay holds the shell's descriptors for the duration of the + command, so what matters is not only what the first word is: + + `cat log | less` classified on `cat` this is relayed, and then the + pager's stdout is a pipe instead of a terminal — it + stops being a pager. Any native or pty stage anywhere + in a pipeline stands the whole line down. + `nmap | tee f` is NOT a hazard and is worth capturing: the last + stage still writes to the terminal, which is exactly + what the relay is holding. + `nmap -oN f > out` the operator has already pointed stdout somewhere + else, so there is nothing for the relay to hold. + Standing down saves starting two processes to watch + an empty descriptor; the record says `redirected` + either way (FR-008). + + Returns None when the line says nothing special and the argv path decides. + """ + if looks_redirected(line): + return "redirected" + stages = split_pipeline(line) + if len(stages) < 2: + return None + for stage in stages: + try: + words = shlex.split(stage) + except ValueError: + # Unbalanced quotes: zsh would not have run this as we read it, so + # the safe answer is to hold nothing. + return "native" + if classify_argv(words, policy) in ("native", "pty"): + return "native" + return "relayed" + + +def split_pipeline(line): + """Split on `|` outside quotes. `||` is not a pipeline.""" + stages = [] + current = [] + quote = None + i = 0 + while i < len(line): + ch = line[i] + if quote is not None: + if ch == quote: + quote = None + elif ch == "\\" and quote == '"': + current.append(ch) + i += 1 + if i < len(line): + current.append(line[i]) + i += 1 + continue + elif ch in ("'", '"'): + quote = ch + elif ch == "\\": + current.append(ch) + i += 1 + if i < len(line): + current.append(line[i]) + i += 1 + continue + elif ch == "|": + if line[i + 1:i + 2] == "|": + # `a || b` is two commands, not a pipeline, and neither half + # has the other's stdout. + current.append(ch) + current.append("|") + i += 2 + continue + stages.append("".join(current)) + current = [] + i += 1 + continue + current.append(ch) + i += 1 + stages.append("".join(current)) + return [s.strip() for s in stages if s.strip()] + + def walk_wrappers(argv, policy): i = 0 while i < len(argv): diff --git a/hooks/shell-bash-hook.sh b/hooks/shell-bash-hook.sh index 371f2c30..2f9cc4aa 100644 --- a/hooks/shell-bash-hook.sh +++ b/hooks/shell-bash-hook.sh @@ -79,4 +79,7 @@ _redlog_prompt_command() { trap '_redlog_debug_trap' DEBUG PROMPT_COMMAND="_redlog_prompt_command;${PROMPT_COMMAND:-}" -_redlog_announce_shell +# Commands only: the automatic output relay is the zsh adapter's (spec 052 +# D1 is built on `preexec`, which bash does not have). `redlog-run` is still +# how a bash user captures a command's output on purpose. +_redlog_announce_shell "commands" diff --git a/hooks/shell-common.sh b/hooks/shell-common.sh index b5eaf832..a1cf9714 100644 --- a/hooks/shell-common.sh +++ b/hooks/shell-common.sh @@ -268,11 +268,22 @@ redlog-run() { return $exit_code } +# What this shell is actually doing, in the words that are true of it. +# +# It said "command metadata will be logged" and offered `redlog-run` as the way +# to get output. Both stopped being true when the zsh adapter started relaying +# output on its own (spec 052 T020), and a banner that overstates what is +# recorded is worse than no banner: an operator who believes the output is in +# the record stops checking. +# +# `$1` is what the adapter records without being asked — "commands" for the +# bash adapter, "commands and their output" for zsh. _redlog_announce_shell() { - if [[ -n "${WSL_DISTRO_NAME:-}" ]]; then - echo "[redlog] shell hook active (WSL: ${WSL_DISTRO_NAME}) — command metadata will be logged to RedLog timeline" - else - echo "[redlog] shell hook active — command metadata will be logged to RedLog timeline" - fi - echo "[redlog] tip: prefix a command with 'redlog-run' to stream and capture stdout/stderr" + local what="${1:-commands}" + local where="" + [[ -n "${WSL_DISTRO_NAME:-}" ]] && where=" (WSL: ${WSL_DISTRO_NAME})" + echo "[redlog] shell hook active${where} — ${what} will be recorded" + # Said at startup because it is the one thing an operator cannot discover by + # looking: everything else about this adapter is visible in the timeline. + echo "[redlog] redlog status · redlog stop" } diff --git a/hooks/shell-zsh-hook.zsh b/hooks/shell-zsh-hook.zsh index 2205c1e0..8cac110a 100644 --- a/hooks/shell-zsh-hook.zsh +++ b/hooks/shell-zsh-hook.zsh @@ -34,7 +34,11 @@ unset _redlog_adapter_dir _redlog_class_of() { local -a words words=(${(z)1}) - python3 "$_REDLOG_RELAY" classify --home "$(_redlog_home)" -- "${words[@]}" 2>/dev/null + # Both: the argv for the program lookup, and the raw line for the shapes the + # relay has to decline — a pipeline with a pager in it, a redirection the + # operator has already made (FR-029). + python3 "$_REDLOG_RELAY" classify --home "$(_redlog_home)" \ + --command-line "$1" -- "${words[@]}" 2>/dev/null } # --- This terminal's own state (spec 052 US2) --- @@ -213,10 +217,30 @@ _redlog_preexec() { "{\"cwd\":\"${PWD//\"/\\\"}\",\"command_id\":\"$_REDLOG_CMD_ID\",\"class\":\"$_REDLOG_CMD_CLASS\",\"source\":\"auto-relay\"}" } +# FR-009. The commands run either way — that part has always worked, silently, +# and silence is the bug. An operator whose RedLog crashed two hours ago has +# been working unrecorded with no way to know. +# +# Once, though, and only on the way in. A warning on every prompt is one an +# operator learns to read past, and then the one that matters is read past too. +# The flag is a shell variable on purpose: "have I said this in this shell" is +# not state that should survive a subshell, unlike the stop (FR-022). +_redlog_warn_unreachable() { + if _redlog_is_running; then + _REDLOG_WARNED_UNREACHABLE="" + return + fi + [[ -n "${_REDLOG_WARNED_UNREACHABLE:-}" ]] && return + _REDLOG_WARNED_UNREACHABLE=1 + print -u2 -- "[redlog] RedLog is not reachable — commands are running unrecorded until it is back" +} + _redlog_precmd() { local exit_code=$? [[ -n "$_REDLOG_LAST_CMD" ]] || return + _redlog_warn_unreachable + local duration=0 [[ -n "$_REDLOG_CMD_START" ]] && duration=$(( EPOCHSECONDS - _REDLOG_CMD_START )) @@ -251,6 +275,10 @@ _redlog_precmd() { local disposition="not-captured" case "$_REDLOG_CMD_CLASS" in native|pty) disposition="interactive" ;; + # The operator pointed stdout somewhere else before the command ran, so + # no relay was started. Same record as when one ran and saw no bytes + # (FR-008), without two processes watching an empty descriptor. + redirected) disposition="redirected" ;; esac extra="{\"exit_code\":$exit_code,\"duration_sec\":$duration,\"cwd\":\"${PWD//\"/\\\"}\",\"command_id\":\"$_REDLOG_CMD_ID\",\"source\":\"auto-relay\",\"completeness\":\"metadata-only\",\"output_disposition\":\"$disposition\"}" fi @@ -304,4 +332,4 @@ autoload -Uz add-zsh-hook add-zsh-hook preexec _redlog_preexec add-zsh-hook precmd _redlog_precmd _redlog_install_pty_wrappers -_redlog_announce_shell +_redlog_announce_shell "commands and their output" diff --git a/test/zsh-degradation.pty.test.ts b/test/zsh-degradation.pty.test.ts new file mode 100644 index 00000000..bb32699a --- /dev/null +++ b/test/zsh-degradation.pty.test.ts @@ -0,0 +1,179 @@ +import { describe, it, expect, beforeAll, afterAll } from 'vitest' +import { findShellTarget, runZsh, startCollector, hookPath, type ShellTarget } from './helpers/zsh-pty' + +// Spec 052 US3, T036/T037. The rule the whole feature is subordinate to: an +// audit logger may lose the recording, and may never take the shell with it. +// +// This is not a defensive extra. The adapter now sits in `preexec` on every +// command of an engagement, holding the shell's descriptors — so every way it +// can fail is a way the operator's shell can fail, in the middle of work that +// may not be repeatable. Unrecorded is bad. A wedged prompt, a lost reverse +// shell or a command that reports someone else's exit status is worse. + +const target: ShellTarget | null = findShellTarget() +const describeShell = target ? describe : describe.skip + +const occurrences = (text: string, needle: string): number => + text.split(needle).length - 1 + +describeShell(`degrading honestly (${target?.label ?? 'no zsh reachable'})`, () => { + // T036, FR-009. With RedLog unreachable the commands still run — that part + // works today, silently. Silence is the bug: an operator whose RedLog + // crashed two hours ago has been working unrecorded and has no way to know. + // Once, though. A warning on every prompt is one an operator learns to read + // past, and then the one that matters is read past too. + describe('when RedLog cannot be reached', () => { + let run: Awaited> + + beforeAll(async () => { + run = await runZsh(target!, { + rc: `source ${hookPath(target!, 'shell-zsh-hook.zsh')}`, + commands: ['echo first-unrecorded', 'echo second-unrecorded', 'echo third-unrecorded'], + // No `redlog` block: no api-port, no api-token in this throwaway HOME. + // + // And no WSL either. Under WSL the adapter deliberately falls back to + // the Windows profile's `.redlog`, which on a developer's machine is a + // real RedLog install — so omitting the files is not enough to make it + // unreachable here. On CI's ubuntu runner the variable is already + // unset and this line does nothing. + env: { WSL_DISTRO_NAME: '' }, + timeoutSeconds: 60 + }) + }, 300_000) + + it('runs the commands anyway', () => { + expect(run.ok, run.error).toBe(true) + expect(run.steps[0].output).toContain('first-unrecorded') + expect(run.steps[1].output).toContain('second-unrecorded') + expect(run.steps[2].output).toContain('third-unrecorded') + }) + + it('says so once, and then stops saying it', () => { + const warnings = occurrences(run.transcript, 'not reachable') + expect(warnings, 'the operator is never told their commands are unrecorded') + .toBeGreaterThan(0) + expect(warnings, 'the warning repeats on every prompt').toBe(1) + }) + }) + + // T038, FR-029. The relay holds the shell's descriptors for the duration of + // a command, so every shape of command it cannot hold safely is one it has + // to decline — and decline BEFORE the command runs, not notice afterwards. + describe('shapes the relay has to decline', () => { + let collector: Awaited> + let run: Awaited> + const token = 'us3-standdown' + + beforeAll(async () => { + collector = await startCollector(token) + run = await runZsh(target!, { + rc: `source ${hookPath(target!, 'shell-zsh-hook.zsh')}`, + commands: [ + // A pager at the end of a pipeline is the hazard: classified on the + // first word, `cat` is relayed, and then the pager's stdout is a + // pipe to the relay rather than a terminal — so it stops being a + // pager. `vim --version` stands in for it because it exits. + 'echo piped | vim --version', + // A pipeline with nothing native in it is still worth capturing: + // the last stage writes to the terminal, which is what the relay + // holds, so the output is the pipeline's own. + 'echo one | tr a-z A-Z', + 'echo redirect-me > /tmp/redlog-t038.txt', + 'cat /tmp/redlog-t038.txt' + ], + redlog: { port: collector.port, token }, + timeoutSeconds: 90 + }) + }, 300_000) + afterAll(async () => { await collector?.close() }) + + const startFor = (match: string) => collector.events.find((e) => + e.data.subtype === 'command_start' && String(e.data.command ?? '').includes(match)) + const endFor = (match: string) => collector.events.find((e) => + e.data.subtype === 'command_end' && String(e.data.command ?? '').includes(match)) + + it('stands down from a pipeline with a native stage, and the command still runs', () => { + expect(run.ok, run.error).toBe(true) + expect(run.steps[0].output, 'the command did not run').toMatch(/VIM|Vi IMproved/i) + expect(startFor('vim --version')?.data.class, 'the pager was relayed anyway').toBe('native') + expect(endFor('vim --version')?.data).toMatchObject({ + completeness: 'metadata-only', output_disposition: 'interactive' + }) + }) + + it('still relays a pipeline that is only ordinary commands', () => { + expect(run.steps[1].output).toContain('ONE') + expect(startFor('tr a-z A-Z')?.data.class).toBe('relayed') + expect(String(endFor('tr a-z A-Z')?.data.stdout)).toContain('ONE') + }) + + it('stands down from a redirection instead of relaying nothing', () => { + // The record is the same as it was when the relay ran and saw no bytes + // (T022) — but two python3 processes are not started to hold a + // descriptor the operator has already pointed somewhere else. + expect(startFor('> /tmp/redlog-t038.txt')?.data.class).toBe('redirected') + expect(endFor('> /tmp/redlog-t038.txt')?.data).toMatchObject({ + completeness: 'metadata-only', output_disposition: 'redirected' + }) + // And the operator's redirection did what they asked. + expect(String(endFor('cat /tmp/redlog-t038.txt')?.data.stdout)).toContain('redirect-me') + }) + }) + + // T037. Two different readers of the exit status, and the relay may lie to + // neither: the record is what the client eventually reads, and `$?` at the + // next prompt is what the operator's own `&&` and `||` depend on, mid + // engagement. A logger that changes it changes what the engagement did. + describe('when the relay dies underneath a command', () => { + let collector: Awaited> + let run: Awaited> + const token = 'us3-token' + + beforeAll(async () => { + collector = await startCollector(token) + run = await runZsh(target!, { + rc: `source ${hookPath(target!, 'shell-zsh-hook.zsh')}`, + commands: [ + // The command kills its own relay and then exits 7. Both pipe + // processes go, so the shell is left holding descriptors whose far + // end is gone — which is the shape of a relay that crashed, an OOM + // kill, or an operator's own `pkill python3`. + // The bracket is not decoration: `pkill -f` matches full command + // lines, and this command's own line contains the pattern — without + // it the command kills itself and reports 143, which looks exactly + // like the bug being tested for. + `sh -c 'pkill -f "redlog-rela[y].py pipe" 2>/dev/null; exit 7'`, + 'echo code=$?', + 'echo still-here' + ], + redlog: { port: collector.port, token }, + timeoutSeconds: 90 + }) + }, 300_000) + afterAll(async () => { await collector?.close() }) + + it('leaves the shell alive and usable', () => { + // If the shell died with the relay, nothing below this line can even be + // asked. That is the failure this whole story exists to prevent. + expect(run.ok, run.error).toBe(true) + expect(run.steps[2].output, 'the shell did not survive its own logger') + .toContain('still-here') + }) + + it('reports the command’s own exit status to the shell', () => { + expect(run.steps[1].output, 'the relay replaced the command’s status') + .toContain('code=7') + }) + + it('reports the command’s own exit status to the record', () => { + const end = collector.events.find((e) => e.agentType === 'shell' + && e.data.subtype === 'command_end' + && String(e.data.command ?? '').includes('exit 7')) + expect(end, 'the command was not recorded at all').toBeTruthy() + expect(end!.data.exit_code).toBe(7) + // And it says the body is not there, rather than reporting the empty + // string as if the command had printed nothing. + expect(end!.data.completeness).not.toBe('complete') + }) + }) +}) From 58793a21b55a9eda9196de450ca77deac41bd8a0 Mon Sep 17 00:00:00 2001 From: guantou Date: Wed, 7 Oct 2026 20:14:42 +0800 Subject: [PATCH 2/2] feat(052): the project moved, and the clock came with it (T039-T040) T039, FR-010. The dangerous outcome is not a missing command. It is a command from engagement A filed under engagement B -- a lie in a document a client reads, written by the tool whose whole job is to be believable. A terminal is pinned to the project it was opened against; when the operator switches project in RedLog the terminal stops, says why, and cannot be talked back into recording. `redlog start` is not the way around the guarantee; the safe answer is a new terminal (research.md D5). Detected by watching the active identity file's mtime with the zstat builtin, so the common case -- nothing changed -- costs a stat and no process. Only a changed mtime pays for the relay call. The session_end row lands in whichever project is open now, which is where someone wondering why the terminal went quiet will be looking, and names the engagement whose work stopped explicitly rather than letting the attribution speak for it. T040. The spool and the replay both existed. What the payload did not carry was WHEN: a command run at 02:00 with RedLog closed arrived claiming 09:00, the moment the operator next opened the project. A record whose times are the times someone read it is not a record of the engagement (Domain Invariant #8). One field -- source_timestamp on every event the adapter sends. insertEvent already validates it and hashes the rejection, so a wrong unit is refused rather than dragging the row to 1970. Two self-inflicted failures the suite caught, both worth the note: - The payload builder is a double-quoted shell string. A comment written with backticks around a function name RAN it; the follow-up comment quoting the resulting error message ended the string early and truncated the builder, so no event was sent at all. Prose punctuation is executable in there. - shell-adapter-boundaries holds the line that paths into the RedLog directory are transport, not lifecycle. The identity file is now named by shell-common; the zsh adapter only watches what it is handed. Co-Authored-By: Claude Opus 5 --- hooks/redlog-relay.py | 6 +- hooks/shell-common.sh | 30 ++++- hooks/shell-zsh-hook.zsh | 45 +++++++ specs/052-terminal-auto-capture/tasks.md | 22 +++- test/zsh-degradation.pty.test.ts | 153 +++++++++++++++++++++++ 5 files changed, 248 insertions(+), 8 deletions(-) diff --git a/hooks/redlog-relay.py b/hooks/redlog-relay.py index ba0019bd..312bc8c5 100644 --- a/hooks/redlog-relay.py +++ b/hooks/redlog-relay.py @@ -529,7 +529,11 @@ def apply_terminal_action(state, action, opts): out["recording"] = False out["stoppedReason"] = "operator" elif action == "project": - if (opts["engagement"] or "") != state.get("engagementId"): + # No `--engagement` means "whatever RedLog has open now", which is the + # question the adapter is actually asking at each prompt. Defaulting to + # the empty string instead would read as a switch every time. + current = opts["engagement"] or read_identity(opts)[0] + if current != state.get("engagementId"): out["recording"] = False out["stoppedReason"] = "project-switched" return out diff --git a/hooks/shell-common.sh b/hooks/shell-common.sh index a1cf9714..66fd73e0 100644 --- a/hooks/shell-common.sh +++ b/hooks/shell-common.sh @@ -78,6 +78,14 @@ _redlog_new_command_id() { printf '%s-%s-%s' "$stamp" "$$" "${RANDOM:-0}" } +# Where the active project's identity lives. Paths into the RedLog directory +# belong here rather than in an adapter: `shell-adapter-boundaries.test.ts` +# holds that line, and it is the reason every POSIX adapter emits the same +# contract instead of each one knowing its own layout. +_redlog_identity_file() { + printf '%s/active-identity.json' "${_REDLOG_DIR:-$HOME/.redlog}" +} + _redlog_is_running() { [[ -n "${_REDLOG_DIR:-}" ]] || { _REDLOG_DIR=$(_redlog_resolve_dir) || return 1; export _REDLOG_DIR; } [[ -f "$_REDLOG_DIR/api-port" ]] && [[ -f "$_REDLOG_DIR/api-token" ]] @@ -98,14 +106,32 @@ _redlog_send_event() { local payload payload=$(python3 -c " -import json, sys, os, pathlib +import json, sys, os, pathlib, time d = { 'agent_type': 'shell', 'data': { 'subtype': sys.argv[1], 'command': sys.argv[2], 'shell': '${SHELL##*/}', - 'pid': $$ + 'pid': $$, + # WHEN, not when someone next looked. + # + # A POST that fails spools the payload and RedLog replays it on the + # next project open — so without this, a command run at 02:00 with + # RedLog closed arrived claiming 09:00, the moment the operator opened + # the project. A record whose times are the times someone read it is + # not a record of the engagement (Domain Invariant #8). + # + # insertEvent validates the field and rejects anything before 2015 or + # more than a minute ahead, with the rejection hashed into the row, so + # a wrong unit is refused rather than silently believed. + # + # Nothing shell-special in these comments. The whole block is a + # double-quoted shell string, so a backtick pair is command + # substitution and a double quote ends the string: quoting a function + # name the prose way ran it, and quoting the resulting error message + # truncated the payload builder so that NO event was sent at all. + 'source_timestamp': int(time.time() * 1000) } } if os.environ.get('REDLOG_TERMINAL') == '1': diff --git a/hooks/shell-zsh-hook.zsh b/hooks/shell-zsh-hook.zsh index 8cac110a..8c3f0bd1 100644 --- a/hooks/shell-zsh-hook.zsh +++ b/hooks/shell-zsh-hook.zsh @@ -169,7 +169,52 @@ redlog() { esac } +# FR-010. The dangerous outcome is not a missing command — it is a command from +# engagement A filed under engagement B, which is a lie in a document a client +# reads, written by the tool whose whole job is to be believable. +# +# RedLog rewrites the active identity when the operator opens another project, +# so the terminal finds out by watching that file — named by shell-common, not +# here, because paths into the RedLog directory are transport. `zstat` is a +# builtin: the common case, where nothing changed, costs a stat and no +# process. Only a changed mtime pays for the relay call that compares the +# pinned engagement with the current one. +zmodload -F zsh/stat b:zstat 2>/dev/null + +_redlog_check_project() { + local file + file=$(_redlog_identity_file) + [[ -f "$file" ]] || return + local -a st + zstat -A st +mtime "$file" 2>/dev/null || return + [[ "${st[1]}" == "${_REDLOG_IDENTITY_MTIME:-}" ]] && return + # The first sight of the file is the pin itself, not a switch. + if [[ -z "${_REDLOG_IDENTITY_MTIME:-}" ]]; then + _REDLOG_IDENTITY_MTIME="${st[1]}" + return + fi + _REDLOG_IDENTITY_MTIME="${st[1]}" + + local after + after=$(_redlog_state --action project) + [[ "$after" == *project-switched* ]] || return + [[ -n "${_REDLOG_ANNOUNCED_SWITCH:-}" ]] && return + _REDLOG_ANNOUNCED_SWITCH=1 + + # The pin is never updated, so the state still names the project whose work + # just stopped. The row lands in whichever project RedLog has open now — + # that is where someone wondering why this terminal went quiet will be + # looking — and it names the old one explicitly rather than letting the + # attribution speak for it. + local pinned="" + [[ "$after" =~ '"engagementId":[[:space:]]*"([^"]*)"' ]] && pinned="$match[1]" + _redlog_send_event "session_end" "" \ + "{\"session_id\":\"$_REDLOG_SESSION_ID\",\"reason\":\"project-switched\",\"engagement_id\":\"$pinned\",\"source\":\"auto-relay\"}" + print -u2 -- "[redlog] the project changed — this terminal stopped recording; open a new terminal for the new project" +} + _redlog_preexec() { + _redlog_check_project _REDLOG_LAST_CMD="" _REDLOG_CMD_START="" _REDLOG_CMD_ID="" diff --git a/specs/052-terminal-auto-capture/tasks.md b/specs/052-terminal-auto-capture/tasks.md index 771ae3d0..9959368f 100644 --- a/specs/052-terminal-auto-capture/tasks.md +++ b/specs/052-terminal-auto-capture/tasks.md @@ -172,11 +172,23 @@ recorded, status again, start, a command that is. **Independent test**: quickstart.md §3 — kill RedLog mid-session, keep working, one message, spool fills, restart and recording resumes without re-enrolling. -- [ ] T036 [US3] Write the failing pty test: with RedLog unreachable, commands run normally, the operator is told once, and the message does not repeat on every prompt (FR-009) -- [ ] T037 [US3] Write the failing pty test: the shell reports the *command's* exit status, never the relay's, including when the relay dies mid-command -- [ ] T038 [US3] Implement the stand-down path in `hooks/shell-zsh-hook.zsh`: no Python 3, a failed `mkfifo`, an unwritable temp dir, recording off, a pipeline, or a redirection — run the command untouched (FR-029), the shape `redlog-run` already uses when `mkfifo` fails -- [ ] T039 [US3] Write the failing test then implement the project-switch stop (FR-010): `session_end` with a reason, no writes into the new project, and the terminal says so -- [ ] T040 [P] [US3] Confirm spool behaviour end to end with the existing `~/.redlog/pending` replay — a test that fills the spool while RedLog is down and asserts the events arrive on next project open, with their original occurrence times +- [x] T036 [US3] Write the failing pty test: with RedLog unreachable, commands run normally, the operator is told once, and the message does not repeat on every prompt (FR-009) + → the commands already ran; silence was the bug. Told once on the way in, and again only if RedLog comes back and goes away — a warning on every prompt is one an operator learns to read past, and then the one that matters is read past too. + → the startup banner said "command metadata will be logged" and offered `redlog-run` for output. Both stopped being true at T020, so zsh now announces "commands and their output" and bash "commands". A banner that overstates what is recorded is worse than none: an operator who believes the output is in the record stops checking. + → making RedLog unreachable needed `WSL_DISTRO_NAME=''` in the test: under WSL the adapter deliberately falls back to the Windows profile's `.redlog`, which on a developer's machine is a real install, so omitting the credential files is not enough. +- [x] T037 [US3] Write the failing pty test: the shell reports the *command's* exit status, never the relay's, including when the relay dies mid-command + → **it already did.** All three assertions passed on the first run: killing the relay underneath a running command leaves the shell alive and reports the command's own status to both the shell and the record. That is T020's design working, and it is now pinned rather than assumed. + → one note the test needed: `pkill -f` matches full command lines, so a command that kills its own relay matches *itself* and reports 143 — which looks exactly like the bug being tested for. +- [x] T038 [US3] Implement the stand-down path in `hooks/shell-zsh-hook.zsh`: no Python 3, a failed `mkfifo`, an unwritable temp dir, recording off, a pipeline, or a redirection — run the command untouched (FR-029), the shape `redlog-run` already uses when `mkfifo` fails + → the first four already stood down. The two that did not: a pipeline, and a redirection. + → **not all pipelines.** `cat log | less` is the hazard — classified on `cat` it is relayed, and then the pager's stdout is a pipe instead of a terminal, so it stops being a pager. Any `native` or `pty` stage anywhere in the line stands the whole thing down. `nmap | tee f` is not a hazard and is worth capturing: the last stage still writes to the terminal, which is exactly what the relay holds. Standing down on every pipeline would have lost that. + → a redirection stands down because there is nothing to hold: the record says `redirected` either way (T022), and two processes are no longer started to watch an empty descriptor. +- [x] T039 [US3] Write the failing test then implement the project-switch stop (FR-010): `session_end` with a reason, no writes into the new project, and the terminal says so + → detected by watching `active-identity.json`'s mtime with the `zstat` builtin: the common case, where nothing changed, costs a stat and no process. Only a changed mtime pays for the relay call. + → the `session_end` row lands in whichever project is open now — that is where someone wondering why the terminal went quiet will be looking — and names the engagement whose work stopped explicitly, rather than letting the attribution speak for it. +- [x] T040 [P] [US3] Confirm spool behaviour end to end with the existing `~/.redlog/pending` replay — a test that fills the spool while RedLog is down and asserts the events arrive on next project open, with their original occurrence times + → "with their original occurrence times" was the half that did not work. The spool and the replay both existed; the payload carried no time, so a command run at 02:00 with RedLog closed arrived claiming 09:00 — the moment the operator next opened the project. A record whose times are the times someone read it is not a record of the engagement (Domain Invariant #8). + → one line: `source_timestamp` on every event the adapter sends. `insertEvent` already validates it and hashes the rejection, so a wrong unit is refused rather than dragging the row to 1970. --- diff --git a/test/zsh-degradation.pty.test.ts b/test/zsh-degradation.pty.test.ts index bb32699a..e01d7736 100644 --- a/test/zsh-degradation.pty.test.ts +++ b/test/zsh-degradation.pty.test.ts @@ -1,4 +1,7 @@ import { describe, it, expect, beforeAll, afterAll } from 'vitest' +import fs from 'fs' +import os from 'os' +import path from 'path' import { findShellTarget, runZsh, startCollector, hookPath, type ShellTarget } from './helpers/zsh-pty' // Spec 052 US3, T036/T037. The rule the whole feature is subordinate to: an @@ -120,6 +123,156 @@ describeShell(`degrading honestly (${target?.label ?? 'no zsh reachable'})`, () }) }) + // T039, FR-010. The dangerous outcome is not a missing command. It is a + // command from engagement A filed under engagement B — a lie in a document a + // client reads, written by the tool whose entire job is to be believable. + // + // So a terminal is pinned to the project it was opened against, and when the + // operator switches project in RedLog the terminal stops. It does not + // re-bind, and it cannot be talked back into recording: `redlog start` in + // that terminal is not the way around the guarantee. The safe answer is a + // new terminal (research.md D5). + describe('when the project changes under an open terminal', () => { + let collector: Awaited> + let run: Awaited> + const token = 'us3-switch' + + beforeAll(async () => { + collector = await startCollector(token) + run = await runZsh(target!, { + rc: `source ${hookPath(target!, 'shell-zsh-hook.zsh')}`, + commands: [ + 'echo before-the-switch', + // RedLog rewrites this file when the operator opens another + // project; the terminal finds out the same way it would then. + `printf '%s' '{"engagementId":"eng-after","operatorId":"op-a"}' > $HOME/.redlog/active-identity.json`, + 'echo after-the-switch', + 'redlog start', + 'echo after-trying-to-start', + 'redlog status' + ], + redlog: { + port: collector.port, token, + identity: { engagementId: 'eng-before', operatorId: 'op-a' } + }, + timeoutSeconds: 90 + }) + }, 300_000) + afterAll(async () => { await collector?.close() }) + + const named = (match: string) => collector.events.filter((e) => + String(e.data.command ?? '').includes(match)) + + it('stops, rather than writing the new project’s name on old work', () => { + expect(run.ok, run.error).toBe(true) + expect(named('before-the-switch').length).toBeGreaterThan(0) + expect(named('after-the-switch'), 'a command was recorded after the switch') + .toHaveLength(0) + // The operator's command still ran — stopping the recording is not + // stopping the engagement. + expect(run.steps[2].output).toContain('after-the-switch') + }) + + it('says why, in the record and in the terminal', () => { + const ended = collector.events.find((e) => e.data.subtype === 'session_end' + && e.data.reason === 'project-switched') + expect(ended, 'nothing in the record explains the gap').toBeTruthy() + // Attributed to the project it was recording, not the one now open: + // this row belongs to the engagement whose work just stopped. + expect(ended!.data.engagement_id).toBe('eng-before') + expect(run.transcript, 'the terminal never said anything') + .toMatch(/project changed|stopped recording/i) + }) + + it('cannot be talked back into recording', () => { + expect(named('after-trying-to-start'), '`redlog start` re-bound the terminal') + .toHaveLength(0) + expect(run.steps[5].output).toMatch(/project-switched/) + }) + }) + + // T040, Domain Invariant #8. The spool already existed: a POST that fails + // writes the payload to `~/.redlog/pending` and RedLog replays it on the + // next project open. What it did not carry was WHEN — so a command run at + // 02:00 while RedLog was closed arrived claiming to have happened at 09:00, + // when the operator next opened the project. A record whose times are the + // times someone looked at it is not a record of the engagement. + describe('commands run while RedLog is closed', () => { + let run: Awaited> + let payloads: Array> = [] + let ranAt = 0 + + beforeAll(async () => { + // A port that is certainly dead: one the OS just gave us and we handed + // straight back. + const stillborn = await startCollector('unused') + const deadPort = stillborn.port + await stillborn.close() + + ranAt = Date.now() + run = await runZsh(target!, { + rc: `source ${hookPath(target!, 'shell-zsh-hook.zsh')}`, + commands: [ + 'echo spooled-while-down', + // One per line: the spool writes payloads with no trailing newline, + // so a plain `cat` of the directory runs them together. + 'for f in $HOME/.redlog/pending/*.json; do print -r -- "$(<$f)"; done' + ], + redlog: { + port: deadPort, token: 'nobody-home', + identity: { engagementId: 'eng-spool', operatorId: 'op-spool' } + }, + timeoutSeconds: 90 + }) + payloads = run.steps[1].output + .split('\n') + .map((l) => l.trim()) + .filter((l) => l.startsWith('{')) + .map((l) => JSON.parse(l) as Record) + }, 300_000) + + it('keeps the command, and the operator keeps their shell', () => { + expect(run.ok, run.error).toBe(true) + expect(run.steps[0].output).toContain('spooled-while-down') + expect(payloads.length, 'nothing reached the spool').toBeGreaterThan(0) + }) + + it('stamps when it happened, not when it will be read', () => { + for (const payload of payloads) { + const data = payload.data as Record + const stamp = data.source_timestamp + expect(typeof stamp, `no source_timestamp on ${String(data.subtype)}`).toBe('number') + // Within the window the shell actually ran in. `insertEvent` validates + // this field too — it refuses anything before 2015 or more than a + // minute in the future — so a wrong unit would be rejected rather + // than drag the row to 1970. + expect(stamp as number).toBeGreaterThanOrEqual(ranAt - 60_000) + expect(stamp as number).toBeLessThanOrEqual(Date.now() + 60_000) + } + }) + + it('carries that time through the replay', async () => { + const { replaySpoolDirectory } = await import('../src/core/spool-replay') + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'redlog-spool-')) + try { + payloads.forEach((p, i) => fs.writeFileSync(path.join(dir, `${i}.json`), JSON.stringify(p))) + const emitted: Array> = [] + const result = replaySpoolDirectory( + dir, + { engagementId: 'eng-spool', operatorId: 'op-spool' }, + (e) => { emitted.push(e.data); return true } + ) + expect(result.replayed).toBe(payloads.length) + for (const data of emitted) { + expect(data.source_timestamp, 'the replay dropped the occurrence time').toBeTruthy() + expect(data.recovered_from_spool).toBe(true) + } + } finally { + fs.rmSync(dir, { recursive: true, force: true }) + } + }) + }) + // T037. Two different readers of the exit status, and the relay may lie to // neither: the record is what the client eventually reads, and `$?` at the // next prompt is what the operator's own `&&` and `||` depend on, mid