Files
ersatztv/scripts/hook-fire-log.sh
T
timothyandClaude Opus 5 fc65b5fbe3 docs(776,784): state the hazard, not the author's timeline
Applies ersatztv#784's who-benefits test to this change's own prose: if only
the author's timeline explains why a sentence is there, it is narrative. Three
comments said "the first version of this did X" where the reader only needs the
hazard and the reason nothing downstream would catch it.

One of the three turned into a real correction rather than a reword. The
byte-exactness test was justified as "the A/B does not cover this", which is
sharper and also true: the A/B compares the two halves against each other, so a
wrapper that truncated BOTH would pass it. Only comparing against the literal
expected bytes catches that.

Refs: #776
Refs: #784

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-14 18:52:57 +02:00

364 lines
17 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() {
printf '%s/%s.jsonl' "$(etv_hook_fire_log_dir)" "$(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
}
# 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
printf '%s\n' "$line" >> "$file" 2>/dev/null || 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=""
# 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
d=$(printf '%s' "$out" | sed -n 's/.*"permissionDecision"[[:space:]]*:[[:space:]]*"\([a-z]*\)".*/\1/p' | head -n1)
[ -z "$d" ] && d=$(printf '%s' "$out" | sed -n 's/.*"decision"[[:space:]]*:[[:space:]]*"\([a-z]*\)".*/\1/p' | head -n1)
# `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.
if [ -z "$d" ] && printf '%s' "$out" | grep -q 'additionalContext'; then d="context"; fi
[ -z "$d" ] && d="output"
fi
# Exit 2 is the harness's non-JSON block channel. No hook here uses it today; it is classified
# anyway so that a hook which starts using it is not silently recorded as a no-op.
if [ "$code" = "2" ] && [ -z "$d" ]; then d="deny-exit2"; fi
[ -z "$d" ] && d="no-op"
[ "$code" != "0" ] && [ "$code" != "2" ] && d="error"
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=""
[ "${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 > "$sin" 2>/dev/null || true
# Replay unconditionally: even a partial capture is closer to the truth than the drained pipe
# the hook would otherwise inherit.
exec 0<"$sin" 2>/dev/null || true
payload=$(head -c 65536 "$sin" 2>/dev/null || true)
fi
if [ -n "$payload" ]; then
event=$(printf '%s' "$payload" | sed -n 's/.*"hook_event_name"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' | head -n1)
tool=$(printf '%s' "$payload" | sed -n 's/.*"tool_name"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' | head -n1)
sess=$(printf '%s' "$payload" | sed -n 's/.*"session_id"[[:space:]]*:[[:space:]]*"\([^"]*\)".*/\1/p' | head -n1)
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; }
fi
trap 'etv_hook_fire_end "$?"' EXIT
return 0
}
etv_hook_fire_end() {
local code="${1:-0}" out=""
# RESTORE AND REPLAY FIRST. Everything after this point is bookkeeping; if any of it dies, the
# hook has already said what it came to say. Getting this order wrong would let an instrumentation
# bug swallow a `deny`, which is the one outcome worse than not logging at all.
if [ -n "${ETV_HOOK_FIRE_STDOUT_TMP:-}" ] && [ -f "${ETV_HOOK_FIRE_STDOUT_TMP:-}" ]; then
exec 1>&3 3>&- 2>/dev/null || true
# `cat` the FILE, not a variable. `out=$(cat f)` strips trailing newlines, so replaying from a
# variable delivers the hook's JSON one byte short of what it wrote — and every JSON parser
# downstream accepts the short form, so nothing would ever complain. Pinned by
# `test_stdout_is_replayed_BYTE_EXACT`.
cat "$ETV_HOOK_FIRE_STDOUT_TMP" 2>/dev/null || true
# A separate read for CLASSIFICATION only, where losing a trailing newline is harmless.
out=$(head -c 65536 "$ETV_HOOK_FIRE_STDOUT_TMP" 2>/dev/null || 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
# 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