From 9608a7ebc0f2e4a51e1410fc85738f778571522d Mon Sep 17 00:00:00 2001 From: chick Date: Thu, 17 Sep 2026 01:52:59 +0800 Subject: [PATCH] =?UTF-8?q?fix(agent):=20=E5=AE=A1=E8=AE=A1=E5=86=99?= =?UTF-8?q?=E5=85=A5=E5=A4=B1=E8=B4=A5=E4=B8=8D=E5=86=8D=E9=9D=99=E9=BB=98?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 审计日志是证据而不是控制手段：写失败不能让请求失败，否则磁盘写满会变成一次远程 拒绝服务——已经执行成功的指令会因为日志追加不上而开始报错，那是坏错了地方。 但它也不能消失。静默丢审计条目是那种"运维以为自己有记录、其实没有"的失败，而这份 日志的全部意义就是事后能回答"谁在什么时候要求了什么"。现在写失败会进 agent 自己的 日志，磁盘写满表现为一行反复出现，而不是一片空白。 顺带把 Close 之后的语义写清楚：Close 会丢掉 sink，此后的写入返回 nil——这是刻意的， 因为一个正在关闭的进程与在途请求赛跑时，为每一个恰好到达的请求报一次失败是噪声 而不是信息。这条差别在 agent 日志里看得见。 测试用真实失败路径（写一个已关闭的文件）而不是填满文件系统，并断言 exec.record 把 它报了出来。 Go 全包、Node 112 项、Swift 101 项通过。 --- internal/runtime/audit.go | 13 +++++++-- internal/runtime/executor.go | 17 +++++++++-- internal/runtime/runtime_test.go | 50 ++++++++++++++++++++++++++++++++ 3 files changed, 76 insertions(+), 4 deletions(-) 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()) + } +}