diff --git a/internal/hooks/dispatcher.go b/internal/hooks/dispatcher.go index d21b9617..f4edb1b5 100644 --- a/internal/hooks/dispatcher.go +++ b/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) diff --git a/internal/hooks/dispatcher_test.go b/internal/hooks/dispatcher_test.go index 8d2eff42..35dd0fa5 100644 --- a/internal/hooks/dispatcher_test.go +++ b/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) + } +} diff --git a/internal/hooks/handlers/script.go b/internal/hooks/handlers/script.go index a72241cf..04aa9d9e 100644 --- a/internal/hooks/handlers/script.go +++ b/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 diff --git a/internal/hooks/types.go b/internal/hooks/types.go index a55485f7..eed3ee51 100644 --- a/internal/hooks/types.go +++ b/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 }