timothyandClaude Opus 5
bd40c962cf
Round 5, two independent reviews. Two findings, one technical and one about honesty, and the second is the more important. THE RATIONALE. The round-4 commit and the decision record state as measured fact that trapping signals made a hook take 30s to die where it took 1s. That came from a review finding I accepted without re-measuring. It is wrong. Measured A/B: signal the pid control 4.01s trapped 4.12s signal the group control 0.002s trapped 0.054s The stall is bash deferring a fatal signal until its foreground command finishes, and it happens identically with NO trap — the control stalls too. The trap cost ~0.1s, not 29s. The withdrawal still stands, but on its real grounds: three silent permissive-direction defects in three rounds for a sub-millisecond rescue window, and the trapped sink STILL returned rc 0 on SIGINT where the control returns -2. The record now carries the correction rather than the fabrication, because a decision record with an invented measurement reads as checked and talks the next reader out of checking. The test that was supposed to enforce this was itself vacuous: it signalled the pid, so both sides took the full sleep and the timing assertion could distinguish nothing. It signals the process group now — the supervisor shape, and the only one where the assertion can see anything. THE LOCALE FIX WAS INERT. `local LC_ALL=C` does not export, so the child sed/tr never saw it. It read as fixed only because this author's shell sets LANG alone; with an inherited LC_CTYPE (macOS Terminal, ssh SendEnv, sudo env_keep) LC_CTYPE outranks the exported LANG=C and the symptom returns in full — a real deny filed as `output`, records under `unknown-session` with empty event and tool, and `illegal byte sequence` at the harness. `local -x` now, verified end-to-end across four locale environments, and the test is parametrised over them because a single ambient locale tests one row of the matrix. Also this round: - Removing the 64KB cap ARMED a latent bug rather than fixing one: a greedy `.*` over a single-line payload takes the LAST match, so a nested session_id inside a tool_response outranked the top-level one and filed the whole invocation under the wrong session. The cap had been accidentally protecting the right answer. First-match extraction now, bounded at 256KB where the bound is no longer load-bearing (3 unbounded scans cost 1.5s on a 20MB payload). - A present-but-empty decision value was laundered to `output`. - The redirect-order guard excluded operators preceded by a digit, so it was blind to `exec 0<` — the exact line it was written for. Mutation-checked both ways now: clean on the real file, red when the original bug is reintroduced verbatim. Its limits are stated in the docstring rather than implied. Refs: #776 Decisions-Edit: yes Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
540 lines
29 KiB
Bash
Executable File
540 lines
29 KiB
Bash
Executable File
#!/usr/bin/env bash
|
|
# Hook fire log — the WRITE side and the READ side, deliberately in ONE file (ersatztv#776).
|
|
#
|
|
# WHY THIS EXISTS. In this harness version only `Stop` hooks emit a structured transcript record
|
|
# (`stop_hook_summary`/`hookInfos`). `PreToolUse` and `PostToolUse` hooks leave no durable execution
|
|
# trace — which is every guard this repo actually relies on. #773 §5.4 could therefore only count
|
|
# *filename mentions in settings dumps*, i.e. inference. A guard that is neither proven nor
|
|
# observable is an assertion about the past, and a silently broken hook looks identical to a working
|
|
# one indefinitely. #756's standing lesson: make the system REPORT it rather than infer it.
|
|
#
|
|
# WHY ONE FILE. The reader and the writer share the record format. Two files means the format can
|
|
# drift and the report can quietly describe a shape nothing writes any more — the same argument that
|
|
# put `scripts/ci-step-ran.sh` in one script instead of an inline workflow body (#756).
|
|
#
|
|
# WHY IT CAPTURES STDOUT RATHER THAN BEING TOLD THE DECISION. Every hook here exits 0 always; the
|
|
# decision is communicated by *printing* `hookSpecificOutput.permissionDecision` (PreToolUse) or
|
|
# `decision` (Stop). `pretooluse-merge-consent.sh` alone reaches that print from ~40 call sites via
|
|
# its `decide` helper. Asking each site to also set a variable would (a) be 40 edits in the most
|
|
# load-bearing guard in the repo and (b) record what the author *meant*, which is the inference this
|
|
# issue exists to abolish. Capturing the bytes the hook actually emits records what the HARNESS
|
|
# sees. It cannot drift from the decision because it IS the decision.
|
|
#
|
|
# WHY IT CAPTURES STDIN. 8 of the 9 hooks already open with `input=$(cat)` — a full blocking slurp —
|
|
# so reading stdin once here and replaying it via `exec 0<` is not a new risk, it is the read they
|
|
# already perform, moved earlier. It buys the tool name and session id for the log, and it makes
|
|
# `pretooluse-agent-ram.sh` (which reads no stdin at all today) observable on the same terms as the
|
|
# rest instead of being a hole in the table.
|
|
#
|
|
# FAIL-OPEN, DELIBERATELY AND IN THIS DIRECTION ONLY. This file is observability, not a guard. If
|
|
# anything here fails — no temp dir, unwritable log, missing `date` — the hook must behave EXACTLY as
|
|
# it did before instrumentation. A logging bug that denies a merge, or that swallows a guard's deny
|
|
# JSON, would be far worse than the blindness it is fixing. Every function returns 0, the stdout
|
|
# replay is the first act of the exit path, and the original exit code is re-raised explicitly.
|
|
#
|
|
# USAGE (write side) — the first two lines of every hook, before anything reads stdin:
|
|
# . "${CLAUDE_PROJECT_DIR:-$(cd -- "$(dirname -- "${BASH_SOURCE[0]}")/../.." && pwd)}/scripts/hook-fire-log.sh"
|
|
# etv_hook_fire_begin <hook-name> [label]
|
|
#
|
|
# USAGE (read side):
|
|
# scripts/hook-fire-log.sh report # this session (or every session, see below)
|
|
# scripts/hook-fire-log.sh report --all # every session in the log dir
|
|
# scripts/hook-fire-log.sh report --json
|
|
# scripts/hook-fire-log.sh path # where the current session logs
|
|
#
|
|
# `scripts/tests/test_hook_fire_log.py` is the guard: it derives the hook population from the
|
|
# filesystem (never a list — `testing.guard-derives-population-from-source`) and fails if any hook
|
|
# is uninstrumented, and it proves stdin, stdout and the exit code survive the wrapper.
|
|
|
|
# ---------------------------------------------------------------------------------------------
|
|
# Shared: where the log lives, and how a record is written
|
|
# ---------------------------------------------------------------------------------------------
|
|
|
|
etv_hook_fire_log_dir() {
|
|
printf '%s' "${ETV_HOOK_FIRE_LOG_DIR:-${HOME:-/tmp}/.cache/ersatztv/hook-fire}"
|
|
}
|
|
|
|
etv_hook_fire_session() {
|
|
# The harness does not export a session id to hooks in this version, so the payload's
|
|
# `.session_id` is the real source and the env var is only a fallback. Recorded rather than
|
|
# assumed: several hooks already read `.session_id` from stdin for exactly this reason.
|
|
printf '%s' "${ETV_HOOK_FIRE_SESSION:-${CLAUDE_SESSION_ID:-unknown-session}}"
|
|
}
|
|
|
|
etv_hook_fire_log_file() {
|
|
# SCRUBBED, like every other use of this value. The session id is extracted from the payload by a
|
|
# `sed` that only excludes `"`, so a `/` or `..` in it would otherwise steer the write outside the
|
|
# log dir. Harness-generated UUIDs make that unreachable today, but a file whose stated thesis is
|
|
# "restrict the value space so there is no escaping bug to have" should not exempt the one use
|
|
# that becomes a path.
|
|
printf '%s/%s.jsonl' "$(etv_hook_fire_log_dir)" "$(etv_hook_fire_scrub_component "$(etv_hook_fire_session)")"
|
|
}
|
|
|
|
# Sanitise a value to a safe JSON scalar charset. This is why no `jq` is needed on the write side:
|
|
# with the value space restricted there is nothing to escape, so there is no escaping bug to have.
|
|
# A quote, backslash or newline in a hook name or tool name is not a case worth supporting — it is a
|
|
# case worth flattening, loudly, to `_`.
|
|
etv_hook_fire_scrub() {
|
|
printf '%s' "${1:-}" | tr -c 'A-Za-z0-9._/:+@=-' '_' | cut -c1-200
|
|
}
|
|
|
|
# A STRICTER scrub for the one value that becomes a PATH. The record scrub above deliberately keeps
|
|
# `/` and `.` — tool names like `mcp__gitea__x` and event paths read better with them — but those
|
|
# are exactly the two characters that turn a session id into `../../escaped`. Passing a value
|
|
# through a scrub is not the same as passing it through the RIGHT scrub, and the first version of
|
|
# this fix reused the record scrubber and left the traversal wide open while reading as fixed.
|
|
etv_hook_fire_scrub_component() {
|
|
printf '%s' "${1:-}" | tr -c 'A-Za-z0-9_-' '_' | cut -c1-120
|
|
}
|
|
|
|
# Append one record. Never fails; never writes a partial line (built whole, appended once).
|
|
etv_hook_fire_record() {
|
|
[ "${ETV_HOOK_FIRE_DISABLE:-0}" = "1" ] && return 0
|
|
|
|
local file line
|
|
file="${ETV_HOOK_FIRE_LOG_FILE:-$(etv_hook_fire_log_file)}"
|
|
mkdir -p "$(dirname "$file")" 2>/dev/null || return 0
|
|
|
|
line=$(printf '{"ts":"%s","session":"%s","pid":"%s","hook":"%s","label":"%s","event":"%s","tool":"%s","phase":"%s","code":"%s","decision":"%s"}' \
|
|
"$(date -u '+%Y-%m-%dT%H:%M:%SZ' 2>/dev/null || printf 'unknown')" \
|
|
"$(etv_hook_fire_scrub "$(etv_hook_fire_session)")" \
|
|
"$(etv_hook_fire_scrub "${ETV_HOOK_FIRE_PID:-$$}")" \
|
|
"$(etv_hook_fire_scrub "${1:-}")" \
|
|
"$(etv_hook_fire_scrub "${2:-}")" \
|
|
"$(etv_hook_fire_scrub "${3:-}")" \
|
|
"$(etv_hook_fire_scrub "${4:-}")" \
|
|
"$(etv_hook_fire_scrub "${5:-}")" \
|
|
"$(etv_hook_fire_scrub "${6:-}")" \
|
|
"$(etv_hook_fire_scrub "${7:-}")" 2>/dev/null) || return 0
|
|
|
|
# ORDER MATTERS: `2>` BEFORE `>>`. Redirections are applied left to right, so
|
|
# `printf ... >> "$file" 2>/dev/null` opens the file FIRST and bash reports a failure to open it
|
|
# on the stderr still in force — the hook prints `Operation not permitted` at the harness. An
|
|
# existing-but-unwritable log file is the reachable case; the fail-open test missed it by using a
|
|
# path that dies at `mkdir` instead. Redirecting stderr first covers the open failure too.
|
|
printf '%s\n' "$line" 2>/dev/null >> "$file" || true
|
|
return 0
|
|
}
|
|
|
|
# ---------------------------------------------------------------------------------------------
|
|
# Write side: what a hook calls
|
|
# ---------------------------------------------------------------------------------------------
|
|
|
|
# Classify what the hook printed. The harness reads these two shapes and nothing else:
|
|
# PreToolUse : {"hookSpecificOutput":{"permissionDecision":"allow|deny|ask", ...}}
|
|
# Stop : {"decision":"block", "reason": ...}
|
|
# Anything else printed on stdout is surfaced to the user but decides nothing.
|
|
etv_hook_fire_classify() {
|
|
local out="${1:-}" code="${2:-0}" mode="${3:-capture}" d=""
|
|
# BYTE-ORIENTED, not locale-aware. One 0xE9 byte in a `permissionDecisionReason` made `sed` print
|
|
# `illegal byte sequence` to the harness AND fail to extract, filing a real `deny` as `output`.
|
|
#
|
|
# `local -x`, NOT `local`. A plain `local` sets a shell variable without the export attribute, so
|
|
# the child `sed`/`tr` never sees it — the fix was INERT and read as applied. It looked correct
|
|
# only because this author's shell sets `LANG` alone; with an inherited `LC_CTYPE` (macOS
|
|
# Terminal, ssh `SendEnv LC_*`, sudo `env_keep`) `LC_CTYPE` outranks the exported `LANG=C` and the
|
|
# symptom returns in full.
|
|
local -x LC_ALL=C LANG=C
|
|
|
|
# A `stream`-mode hook is a git hook: git reads its exit code and nothing else, so that is the
|
|
# whole of its decision. Reporting `no-op` here because no JSON was captured would be an
|
|
# inference, and inference is what this file exists to replace.
|
|
if [ "$mode" = "stream" ]; then
|
|
if [ "$code" = "0" ]; then printf 'pass'; else printf 'blocked'; fi
|
|
return 0
|
|
fi
|
|
|
|
if [ -n "$out" ]; then
|
|
# `[^"]*`, not `[A-Za-z-]*`: a restricted class means an odd value fails to EXTRACT and is
|
|
# filed as generic `output`, so "every non-canonical value is recorded as unrecognized" was
|
|
# true only for values the class happened to admit. Extract anything, then judge it below.
|
|
d=$(printf '%s' "$out" | sed -n 's/.*"permissionDecision"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' | head -n1)
|
|
# A PRESENT-but-empty value is not the same as an absent key, and treating them alike let
|
|
# `{"permissionDecision":""}` fall through to `output` — a malformed decision laundered into
|
|
# "the hook just printed something".
|
|
if [ -z "$d" ] && printf '%s' "$out" | grep -q '"permissionDecision"[[:space:]]*:'; then
|
|
d="unrecognized"
|
|
fi
|
|
[ -z "$d" ] && d=$(printf '%s' "$out" | sed -n 's/.*"decision"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' | head -n1)
|
|
|
|
# A NON-CANONICAL VALUE IS RECORDED AS SUCH, not normalised into a valid one. An earlier version
|
|
# lowercased whatever it found, so `"permissionDecision":"Deny"` was filed as a clean `deny` —
|
|
# manufacturing a decision the harness may never have honoured. The documented values are
|
|
# lowercase; anything else is a hook bug, and the log should say so rather than launder it.
|
|
case "$d" in
|
|
allow|deny|ask|block|"") ;;
|
|
*) d="unrecognized" ;;
|
|
esac
|
|
# `additionalContext` with no decision (design-sync-reminder's `start` path) informs, it does
|
|
# not gate. Naming it distinctly keeps it out of the allow/deny counts. Matched WITH its quotes
|
|
# and colon — a bare substring test also fired on human prose that merely used the word.
|
|
if [ -z "$d" ] && printf '%s' "$out" | grep -q '"additionalContext"[[:space:]]*:'; then d="context"; fi
|
|
[ -z "$d" ] && d="output"
|
|
fi
|
|
|
|
# Exit 2 is the harness's block channel and it DOMINATES: the call is blocked whatever the JSON
|
|
# said. Recording a printed `allow` here would report a permit for an invocation that was refused,
|
|
# which is the one direction a log of security decisions must never be wrong in.
|
|
if [ "$code" = "2" ]; then printf 'deny-exit2'; return 0; fi
|
|
|
|
[ -z "$d" ] && d="no-op"
|
|
|
|
# A non-zero status does NOT annotate a parsed decision. It used to overwrite one (`deny` + exit 1
|
|
# recorded as `error`), and the first correction over-swung the other way and appended `+error` —
|
|
# inventing a composite state the harness does not report. The status already has its own field in
|
|
# the record, so the decision field states the decision and nothing else. `error` means only "it
|
|
# failed and said nothing classifiable".
|
|
# `output` too, not just `no-op`: a hook that printed a diagnostic and then FAILED was being
|
|
# filed as `output`, so the report showed `output=1` and the failure vanished from the histogram.
|
|
# A parsed decision is still left alone — the status has its own field.
|
|
case "$code:$d" in 0:*) ;; *:no-op|*:output) d="error" ;; esac
|
|
|
|
printf '%s' "$d"
|
|
}
|
|
|
|
# etv_hook_fire_begin <hook-name> [label] [stdout-mode]
|
|
#
|
|
# `stdout-mode` is `capture` (default) or `stream`, and the split is not a tuning knob — the two
|
|
# kinds of hook in this repo decide by different channels:
|
|
#
|
|
# Claude Code hooks (pretooluse-*, posttooluse-*, design-sync-reminder) always exit 0 and
|
|
# communicate by PRINTING JSON. Their decision is only observable by capturing stdout, and their
|
|
# output is a single line consumed by the harness after exit, so buffering costs nothing.
|
|
#
|
|
# Git hooks (prepush-*, decisions-guard) decide by EXIT CODE, and their stdout is progress text a
|
|
# human is watching in real time. Capturing it would hold a slow pre-push hook's output back until
|
|
# the end, turning a working progress display into an apparent hang. They pass `stream`, and their
|
|
# decision is read from the exit code, which is what git reads too.
|
|
etv_hook_fire_begin() {
|
|
ETV_HOOK_FIRE_NAME="${1:-unknown-hook}"
|
|
ETV_HOOK_FIRE_LABEL="${2:-}"
|
|
ETV_HOOK_FIRE_MODE="${3:-capture}"
|
|
ETV_HOOK_FIRE_PID="$$"
|
|
ETV_HOOK_FIRE_STDIN_TMP=""
|
|
ETV_HOOK_FIRE_STDOUT_TMP=""
|
|
# RESET, never merely default. Inherited from the environment (exported by a parent, or a second
|
|
# `begin` in one shell) a stale `1` made the first flush return immediately: stdout stayed
|
|
# redirected and no exit record was ever written.
|
|
ETV_HOOK_FIRE_FLUSHED=0
|
|
|
|
[ "${ETV_HOOK_FIRE_DISABLE:-0}" = "1" ] && return 0
|
|
|
|
ETV_HOOK_FIRE_LOG_FILE="$(etv_hook_fire_log_file)"
|
|
mkdir -p "$(dirname "$ETV_HOOK_FIRE_LOG_FILE")" 2>/dev/null || { ETV_HOOK_FIRE_DISABLE=1; return 0; }
|
|
|
|
# --- stdin: slurp, replay, and read the payload's identifying fields ------------------------
|
|
#
|
|
# NEVER on a terminal. A `git commit` run interactively hands its hooks a TTY on fd 0, and `cat`
|
|
# would block there forever — instrumentation hanging the commit it was added to observe. Claude
|
|
# Code always writes the JSON payload and closes the pipe, which is why the 8 hooks that already
|
|
# open with `input=$(cat)` are safe today; that guarantee does not extend to the git hooks, so the
|
|
# capture is conditioned on stdin not being a tty rather than on which hook is calling.
|
|
local sin payload="" event="" tool="" sess=""
|
|
if [ ! -t 0 ]; then
|
|
sin=$(mktemp "${TMPDIR:-/tmp}/etv-hook-stdin.XXXXXX" 2>/dev/null) || sin=""
|
|
else
|
|
sin=""
|
|
fi
|
|
if [ -n "$sin" ]; then
|
|
ETV_HOOK_FIRE_STDIN_TMP="$sin"
|
|
cat 2>/dev/null > "$sin" || true
|
|
# Replay: even a partial capture is closer to the truth than the drained pipe the hook would
|
|
# otherwise inherit.
|
|
#
|
|
# NO `2>/dev/null` ON THIS LINE, EVER. `exec` with redirections and no command applies them to
|
|
# the shell PERMANENTLY, so `exec 0<"$sin" 2>/dev/null` does not suppress errors from this one
|
|
# redirection — it sends the HOOK'S ENTIRE STDERR to /dev/null for the rest of its life. That
|
|
# silenced every husky hook's user-facing output, which is stderr: the H6 "push to main BLOCKED"
|
|
# message, the BOM guard's remediation text, `husky - commit message missing Co-Authored-By`.
|
|
# The guards still blocked, and the human was told nothing about why.
|
|
# Readability is tested instead of relying on redirection-failure suppression.
|
|
if [ -r "$sin" ]; then exec 0<"$sin" || true; fi
|
|
payload=1
|
|
fi
|
|
|
|
if [ -n "$payload" ]; then
|
|
# Read the fields from the FILE, byte-oriented, with no size cap. These were extracted from a
|
|
# `head -c 65536` prefix, so a payload whose `tool_response` pushed `session_id` past 64 KB
|
|
# filed its records under `unknown-session` with empty event and tool — and a report keyed on
|
|
# the real session then showed those fires as NEVER HAVING HAPPENED. A truncating read is a
|
|
# sampling error, and this one manufactured exactly the vacuity #776 exists to abolish.
|
|
local -x LC_ALL=C LANG=C
|
|
# FIRST occurrence, via `grep -o`. A `sed` substitution with a leading `.*` is GREEDY, and
|
|
# payloads are one long line, so it selected the LAST match: a nested
|
|
# `{"session_id":"...","tool_name":"..."}` inside a `tool_response` outranked the top-level one
|
|
# and the whole invocation filed under the wrong session. Removing the 64 KB cap is what armed
|
|
# it — the cap had been accidentally protecting the right answer, which is the kind of load a
|
|
# bound can be silently carrying.
|
|
#
|
|
# The scan is bounded again at 256 KB, but now the bound is safe rather than load-bearing:
|
|
# identity fields are at the head of the payload, and first-match means a later duplicate cannot
|
|
# win. Unbounded cost 0.5s per scan on a 20 MB payload, three scans per fire.
|
|
_etv_field() {
|
|
head -c 262144 "$sin" 2>/dev/null \
|
|
| grep -o "\"$1\"[[:space:]]*:[[:space:]]*\"[^\"]*\"" 2>/dev/null \
|
|
| head -n1 | sed 's/.*:[[:space:]]*"//; s/"$//' 2>/dev/null
|
|
}
|
|
event=$(_etv_field hook_event_name)
|
|
tool=$(_etv_field tool_name)
|
|
sess=$(_etv_field session_id)
|
|
fi
|
|
|
|
# The payload's session id is authoritative when the env var is absent, which it is in this
|
|
# harness version. Re-point the log file at it before the first record is written.
|
|
if [ -n "$sess" ] && [ -z "${CLAUDE_SESSION_ID:-}" ] && [ -z "${ETV_HOOK_FIRE_SESSION:-}" ]; then
|
|
ETV_HOOK_FIRE_SESSION="$sess"
|
|
ETV_HOOK_FIRE_LOG_FILE="$(etv_hook_fire_log_file)"
|
|
mkdir -p "$(dirname "$ETV_HOOK_FIRE_LOG_FILE")" 2>/dev/null || true
|
|
fi
|
|
|
|
ETV_HOOK_FIRE_EVENT="$event"
|
|
ETV_HOOK_FIRE_TOOL="$tool"
|
|
|
|
etv_hook_fire_record "$ETV_HOOK_FIRE_NAME" "$ETV_HOOK_FIRE_LABEL" "$event" "$tool" "fire" "" ""
|
|
|
|
# --- stdout: divert, so the exit path can read the decision the hook emitted ----------------
|
|
local sout=""
|
|
if [ "$ETV_HOOK_FIRE_MODE" = "capture" ]; then
|
|
sout=$(mktemp "${TMPDIR:-/tmp}/etv-hook-stdout.XXXXXX" 2>/dev/null) || sout=""
|
|
fi
|
|
if [ -n "$sout" ]; then
|
|
ETV_HOOK_FIRE_STDOUT_TMP="$sout"
|
|
exec 3>&1 || { ETV_HOOK_FIRE_STDOUT_TMP=""; rm -f "$sout" 2>/dev/null; return 0; }
|
|
exec 1>"$sout" || { exec 1>&3 3>&-; ETV_HOOK_FIRE_STDOUT_TMP=""; rm -f "$sout" 2>/dev/null; return 0; }
|
|
# A READ FD held open on the same file, so the replay does not depend on the PATH still
|
|
# resolving at exit. Replaying with `cat "$path"` loses everything if anything unlinks the file
|
|
# mid-run — a $TMPDIR reaper, a hook that clears its own scratch — because the write fd stays
|
|
# valid on the unlinked inode while the name is gone: the hook prints its `deny` into a file
|
|
# nothing can reopen. An fd survives unlink, which turns that from silent guard-disarming into
|
|
# a non-event. Pinned by `test_output_SURVIVES_a_vanished_stdout_tempfile`.
|
|
exec 4<"$sout" || true
|
|
fi
|
|
|
|
# SIGNALS ARE DELIBERATELY NOT TRAPPED — a withdrawal, recorded because the next reader will
|
|
# otherwise re-add this. A `trap ... TERM` was added so a hook killed by the harness timeout would
|
|
# not lose output it had already printed (measured then at 52 bytes before, 0 after). It produced
|
|
# three defects in three rounds and cost more than it bought:
|
|
#
|
|
# 1. the handler ended in `exit "$?"`, so a SIGTERMed `prepush-donewhen.sh` reported 0 and git
|
|
# PUSHED TO MAIN — a signal became consent;
|
|
# 2. `local sig=...` clobbered `$?`, so a killed guard was RECORDED as having passed;
|
|
# 3. and the one that settles it: bash does not run a trap until the current foreground command
|
|
# finishes, so a hook mid-`curl` took 30s to die where it had taken 1s. A TERM-then-KILL
|
|
# supervisor therefore gets no flush AT ALL, plus a 29s stall — strictly worse than the
|
|
# untrapped behaviour on the very path the trap existed for.
|
|
#
|
|
# WHAT IS LOST, enumerated rather than waved past: a hook killed by a signal loses its `exit`
|
|
# record, loses stdout it had already written, and leaks its two temp files. The first is a real
|
|
# gap in the log and is why `report` counts `fire` records, not `exit` records. The second is
|
|
# near-unreachable — every capture-mode hook prints its decision and exits immediately, a
|
|
# sub-millisecond window. The third is bounded by $TMPDIR cleanup.
|
|
#
|
|
# The invariant that replaces the rescue is stronger and is what the tests now assert: under a
|
|
# signal an instrumented hook behaves EXACTLY as an uninstrumented one.
|
|
trap 'etv_hook_fire_end "$?"' EXIT
|
|
return 0
|
|
}
|
|
|
|
# Flush and record, WITHOUT deciding how the process ends. `ETV_HOOK_FIRE_FLUSHED` keeps it
|
|
# idempotent. That guard is retained after the signal traps were withdrawn, because it is cheap and
|
|
# because the failure it prevents — two contradictory `exit` records for one invocation, a real
|
|
# `deny` followed by a phantom `no-op` — is silent, and re-entrancy would return the moment anyone
|
|
# adds a second caller.
|
|
etv_hook_fire_flush() {
|
|
local code="${1:-0}" out=""
|
|
# The `tr -d '\000'` below is a child process too, and it sat outside every locale declaration:
|
|
# `tr: Illegal byte sequence` reached the harness and truncated the classification copy.
|
|
local -x LC_ALL=C LANG=C
|
|
[ "${ETV_HOOK_FIRE_FLUSHED:-0}" = "1" ] && return 0
|
|
ETV_HOOK_FIRE_FLUSHED=1
|
|
|
|
# RESTORE FIRST, UNCONDITIONALLY — then replay if there is anything to replay.
|
|
#
|
|
# These were one conditional, `[ -n "$TMP" ] && [ -f "$TMP" ]`, and that coupling was the bug:
|
|
# `-f` asks "is there output to replay", but the fd restore must happen whenever the redirect was
|
|
# ESTABLISHED, which is a different fact. Any route that makes `-f` false while the redirect is
|
|
# live — the temp file unlinked by a $TMPDIR reaper mid-run (the fd stays valid, so the hook
|
|
# writes happily into an unlinked inode), a $TMPDIR where mktemp yields a non-regular file — left
|
|
# fd 1 still pointing at the temp target with the restore skipped, so nothing later could rescue
|
|
# the bytes. A guard's `deny` was silently discarded and the hook still exited 0.
|
|
#
|
|
# Split, the worst case degrades from "the guard is disarmed" to "the log is short", which is the
|
|
# correct failure direction for observability. Pinned by
|
|
# `test_output_SURVIVES_a_vanished_stdout_tempfile`.
|
|
if [ -n "${ETV_HOOK_FIRE_STDOUT_TMP:-}" ]; then
|
|
# Same rule as the stdin replay: a trailing `2>/dev/null` here would permanently silence stderr
|
|
# rather than suppress an error from this redirection. fd 3 is known open on this path.
|
|
exec 1>&3 3>&- || true
|
|
fi
|
|
if [ -n "${ETV_HOOK_FIRE_STDOUT_TMP:-}" ]; then
|
|
# ONE read, used for BOTH the replay and the classification, so the two cannot disagree. They
|
|
# did: the classifier read fd 4 while the replay preferred the file, so a hook that used fd 4
|
|
# itself replayed its `deny` correctly to the harness and filed it in the log as `no-op` — the
|
|
# log quietly contradicting the decision it exists to record.
|
|
#
|
|
# The `printf X` / `%X` dance preserves trailing newlines, which `$(...)` strips. Without it the
|
|
# rescue path delivered 52 bytes where the hook wrote 53, and every JSON parser downstream
|
|
# accepts the short form without complaint. Pinned by `test_stdout_is_replayed_BYTE_EXACT`.
|
|
#
|
|
# NO `2>/dev/null` ON THE `exec` — see the stdin comment. An earlier version of THIS line had
|
|
# it, eight lines below the comment forbidding it, which is why the rule is now restated at
|
|
# every `exec` rather than once.
|
|
if [ -r "${ETV_HOOK_FIRE_STDOUT_TMP:-}" ]; then
|
|
# Common path: stream the FILE straight through. A shell variable cannot hold a NUL byte, so
|
|
# replaying via `$(...)` silently drops them and warns on stderr; `cat` is byte-exact for any
|
|
# content. Classification reads the SAME file, so the two cannot disagree — reading them from
|
|
# different sources is what made the harness see `deny` while the log recorded `no-op`.
|
|
cat "$ETV_HOOK_FIRE_STDOUT_TMP" 2>/dev/null || true
|
|
# `tr -d '\000'` before the substitution: bash cannot hold a NUL in a variable and warns
|
|
# about it ON STDERR, which the harness sees — an instrumentation message leaking into a
|
|
# guard's output channel. Classification does not care about NULs; the replay above is
|
|
# byte-exact regardless, because it streams the file rather than a variable.
|
|
out=$( { head -c 65536 "$ETV_HOOK_FIRE_STDOUT_TMP" 2>/dev/null | tr -d '\000'; printf 'X'; } )
|
|
out="${out%X}"
|
|
else
|
|
# Rescue path: the name is gone but the fd still reads the unlinked inode. This one goes
|
|
# through a variable and is therefore NUL-lossy — stated rather than hidden, because the
|
|
# alternative is losing the output entirely.
|
|
out=$( { cat 2>/dev/null <&4 | tr -d '\000'; printf 'X'; } )
|
|
out="${out%X}"
|
|
[ -n "$out" ] && printf '%s' "$out"
|
|
fi
|
|
exec 4<&- || true
|
|
fi
|
|
|
|
etv_hook_fire_record \
|
|
"${ETV_HOOK_FIRE_NAME:-unknown-hook}" "${ETV_HOOK_FIRE_LABEL:-}" \
|
|
"${ETV_HOOK_FIRE_EVENT:-}" "${ETV_HOOK_FIRE_TOOL:-}" \
|
|
"exit" "$code" "$(etv_hook_fire_classify "$out" "$code" "${ETV_HOOK_FIRE_MODE:-capture}")" || true
|
|
|
|
rm -f "${ETV_HOOK_FIRE_STDIN_TMP:-}" "${ETV_HOOK_FIRE_STDOUT_TMP:-}" 2>/dev/null || true
|
|
ETV_HOOK_FIRE_STDOUT_TMP=""
|
|
return 0
|
|
}
|
|
|
|
etv_hook_fire_end() {
|
|
local code="${1:-0}"
|
|
etv_hook_fire_flush "$code"
|
|
# Re-raise the hook's own status explicitly rather than relying on the trap preserving it. Bash
|
|
# does not re-enter an EXIT trap, so this is not recursive.
|
|
exit "$code"
|
|
}
|
|
|
|
|
|
# ---------------------------------------------------------------------------------------------
|
|
# Read side: the report
|
|
# ---------------------------------------------------------------------------------------------
|
|
|
|
# The hook population, DERIVED from the filesystem, never listed
|
|
# (`testing.guard-derives-population-from-source`). A hook added tomorrow appears in the report as
|
|
# NEVER-FIRED the moment it exists, rather than being invisible because nobody updated an array.
|
|
etv_hook_fire_population() {
|
|
local root="${1:-}" f
|
|
[ -d "$root/.claude/hooks" ] || return 0
|
|
for f in "$root"/.claude/hooks/*.sh; do
|
|
[ -f "$f" ] || continue
|
|
basename "$f" .sh
|
|
done
|
|
}
|
|
|
|
etv_hook_fire_repo_root() {
|
|
if [ -n "${CLAUDE_PROJECT_DIR:-}" ] && [ -d "$CLAUDE_PROJECT_DIR/.claude/hooks" ]; then
|
|
printf '%s' "$CLAUDE_PROJECT_DIR"
|
|
return 0
|
|
fi
|
|
( cd -- "$(dirname -- "${BASH_SOURCE[0]}")/.." >/dev/null 2>&1 && pwd )
|
|
}
|
|
|
|
etv_hook_fire_report() {
|
|
local all=0 as_json=0 dir root files hook
|
|
while [ $# -gt 0 ]; do
|
|
case "$1" in
|
|
--all) all=1 ;;
|
|
--json) as_json=1 ;;
|
|
--dir) shift; ETV_HOOK_FIRE_LOG_DIR="${1:-}" ;;
|
|
--session) shift; ETV_HOOK_FIRE_SESSION="${1:-}" ;;
|
|
*) printf 'hook-fire-log: unknown report option %s\n' "$1" >&2; return 2 ;;
|
|
esac
|
|
shift
|
|
done
|
|
|
|
dir="$(etv_hook_fire_log_dir)"
|
|
root="$(etv_hook_fire_repo_root)"
|
|
|
|
if [ "$all" = "1" ]; then
|
|
files=$(find "$dir" -name '*.jsonl' -type f 2>/dev/null | sort)
|
|
else
|
|
files="$(etv_hook_fire_log_file)"
|
|
[ -f "$files" ] || files=""
|
|
fi
|
|
|
|
if [ -z "$files" ]; then
|
|
printf 'hook-fire-log: no records under %s%s\n' "$dir" \
|
|
"$([ "$all" = "1" ] || printf ' for session %s (try --all)' "$(etv_hook_fire_session)")" >&2
|
|
fi
|
|
|
|
# ANTI-VACUITY. A report over an empty population would print a clean table of nothing and read
|
|
# as "all hooks accounted for" — the exact failure this file exists to end.
|
|
local pop
|
|
pop=$(etv_hook_fire_population "$root")
|
|
if [ -z "$pop" ]; then
|
|
printf 'hook-fire-log: found NO hook scripts under %s/.claude/hooks — refusing to report, because a report over an empty population reads as full coverage.\n' "$root" >&2
|
|
return 2
|
|
fi
|
|
|
|
local total_fires=0 rows=""
|
|
while IFS= read -r hook; do
|
|
[ -n "$hook" ] || continue
|
|
local fires decisions
|
|
fires=0
|
|
decisions=""
|
|
if [ -n "$files" ]; then
|
|
fires=$(cat $files 2>/dev/null | grep -c "\"hook\":\"$hook\",.*\"phase\":\"fire\"" || true)
|
|
decisions=$(cat $files 2>/dev/null \
|
|
| grep "\"hook\":\"$hook\",.*\"phase\":\"exit\"" \
|
|
| sed -n 's/.*"decision":"\([^"]*\)".*/\1/p' \
|
|
| sort | uniq -c | sort -rn \
|
|
| awk '{printf "%s=%s ", $2, $1}')
|
|
fi
|
|
[ -z "$fires" ] && fires=0
|
|
total_fires=$((total_fires + fires))
|
|
if [ "$as_json" = "1" ]; then
|
|
rows="${rows}{\"hook\":\"$hook\",\"fires\":$fires,\"decisions\":\"$(printf '%s' "$decisions" | tr -d '"')\"}\n"
|
|
else
|
|
rows="$(printf '%s%-34s %6s %s\n' "$rows" "$hook" "$fires" "${decisions:-—}")"$'\n'
|
|
fi
|
|
done <<EOF
|
|
$pop
|
|
EOF
|
|
|
|
if [ "$as_json" = "1" ]; then
|
|
printf '{"log_dir":"%s","total_fires":%s,"hooks":[%s]}\n' "$dir" "$total_fires" \
|
|
"$(printf '%b' "$rows" | sed '/^$/d' | paste -sd, -)"
|
|
return 0
|
|
fi
|
|
|
|
printf 'Hook fire log — %s\n' "$dir"
|
|
printf '%-34s %6s %s\n' 'HOOK' 'FIRES' 'DECISIONS'
|
|
printf '%s' "$rows"
|
|
printf '\n%s hook scripts on disk, %s recorded fires.\n' "$(printf '%s\n' "$pop" | wc -l | tr -d ' ')" "$total_fires"
|
|
printf 'A hook showing 0 has NOT been observed firing. That is a finding to investigate (broken\nwiring vs genuinely never matched in this window), not a blank to ignore.\n'
|
|
return 0
|
|
}
|
|
|
|
# ---------------------------------------------------------------------------------------------
|
|
# CLI (only when executed, never when sourced)
|
|
# ---------------------------------------------------------------------------------------------
|
|
|
|
if [ "${BASH_SOURCE[0]}" = "$0" ]; then
|
|
set -uo pipefail
|
|
case "${1:-report}" in
|
|
report) shift 2>/dev/null || true; etv_hook_fire_report "$@" ;;
|
|
path) etv_hook_fire_log_file; printf '\n' ;;
|
|
record) shift; etv_hook_fire_record "$@" ;;
|
|
*)
|
|
printf 'usage: %s [report [--all|--json|--dir D|--session S] | path]\n' "$0" >&2
|
|
exit 2
|
|
;;
|
|
esac
|
|
fi
|