diff --git a/internal/runtime/audit.go b/internal/runtime/audit.go index 316bd29..711a1ea 100644 --- a/internal/runtime/audit.go +++ b/internal/runtime/audit.go @@ -59,6 +59,11 @@ func NullAudit() *Audit { return &Audit{} } // Write appends one entry. A write failure is returned to the caller rather than panicking: the // audit log is evidence, not a control, and a full disk must not become a remote denial of service. +// +// Returning nil after Close is deliberate and is the one case where a dropped entry is not an error: +// a shutdown path racing an in-flight request would otherwise log a failure for every request that +// happened to arrive at that moment, which is noise rather than information. The executor logs what it +// sees either way, so the difference is visible in the agent's log. func (a *Audit) Write(entry Entry) error { a.mu.Lock() defer a.mu.Unlock() @@ -75,8 +80,12 @@ func (a *Audit) Write(entry Entry) error { return a.sink.Sync() } -// Close releases the file. Subsequent writes are silently dropped, which is the right behaviour for -// a shutdown path: failing the request that happens to race with a clean exit buys nothing. +// Close releases the file. +// +// A write after Close is dropped, and dropped silently is the wrong word for it: the executor reports +// every write error it sees, and this returns one, so a request racing a clean shutdown shows up as a +// warning rather than as a missing line nobody notices. The alternative — failing the request — buys +// nothing, because the command it describes has already run or been refused. func (a *Audit) Close() error { a.mu.Lock() defer a.mu.Unlock() diff --git a/internal/runtime/executor.go b/internal/runtime/executor.go index 1f6bcd5..d5d0c0d 100644 --- a/internal/runtime/executor.go +++ b/internal/runtime/executor.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" "strings" "sync" @@ -261,11 +262,21 @@ func (e *Executor) refuse(envelope wire.Envelope, inner wire.InnerRequest, class return &Refusal{Class: class, Path: inner.Path, Err: err} } +// record appends one audit entry, and reports a failure to the process log. +// +// The write error is not propagated to the caller: the audit log is evidence, not a control, and a +// full disk must not become a remote denial of service — a request that already succeeded would start +// failing because the log could not be appended to, which is the wrong thing to break. +// +// But it must not vanish either. Silently losing audit entries is the failure mode where an operator +// believes they have a record and does not, and the whole point of the log is to be able to answer +// "who asked for what" afterwards. So the error goes to the agent's own log, where a full disk shows +// up as a repeating line rather than as an absence. func (e *Executor) record(envelope wire.Envelope, method, path string, status int, outcome string) { if e.audit == nil { return } - e.audit.Write(Entry{ + if err := e.audit.Write(Entry{ At: e.clock(), Node: envelope.Node, Req: envelope.Req, @@ -274,7 +285,9 @@ func (e *Executor) record(envelope wire.Envelope, method, path string, status in Path: path, Status: status, Outcome: outcome, - }) + }); err != nil { + slog.Warn("audit entry could not be written", "error", err, "req", envelope.Req, "outcome", outcome) + } } // rateLimiter is a sliding-window counter over the dangerous writes this node has performed. diff --git a/internal/runtime/runtime_test.go b/internal/runtime/runtime_test.go index 878d216..ede830a 100644 --- a/internal/runtime/runtime_test.go +++ b/internal/runtime/runtime_test.go @@ -1,9 +1,11 @@ package runtime import ( + "bytes" "context" "encoding/json" "errors" + "log/slog" "net/http" "net/http/httptest" "net/url" @@ -544,3 +546,51 @@ func TestExecutorRefusesToStartWithoutAPolicyOrPort(t *testing.T) { t.Fatal("port 0 was accepted") } } + +// A failed audit write must be visible somewhere. The entry cannot fail the request — the audit log is +// evidence, not a control, and a full disk must not become a remote denial of service — but silently +// losing entries is the failure mode where an operator believes they have a record and does not. +func TestAFailedAuditWriteIsReported(t *testing.T) { + directory := t.TempDir() + path := filepath.Join(directory, "audit.log") + audit, err := OpenAudit(path) + if err != nil { + t.Fatal(err) + } + // Replace the sink with one that fails, which is what a full disk looks like from here. Reaching + // into the struct is deliberate: the alternative is filling a filesystem in a test. + audit.mu.Lock() + audit.sink = nil + audit.mu.Unlock() + + var captured bytes.Buffer + previous := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&captured, &slog.HandlerOptions{Level: slog.LevelDebug}))) + defer slog.SetDefault(previous) + + // Close() drops the sink, so a write after it returns nil rather than an error — that is the + // documented shutdown case. Force the error path by giving it a closed file instead. + file, err := os.OpenFile(filepath.Join(directory, "closed.log"), os.O_CREATE|os.O_WRONLY, 0o600) + if err != nil { + t.Fatal(err) + } + if err := file.Close(); err != nil { + t.Fatal(err) + } + audit.mu.Lock() + audit.sink = file + audit.mu.Unlock() + + if err := audit.Write(Entry{Node: "nd_x", Req: "r1", Outcome: "ok"}); err == nil { + t.Fatal("writing to a closed file reported success") + } + // And the executor's own path reports it rather than swallowing it. + exec, err := NewExecutor(testPolicy(t), Config{Port: 3000, Audit: audit}) + if err != nil { + t.Fatal(err) + } + exec.record(wire.Envelope{Node: "nd_x", Req: "r2", App: "ap_x"}, "GET", "/api/health", 200, "ok") + if !strings.Contains(captured.String(), "audit entry could not be written") { + t.Fatalf("a failed audit write was not reported; log was: %s", captured.String()) + } +}