fix(agent): 审计写入失败不再静默

审计日志是证据而不是控制手段:写失败不能让请求失败,否则磁盘写满会变成一次远程
拒绝服务——已经执行成功的指令会因为日志追加不上而开始报错,那是坏错了地方。

但它也不能消失。静默丢审计条目是那种"运维以为自己有记录、其实没有"的失败,而这份
日志的全部意义就是事后能回答"谁在什么时候要求了什么"。现在写失败会进 agent 自己的
日志,磁盘写满表现为一行反复出现,而不是一片空白。

顺带把 Close 之后的语义写清楚:Close 会丢掉 sink,此后的写入返回 nil——这是刻意的,
因为一个正在关闭的进程与在途请求赛跑时,为每一个恰好到达的请求报一次失败是噪声
而不是信息。这条差别在 agent 日志里看得见。

测试用真实失败路径(写一个已关闭的文件)而不是填满文件系统,并断言 exec.record 把
它报了出来。

Go 全包、Node 112 项、Swift 101 项通过。
This commit is contained in:
chick
2026-09-17 01:52:59 +08:00
parent 3a9eec5de2
commit 9608a7ebc0
3 changed files with 76 additions and 4 deletions
+11 -2
View File
@@ -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 // 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. // 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 { func (a *Audit) Write(entry Entry) error {
a.mu.Lock() a.mu.Lock()
defer a.mu.Unlock() defer a.mu.Unlock()
@@ -75,8 +80,12 @@ func (a *Audit) Write(entry Entry) error {
return a.sink.Sync() return a.sink.Sync()
} }
// Close releases the file. Subsequent writes are silently dropped, which is the right behaviour for // Close releases the file.
// a shutdown path: failing the request that happens to race with a clean exit buys nothing. //
// 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 { func (a *Audit) Close() error {
a.mu.Lock() a.mu.Lock()
defer a.mu.Unlock() defer a.mu.Unlock()
+15 -2
View File
@@ -5,6 +5,7 @@ import (
"errors" "errors"
"fmt" "fmt"
"io" "io"
"log/slog"
"net/http" "net/http"
"strings" "strings"
"sync" "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} 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) { func (e *Executor) record(envelope wire.Envelope, method, path string, status int, outcome string) {
if e.audit == nil { if e.audit == nil {
return return
} }
e.audit.Write(Entry{ if err := e.audit.Write(Entry{
At: e.clock(), At: e.clock(),
Node: envelope.Node, Node: envelope.Node,
Req: envelope.Req, Req: envelope.Req,
@@ -274,7 +285,9 @@ func (e *Executor) record(envelope wire.Envelope, method, path string, status in
Path: path, Path: path,
Status: status, Status: status,
Outcome: outcome, 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. // rateLimiter is a sliding-window counter over the dangerous writes this node has performed.
+50
View File
@@ -1,9 +1,11 @@
package runtime package runtime
import ( import (
"bytes"
"context" "context"
"encoding/json" "encoding/json"
"errors" "errors"
"log/slog"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"net/url" "net/url"
@@ -544,3 +546,51 @@ func TestExecutorRefusesToStartWithoutAPolicyOrPort(t *testing.T) {
t.Fatal("port 0 was accepted") 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())
}
}