From 3f1eaf97246f458d536fb35e72bafc44b4796d9f Mon Sep 17 00:00:00 2001 From: Chris Lu Date: Wed, 13 May 2026 09:24:59 -0700 Subject: [PATCH] fix(s3/audit): emit audit log for successful GET/HEAD (#9467) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(s3/audit): emit audit log for successful GET/HEAD Successful GET/HEAD object requests never produced a fluent audit entry because those handlers write the response directly (streaming for GET, WriteHeader for HEAD) and never reach a PostLog call site. The wiki advertises GET as an audited verb, so the asymmetry surprises operators who rely on the log for read-access auditing. Move the safety net into the track() middleware: tag each request with an audit-tracking flag, let PostLog/PostAccessLog (delete path) mark it, and emit a single fallback entry after the handler returns when nothing fired. The recorder's status flows into the fallback so the audit row still reflects 200/206 vs 404 etc. No double logging for handlers that already emit (write helpers, error paths, bulk delete). Refs #9463 * fix(s3/audit): defensive nil checks on audit-tracking helpers Address PR review: guard against nil request and nil *atomic.Bool stored under the audit-tracking key. The conditions are unreachable today (the key is private and we only ever store new(atomic.Bool)), but the checks are free and keep the helpers safe if a future caller misbehaves. * test(s3/audit): track() audit fallback coverage + stale comment cleanup (#9469) test(s3/audit): cover track() fallback wiring + cleanup Adds two unit tests in weed/s3api/stats_test.go that exercise the audit-tracking flag set up by track(): one verifies the fallback path fires when a handler writes the response directly (the GET/HEAD object regression in #9463), the other verifies the flag is set when a handler emits PostLog itself so the fallback is skipped. To make the wiring observable without standing up fluent, PostLog now marks the audit flag before short-circuiting on a nil Logger; production behavior is unchanged (no logger, no posting) but the flag stays consistent. Also drops two stale comments in s3api_object_handlers.go that still referenced proxyToFiler — that helper was removed when GET/HEAD started streaming from volume servers directly. Stacks on #9467. --- weed/s3api/s3api_object_handlers.go | 2 - weed/s3api/s3api_object_handlers_delete.go | 2 + weed/s3api/s3err/audit_fluent.go | 57 ++++++++++++++++++++++ weed/s3api/s3err/audit_fluent_test.go | 15 ++++++ weed/s3api/stats.go | 8 +++ weed/s3api/stats_test.go | 51 +++++++++++++++++++ 6 files changed, 133 insertions(+), 2 deletions(-) create mode 100644 weed/s3api/stats_test.go diff --git a/weed/s3api/s3api_object_handlers.go b/weed/s3api/s3api_object_handlers.go index 8e5abaac2..87b71b017 100644 --- a/weed/s3api/s3api_object_handlers.go +++ b/weed/s3api/s3api_object_handlers.go @@ -772,7 +772,6 @@ func (s3a *S3ApiServer) GetObjectHandler(w http.ResponseWriter, r *http.Request) return } if objectEntryForSSE == nil { - // Not found, return error early to avoid another lookup in proxyToFiler s3err.WriteErrorResponse(w, r, s3err.ErrNoSuchKey) return } @@ -2274,7 +2273,6 @@ func (s3a *S3ApiServer) HeadObjectHandler(w http.ResponseWriter, r *http.Request return } if objectEntryForSSE == nil { - // Not found, return error early to avoid another lookup in proxyToFiler s3err.WriteErrorResponse(w, r, s3err.ErrNoSuchKey) return } diff --git a/weed/s3api/s3api_object_handlers_delete.go b/weed/s3api/s3api_object_handlers_delete.go index cc031d691..39742ed51 100644 --- a/weed/s3api/s3api_object_handlers_delete.go +++ b/weed/s3api/s3api_object_handlers_delete.go @@ -256,6 +256,7 @@ func (s3a *S3ApiServer) DeleteObjectHandler(w http.ResponseWriter, r *http.Reque if auditLog != nil { auditLog.Key = strings.TrimPrefix(object, "/") s3err.PostAccessLog(*auditLog) + s3err.MarkAuditLogged(r) } stats_collect.RecordBucketActiveTime(bucket) @@ -404,6 +405,7 @@ func (s3a *S3ApiServer) DeleteMultipleObjectsHandler(w http.ResponseWriter, r *h if auditLog != nil { auditLog.Key = object.Key s3err.PostAccessLog(*auditLog) + s3err.MarkAuditLogged(r) } } diff --git a/weed/s3api/s3err/audit_fluent.go b/weed/s3api/s3err/audit_fluent.go index 69a8ad54e..f037d8f59 100644 --- a/weed/s3api/s3err/audit_fluent.go +++ b/weed/s3api/s3err/audit_fluent.go @@ -1,12 +1,14 @@ package s3err import ( + "context" "encoding/json" "fmt" "net" "net/http" "os" "strings" + "sync/atomic" "time" "github.com/fluent/fluent-logger-golang/fluent" @@ -181,6 +183,14 @@ func GetAccessLog(r *http.Request, HTTPStatusCode int, s3errCode ErrorCode) *Acc } func PostLog(r *http.Request, HTTPStatusCode int, errorCode ErrorCode) { + if r == nil { + return + } + // Mark before the Logger nil-check so the middleware fallback in track() + // still sees that audit was handled by the caller in deployments that + // haven't configured fluent — keeps the flag behavior consistent and + // makes wiring testable without standing up a fluent server. + markAuditLogged(r) if Logger == nil { return } @@ -197,3 +207,50 @@ func PostAccessLog(log AccessLog) { glog.Warning("Error while posting log: ", err) } } + +// auditLogCtxKey identifies the per-request flag used to detect whether an +// audit entry has already been emitted, so middleware can supply a fallback +// log for handlers that don't call PostLog themselves without double-logging +// the ones that do. +type auditLogCtxKey struct{} + +// EnsureAuditTracking attaches an audit-tracking flag to the request context +// if one is not already present. Safe to call when no fluent logger is +// configured; the flag is harmless in that case. +func EnsureAuditTracking(r *http.Request) *http.Request { + if r == nil { + return nil + } + if v, ok := r.Context().Value(auditLogCtxKey{}).(*atomic.Bool); ok && v != nil { + return r + } + flag := new(atomic.Bool) + return r.WithContext(context.WithValue(r.Context(), auditLogCtxKey{}, flag)) +} + +// MarkAuditLogged signals that an audit entry has already been emitted for r. +// Callers that emit logs via paths other than PostLog (e.g. PostAccessLog in +// batch delete) should invoke this so the middleware fallback skips r. +func MarkAuditLogged(r *http.Request) { + markAuditLogged(r) +} + +func markAuditLogged(r *http.Request) { + if r == nil { + return + } + if v, ok := r.Context().Value(auditLogCtxKey{}).(*atomic.Bool); ok && v != nil { + v.Store(true) + } +} + +// AuditAlreadyLogged reports whether PostLog (or MarkAuditLogged) has run for r. +func AuditAlreadyLogged(r *http.Request) bool { + if r == nil { + return false + } + if v, ok := r.Context().Value(auditLogCtxKey{}).(*atomic.Bool); ok && v != nil { + return v.Load() + } + return false +} diff --git a/weed/s3api/s3err/audit_fluent_test.go b/weed/s3api/s3err/audit_fluent_test.go index 4d06ecdb4..710a705cc 100644 --- a/weed/s3api/s3err/audit_fluent_test.go +++ b/weed/s3api/s3err/audit_fluent_test.go @@ -85,3 +85,18 @@ func TestGetAccessLogRemoteIP(t *testing.T) { }) } } + +func TestAuditTrackingFlag(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "/bucket/object", nil) + assert.False(t, AuditAlreadyLogged(req), "untracked request reports not logged") + + tracked := EnsureAuditTracking(req) + assert.NotSame(t, req, tracked, "EnsureAuditTracking returns a new request when no flag is present") + assert.False(t, AuditAlreadyLogged(tracked), "tracked request starts unlogged") + + again := EnsureAuditTracking(tracked) + assert.Same(t, tracked, again, "EnsureAuditTracking is idempotent when flag already present") + + MarkAuditLogged(tracked) + assert.True(t, AuditAlreadyLogged(tracked), "flag flips after MarkAuditLogged") +} diff --git a/weed/s3api/stats.go b/weed/s3api/stats.go index 14c0ad150..00ff38dad 100644 --- a/weed/s3api/stats.go +++ b/weed/s3api/stats.go @@ -8,6 +8,7 @@ import ( "github.com/seaweedfs/seaweedfs/weed/util/version" "github.com/seaweedfs/seaweedfs/weed/s3api/s3_constants" + "github.com/seaweedfs/seaweedfs/weed/s3api/s3err" stats_collect "github.com/seaweedfs/seaweedfs/weed/stats" ) @@ -20,6 +21,10 @@ func track(f http.HandlerFunc, action string) http.HandlerFunc { bucket, _ := s3_constants.GetBucketAndObject(r) w.Header().Set("Server", "SeaweedFS "+version.VERSION) recorder := stats_collect.NewStatusResponseWriter(w) + // Attach an audit-tracking flag to the request so handlers that call + // PostLog directly mark it; we emit a fallback entry afterward for + // handlers (e.g. successful GET/HEAD object) that don't. + r = s3err.EnsureAuditTracking(r) start := time.Now() f(recorder, r) if recorder.Status == http.StatusForbidden { @@ -28,6 +33,9 @@ func track(f http.HandlerFunc, action string) http.HandlerFunc { stats_collect.S3RequestHistogram.WithLabelValues(action, bucket).Observe(time.Since(start).Seconds()) stats_collect.S3RequestCounter.WithLabelValues(action, strconv.Itoa(recorder.Status), bucket).Inc() stats_collect.RecordBucketActiveTime(bucket) + if !s3err.AuditAlreadyLogged(r) { + s3err.PostLog(r, recorder.Status, s3err.ErrNone) + } } } diff --git a/weed/s3api/stats_test.go b/weed/s3api/stats_test.go new file mode 100644 index 000000000..63d019b90 --- /dev/null +++ b/weed/s3api/stats_test.go @@ -0,0 +1,51 @@ +package s3api + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/seaweedfs/seaweedfs/weed/s3api/s3err" + "github.com/stretchr/testify/assert" +) + +// TestTrackAuditFallbackForDirectWriteHeader covers the regression behind +// issue #9463: handlers that bypass writeSuccessResponse helpers and call +// w.WriteHeader directly (GetObjectHandler stream path, HeadObjectHandler, +// GetBucketEncryption, GetObjectLockConfiguration, etc.) used to drop their +// audit entry. track() must mark the request as audited via a fallback +// PostLog after the handler returns. +func TestTrackAuditFallbackForDirectWriteHeader(t *testing.T) { + var captured *http.Request + handler := func(w http.ResponseWriter, r *http.Request) { + captured = r + w.WriteHeader(http.StatusOK) + } + wrapped := track(handler, "GET") + wrapped(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/bucket/object", nil)) + + if assert.NotNil(t, captured, "handler must have been invoked") { + assert.True(t, s3err.AuditAlreadyLogged(captured), + "track must emit fallback audit when handler writes response directly") + } +} + +// TestTrackAuditSkipsFallbackWhenHandlerEmits guards against double logging: +// handlers that already call PostLog (e.g. via writeSuccessResponseXML or +// WriteErrorResponse) flip the audit flag, and track must observe that and +// not re-emit. +func TestTrackAuditSkipsFallbackWhenHandlerEmits(t *testing.T) { + var captured *http.Request + handler := func(w http.ResponseWriter, r *http.Request) { + captured = r + s3err.PostLog(r, http.StatusOK, s3err.ErrNone) + w.WriteHeader(http.StatusOK) + } + wrapped := track(handler, "PUT") + wrapped(httptest.NewRecorder(), httptest.NewRequest(http.MethodPut, "/bucket/object", nil)) + + if assert.NotNil(t, captured) { + assert.True(t, s3err.AuditAlreadyLogged(captured), + "flag must be set after handler PostLog") + } +}