feat(hooks): add debug logging, capture console.log output, fail closed on matched-then-errored hooks (#1337)

prefilter() had zero logging -- matcher regex failures, tool-name
mismatches, CEL compile errors, and CEL evaluating to false were all
completely silent, making a misconfigured hook impossible to debug.
A user's PreToolUse script hook silently failed to block an
unauthorized file write with no way to determine why.

- Added slog.Debug/Warn logging throughout prefilter() and the
  dispatch chain: hooks.prefilter.considered, matcher_checked,
  condition_evaluated, error, and hooks.dispatch.decision -- covering
  matcher match/miss, CEL compile/eval result, and final decision
  with reasoning.
- console.log/console.error output from script hooks (captured via
  the existing goja sandbox stdout buffer, previously discarded after
  execution) now surfaces via slog.Debug and persists into
  HookExecution.ConsoleOutput / Metadata["console_output"] in the
  audit record, using the existing metadata JSON column (no
  migration needed).
- Fail-closed, narrowly scoped: when a hook's matcher successfully
  matches a tool call but CEL condition or script execution then
  errors, the dispatcher now blocks that specific tool call
  (previously: silently treated as non-match, call proceeded
  allowed). Hooks that legitimately don't match remain unaffected
  pass-through -- this does not turn one broken hook into a global
  outage, it only blocks the specific gated action that couldn't be
  confidently evaluated.

Added tests: matched-then-CEL-errors blocks the call and never
invokes the handler; matcher-doesn't-match proceeds normally
unaffected (confirms narrow scope); console.log output is captured
in the audit record.

Co-authored-by: Bruno Clermont <bruno.clermont@gmail.com>

internal/hooks/dispatcher.go

@@ -202,11 +202,30 @@ func (d *stdDispatcher) runSync(ctx context.Context, ev Event, chain []HookConfi
 		if !cfg.Enabled {
 			continue
 		}
+		slog.Debug("hooks.prefilter.considered",
+			"hook_id", cfg.ID, "tool_name", evMut.ToolName, "agent_id", evMut.AgentID, "hook_event", evMut.HookEvent)
 		if d.cb.isTripped(cfg.ID, d.now()) {
-			d.writeExec(ctx, cfg, evMut, DecisionBlock, 0, "circuit breaker open")
+			slog.Warn("hooks.dispatch.decision",
+				"hook_id", cfg.ID, "decision", "block", "reason", "circuit breaker open")
+			d.writeExec(ctx, cfg, evMut, DecisionBlock, 0, "circuit breaker open", "")
 			return FireResult{Decision: DecisionBlock}, nil
 		}
-		if !d.prefilter(cfg, evMut) {
+		pf := d.prefilter(cfg, evMut)
+		if pf.errored {
+			// Fail-closed (narrow scope): the matcher matched this call, but
+			// the CEL condition then failed to compile/evaluate. We cannot
+			// know whether the hook intended to block or allow, so we treat
+			// this specific tool call as blocked rather than silently
+			// letting it through. Other hooks/calls are unaffected.
+			blockMsg := fmt.Sprintf("hook evaluation failed: %v", pf.err)
+			slog.Warn("hooks.dispatch.decision",
+				"hook_id", cfg.ID, "decision", "block", "reason", blockMsg)
+			d.writeExec(ctx, cfg, evMut, DecisionBlock, 0, blockMsg, "")
+			return FireResult{Decision: DecisionBlock}, nil
+		}
+		if !pf.match {
+			slog.Debug("hooks.dispatch.decision",
+				"hook_id", cfg.ID, "decision", "skip", "reason", "prefilter did not match")
 			continue
 		}
 
@@ -221,7 +240,9 @@ func (d *stdDispatcher) runSync(ctx context.Context, ev Event, chain []HookConfi
 		if execErr != nil {
 			errMsg = execErr.Error()
 		}
-		d.writeExec(ctx, cfg, evMut, dec, duration, errMsg)
+		slog.Debug("hooks.dispatch.decision",
+			"hook_id", cfg.ID, "decision", string(dec), "duration_ms", duration.Milliseconds(), "err", errMsg)
+		d.writeExec(ctx, cfg, evMut, dec, duration, errMsg, scriptRes.Stdout)
 
 		// Apply mutation to the local copy only when the hook is builtin-source.
 		// Non-builtin scripts get their updatedInput stripped + warned.
@@ -357,20 +378,40 @@ const SourceBuiltin = "builtin"
 // goroutine-per-hook; Phase 2 will route through the eventbus worker pool.
 func (d *stdDispatcher) runAsync(ctx context.Context, ev Event, chain []HookConfig) {
 	for _, cfg := range chain {
-		if !cfg.Enabled || !d.prefilter(cfg, ev) {
+		if !cfg.Enabled {
+			continue
+		}
+		slog.Debug("hooks.prefilter.considered",
+			"hook_id", cfg.ID, "tool_name", ev.ToolName, "agent_id", ev.AgentID, "hook_event", ev.HookEvent)
+		pf := d.prefilter(cfg, ev)
+		if pf.errored {
+			// Non-blocking event: there is no tool call to block, so we log
+			// loudly and skip this hook rather than fail-closed. Fail-closed
+			// blocking only applies to the synchronous (blocking) chain.
+			slog.Warn("hooks.dispatch.decision",
+				"hook_id", cfg.ID, "decision", "skip", "reason", fmt.Sprintf("prefilter error: %v", pf.err))
+			continue
+		}
+		if !pf.match {
+			slog.Debug("hooks.dispatch.decision",
+				"hook_id", cfg.ID, "decision", "skip", "reason", "prefilter did not match")
 			continue
 		}
 		go func(c HookConfig) {
-			dec, execErr, duration := d.runOne(ctx, c, ev)
+			scriptRes := &ScriptResult{}
+			hctx := WithScriptResult(ctx, scriptRes)
+			dec, execErr, duration := d.runOne(hctx, c, ev)
 			errMsg := ""
 			if execErr != nil {
 				errMsg = execErr.Error()
 			}
+			slog.Debug("hooks.dispatch.decision",
+				"hook_id", c.ID, "decision", string(dec), "duration_ms", duration.Milliseconds(), "err", errMsg)
 			// Use WithoutCancel to preserve context values (TenantID, UserID)
 			// but detach from parent deadline, then add a timeout to prevent indefinite hang
 			writeCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), 5*time.Second)
 			defer cancel()
-			d.writeExec(writeCtx, c, ev, dec, duration, errMsg)
+			d.writeExec(writeCtx, c, ev, dec, duration, errMsg, scriptRes.Stdout)
 		}(cfg)
 	}
 }
@@ -400,54 +441,92 @@ func (d *stdDispatcher) runOne(ctx context.Context, cfg HookConfig, ev Event) (D
 	return dec, err, duration
 }
 
+// prefilterResult distinguishes "hook legitimately did not match" (match=false,
+// errored=false — normal pass-through, no side effects) from "matcher matched
+// but the CEL condition then failed to compile/evaluate" (errored=true — the
+// caller must fail-closed for blocking events). Matcher regex compile
+// failures are treated as a non-match (pre-existing behavior, out of the
+// narrow fail-closed scope requested) since there is no successful match to
+// fail closed on.
+type prefilterResult struct {
+	match   bool
+	errored bool
+	err     error
+}
+
 // prefilter applies the matcher + CEL gate; Phase 1 keeps it lightweight and
 // pushes the actual compile through matcher.go's cached helpers.
-func (d *stdDispatcher) prefilter(cfg HookConfig, ev Event) bool {
+func (d *stdDispatcher) prefilter(cfg HookConfig, ev Event) prefilterResult {
 	if cfg.Matcher != "" {
 		re, err := CompileMatcher(cfg.Matcher)
-		if err != nil || !MatchToolName(re, ev.ToolName) {
-			return false
+		if err != nil {
+			slog.Warn("hooks.prefilter.error",
+				"hook_id", cfg.ID, "stage", "matcher_compile", "matcher", cfg.Matcher, "err", err)
+			return prefilterResult{match: false}
+		}
+		matched := MatchToolName(re, ev.ToolName)
+		slog.Debug("hooks.prefilter.matcher_checked",
+			"hook_id", cfg.ID, "tool_name", ev.ToolName, "matcher", cfg.Matcher, "matched", matched)
+		if !matched {
+			return prefilterResult{match: false}
 		}
 	}
 	if cfg.IfExpr != "" {
 		prg, err := CompileCELExpr(cfg.IfExpr)
 		if err != nil {
-			return false
+			slog.Warn("hooks.prefilter.error",
+				"hook_id", cfg.ID, "stage", "cel_compile", "expr", cfg.IfExpr, "err", err)
+			return prefilterResult{errored: true, err: fmt.Errorf("CEL compile failed: %w", err)}
 		}
 		ok, err := EvalCEL(prg, map[string]any{
 			"tool_name":  ev.ToolName,
 			"tool_input": ev.ToolInput,
 			"depth":      ev.Depth,
 		})
-		if err != nil || !ok {
-			return false
+		if err != nil {
+			slog.Warn("hooks.prefilter.error",
+				"hook_id", cfg.ID, "stage", "cel_eval", "err", err)
+			return prefilterResult{errored: true, err: fmt.Errorf("CEL evaluation failed: %w", err)}
+		}
+		slog.Debug("hooks.prefilter.condition_evaluated",
+			"hook_id", cfg.ID, "result", ok)
+		if !ok {
+			return prefilterResult{match: false}
 		}
 	}
-	return true
+	return prefilterResult{match: true}
 }
 
 // writeExec assembles the audit row and routes it through AuditWriter which
 // handles truncation, redaction, and encryption. Failures are logged but do
 // not propagate — audit is observability, not policy.
-func (d *stdDispatcher) writeExec(ctx context.Context, cfg HookConfig, ev Event, dec Decision, duration time.Duration, errMsg string) {
+func (d *stdDispatcher) writeExec(ctx context.Context, cfg HookConfig, ev Event, dec Decision, duration time.Duration, errMsg string, consoleOutput string) {
 	if d.audit == nil {
 		return
 	}
 	inputHash, _ := CanonicalInputHash(ev.ToolName, ev.ToolInput)
 	hookID := cfg.ID
+	metadata := map[string]any{}
+	if consoleOutput != "" {
+		// No dedicated DB column for console output — mirrored into the
+		// already-persisted JSON metadata column so it survives AuditWriter.Log
+		// without a schema migration.
+		metadata["console_output"] = consoleOutput
+	}
 	exec := HookExecution{
-		ID:         uuid.New(),
-		HookID:     &hookID,
-		TenantID:   &ev.TenantID,
-		SessionID:  ev.SessionID,
-		Event:      ev.HookEvent,
-		InputHash:  inputHash,
-		Decision:   dec,
-		DurationMS: int(duration / time.Millisecond),
-		DedupKey:   cfg.ID.String() + ":" + ev.EventID,
-		Error:      errMsg,
-		Metadata:   map[string]any{},
-		CreatedAt:  d.now(),
+		ID:            uuid.New(),
+		HookID:        &hookID,
+		TenantID:      &ev.TenantID,
+		SessionID:     ev.SessionID,
+		Event:         ev.HookEvent,
+		InputHash:     inputHash,
+		Decision:      dec,
+		DurationMS:    int(duration / time.Millisecond),
+		DedupKey:      cfg.ID.String() + ":" + ev.EventID,
+		Error:         errMsg,
+		Metadata:      metadata,
+		ConsoleOutput: consoleOutput,
+		CreatedAt:     d.now(),
 	}
 	if err := d.audit.Log(ctx, exec); err != nil {
 		slog.Warn("security.hook.audit_write_failed", "err", err, "hook_id", cfg.ID)

internal/hooks/dispatcher_test.go

@@ -627,3 +627,125 @@ func allowlistID(name string) uuid.UUID {
 	// Stable deterministic UUID per label so cfg.ID matches the lookup.
 	return uuid.NewSHA1(uuid.NameSpaceDNS, []byte("test.allowlist/"+name))
 }
+
+// TestDispatcher_MatchedThenCELErrors_FailsClosed verifies the narrow
+// fail-closed contract: a hook whose matcher successfully matches the tool
+// name, but whose CEL `if` expression then fails to compile, must BLOCK that
+// specific tool call rather than silently allow it through.
+func TestDispatcher_MatchedThenCELErrors_FailsClosed(t *testing.T) {
+	cfg := newBaseHook(hooks.HandlerHTTP, hooks.EventPreToolUse)
+	cfg.Matcher = "shell_exec"                // matches the tool name below
+	cfg.IfExpr = "tool_input.foo +++ bogus((" // deliberately invalid CEL
+	fs := &fakeStore{hooks: []hooks.HookConfig{cfg}}
+
+	handler := &fakeHandler{decision: hooks.DecisionAllow}
+	d := hooks.NewStdDispatcher(hooks.StdDispatcherOpts{
+		Store:    fs,
+		Audit:    hooks.NewAuditWriter(fs, ""),
+		Handlers: map[hooks.HandlerType]hooks.Handler{hooks.HandlerHTTP: handler},
+	})
+
+	r, err := d.Fire(context.Background(), hooks.Event{
+		EventID:   "e-cel-error",
+		HookEvent: hooks.EventPreToolUse,
+		ToolName:  "shell_exec",
+		ToolInput: map[string]any{},
+	})
+	if err != nil {
+		t.Fatalf("Fire: %v", err)
+	}
+	if r.Decision != hooks.DecisionBlock {
+		t.Fatalf("decision=%q, want block (matched hook with broken CEL must fail-closed)", r.Decision)
+	}
+	if atomic.LoadInt32(&handler.calls) != 0 {
+		t.Errorf("handler.calls=%d, want 0 — the hook must never execute once prefilter errors", handler.calls)
+	}
+}
+
+// TestDispatcher_MatcherNoMatch_ProceedsNormally confirms the fail-closed
+// change is scoped to "matched but then errored" only: a hook whose matcher
+// regex simply doesn't match the tool name must NOT block the call — it's
+// normal pass-through, not an error condition.
+func TestDispatcher_MatcherNoMatch_ProceedsNormally(t *testing.T) {
+	cfg := newBaseHook(hooks.HandlerHTTP, hooks.EventPreToolUse)
+	cfg.Matcher = "^does_not_match$"
+	fs := &fakeStore{hooks: []hooks.HookConfig{cfg}}
+
+	handler := &fakeHandler{decision: hooks.DecisionBlock} // would block if it ran
+	d := hooks.NewStdDispatcher(hooks.StdDispatcherOpts{
+		Store:    fs,
+		Audit:    hooks.NewAuditWriter(fs, ""),
+		Handlers: map[hooks.HandlerType]hooks.Handler{hooks.HandlerHTTP: handler},
+	})
+
+	r, err := d.Fire(context.Background(), hooks.Event{
+		EventID:   "e-no-match",
+		HookEvent: hooks.EventPreToolUse,
+		ToolName:  "shell_exec",
+		ToolInput: map[string]any{},
+	})
+	if err != nil {
+		t.Fatalf("Fire: %v", err)
+	}
+	if r.Decision != hooks.DecisionAllow {
+		t.Fatalf("decision=%q, want allow — a non-matching hook must not affect the call", r.Decision)
+	}
+	if atomic.LoadInt32(&handler.calls) != 0 {
+		t.Errorf("handler.calls=%d, want 0 — non-matching hook must not execute", handler.calls)
+	}
+}
+
+// consoleCapturingHandler mimics a script handler writing captured
+// console.log/console.error output into the ctx-carried ScriptResult, the
+// same way handlers.ScriptHandler.Execute does after running goja.
+type consoleCapturingHandler struct {
+	stdout string
+}
+
+func (h *consoleCapturingHandler) Execute(ctx context.Context, _ hooks.HookConfig, _ hooks.Event) (hooks.Decision, error) {
+	if r := hooks.ScriptResultFrom(ctx); r != nil {
+		r.Stdout = h.stdout
+	}
+	return hooks.DecisionAllow, nil
+}
+
+// TestDispatcher_ScriptConsoleOutput_CapturedInAuditRecord verifies that
+// console.log/console.error output from a script hook execution is persisted
+// on the audit record (HookExecution.ConsoleOutput + mirrored into Metadata).
+func TestDispatcher_ScriptConsoleOutput_CapturedInAuditRecord(t *testing.T) {
+	cfg := newBaseHook(hooks.HandlerScript, hooks.EventPreToolUse)
+	fs := &fakeStore{hooks: []hooks.HookConfig{cfg}}
+
+	h := &consoleCapturingHandler{stdout: "log: hello from script\n"}
+	d := hooks.NewStdDispatcher(hooks.StdDispatcherOpts{
+		Store:    fs,
+		Audit:    hooks.NewAuditWriter(fs, ""),
+		Handlers: map[hooks.HandlerType]hooks.Handler{hooks.HandlerScript: h},
+	})
+
+	r, err := d.Fire(context.Background(), hooks.Event{
+		EventID:   "e-console",
+		HookEvent: hooks.EventPreToolUse,
+		ToolName:  "shell_exec",
+		ToolInput: map[string]any{},
+	})
+	if err != nil {
+		t.Fatalf("Fire: %v", err)
+	}
+	if r.Decision != hooks.DecisionAllow {
+		t.Fatalf("decision=%q, want allow", r.Decision)
+	}
+
+	execs := fs.snapshotExecs()
+	if len(execs) != 1 {
+		t.Fatalf("len(execs)=%d, want 1", len(execs))
+	}
+	exec := execs[0]
+	if exec.ConsoleOutput != h.stdout {
+		t.Errorf("exec.ConsoleOutput=%q, want %q", exec.ConsoleOutput, h.stdout)
+	}
+	got, ok := exec.Metadata["console_output"].(string)
+	if !ok || got != h.stdout {
+		t.Errorf("exec.Metadata[console_output]=%v, want %q", exec.Metadata["console_output"], h.stdout)
+	}
+}

internal/hooks/handlers/script.go

@@ -203,6 +203,9 @@ func (h *ScriptHandler) Execute(ctx context.Context, cfg hooks.HookConfig, ev ho
 	// Write non-decision outputs for dispatcher pickup (Phase 03 applies them
 	// only when cfg.Source == "builtin"). Standalone tests may not provision a
 	// ScriptResult — ScriptResultFrom returns nil in that case, which is fine.
+	if out := stdout.String(); out != "" {
+		slog.Debug("hooks.script.console_output", "hook_id", cfg.ID, "output", out)
+	}
 	if r := hooks.ScriptResultFrom(ctx); r != nil {
 		r.Reason = reason
 		r.UpdatedInput = updated

internal/hooks/types.go

@@ -158,47 +158,52 @@ type FireResult struct {
 // HookConfig mirrors the agent_hooks DB row. All pointer fields correspond to
 // nullable columns.
 type HookConfig struct {
-	ID          uuid.UUID          `json:"id"`
-	TenantID    uuid.UUID          `json:"tenant_id"`
-	AgentID     *uuid.UUID         `json:"agent_id,omitempty"`     // DEPRECATED: kept for JSON backward compat
-	AgentIDs    []uuid.UUID        `json:"agent_ids,omitempty"`
-	Event       HookEvent          `json:"event"`
-	HandlerType HandlerType        `json:"handler_type"`
-	Scope       Scope              `json:"scope"`
-	Name        string             `json:"name,omitempty"`
+	ID          uuid.UUID   `json:"id"`
+	TenantID    uuid.UUID   `json:"tenant_id"`
+	AgentID     *uuid.UUID  `json:"agent_id,omitempty"` // DEPRECATED: kept for JSON backward compat
+	AgentIDs    []uuid.UUID `json:"agent_ids,omitempty"`
+	Event       HookEvent   `json:"event"`
+	HandlerType HandlerType `json:"handler_type"`
+	Scope       Scope       `json:"scope"`
+	Name        string      `json:"name,omitempty"`
 	// Config holds handler-specific options (command path, HTTP URL, prompt template).
-	Config      map[string]any     `json:"config"`
-	Matcher     string             `json:"matcher,omitempty"`
-	IfExpr      string             `json:"if_expr,omitempty"`
-	TimeoutMS   int                `json:"timeout_ms"`
-	OnTimeout   Decision           `json:"on_timeout"`
-	Priority    int                `json:"priority"`
-	Enabled     bool               `json:"enabled"`
-	Version     int                `json:"version"`
-	Source      string             `json:"source"`
-	Metadata    map[string]any     `json:"metadata"`
-	CreatedBy   *uuid.UUID         `json:"created_by,omitempty"`
-	CreatedAt   time.Time          `json:"created_at"`
-	UpdatedAt   time.Time          `json:"updated_at"`
+	Config    map[string]any `json:"config"`
+	Matcher   string         `json:"matcher,omitempty"`
+	IfExpr    string         `json:"if_expr,omitempty"`
+	TimeoutMS int            `json:"timeout_ms"`
+	OnTimeout Decision       `json:"on_timeout"`
+	Priority  int            `json:"priority"`
+	Enabled   bool           `json:"enabled"`
+	Version   int            `json:"version"`
+	Source    string         `json:"source"`
+	Metadata  map[string]any `json:"metadata"`
+	CreatedBy *uuid.UUID     `json:"created_by,omitempty"`
+	CreatedAt time.Time      `json:"created_at"`
+	UpdatedAt time.Time      `json:"updated_at"`
 }
 
 // HookExecution mirrors the hook_executions DB row.
 // error_detail (BYTEA) is AES-256-GCM encrypted before storage.
 type HookExecution struct {
-	ID          uuid.UUID  `json:"id"`
-	HookID      *uuid.UUID `json:"hook_id,omitempty"`  // NULL when hook deleted (ON DELETE SET NULL)
-	TenantID    *uuid.UUID `json:"tenant_id,omitempty"`
-	SessionID   string     `json:"session_id"`
-	Event       HookEvent  `json:"event"`
-	InputHash   string     `json:"input_hash"`  // canonical-JSON sha256, 64 hex chars
-	Decision    Decision   `json:"decision"`
-	DurationMS  int        `json:"duration_ms"`
-	Retry       int        `json:"retry"`
-	DedupKey    string     `json:"dedup_key"`   // (hook_id, event_id) composite
-	Error       string     `json:"error"`        // truncated to 256 chars
-	ErrorDetail []byte     `json:"error_detail"` // encrypted; nil if no error
+	ID          uuid.UUID      `json:"id"`
+	HookID      *uuid.UUID     `json:"hook_id,omitempty"` // NULL when hook deleted (ON DELETE SET NULL)
+	TenantID    *uuid.UUID     `json:"tenant_id,omitempty"`
+	SessionID   string         `json:"session_id"`
+	Event       HookEvent      `json:"event"`
+	InputHash   string         `json:"input_hash"` // canonical-JSON sha256, 64 hex chars
+	Decision    Decision       `json:"decision"`
+	DurationMS  int            `json:"duration_ms"`
+	Retry       int            `json:"retry"`
+	DedupKey    string         `json:"dedup_key"`    // (hook_id, event_id) composite
+	Error       string         `json:"error"`        // truncated to 256 chars
+	ErrorDetail []byte         `json:"error_detail"` // encrypted; nil if no error
 	Metadata    map[string]any `json:"metadata"`
-	CreatedAt   time.Time  `json:"created_at"`
+	// ConsoleOutput carries captured `console.log`/`console.error` text from
+	// script-handler executions (bounded by handlers.MaxStdoutBytes). Not a
+	// dedicated DB column — the dispatcher mirrors it into Metadata["console_output"]
+	// before AuditWriter.Log persists the row, so no schema migration is needed.
+	ConsoleOutput string    `json:"console_output,omitempty"`
+	CreatedAt     time.Time `json:"created_at"`
 }
 
 // Event is the payload passed to the dispatcher and stored for audit.
@@ -211,13 +216,13 @@ type Event struct {
 	TenantID  uuid.UUID
 	AgentID   uuid.UUID
 	// ToolName is populated for PreToolUse/PostToolUse events.
-	ToolName  string
+	ToolName string
 	// ToolInput is the raw tool arguments map for CEL evaluation.
 	ToolInput map[string]any
 	// RawInput is the user's raw message text (for UserPromptSubmit).
-	RawInput  string
+	RawInput string
 	// Depth tracks sub-agent nesting level; max 3 before loop rejection.
-	Depth     int
+	Depth int
 	// HookEvent is the lifecycle event type.
 	HookEvent HookEvent
 }