feat(052): lose the recording, never the shell (US3)

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
 
@@ -540,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
@@ -688,6 +681,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):

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"

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':
@@ -268,11 +294,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"
 }

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) ---
@@ -165,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=""
@@ -213,10 +262,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 +320,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 +377,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"

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.
 
 ---