fix(s3/audit): emit audit log for successful GET/HEAD (#9467)

* 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

@@ -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
 			}

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)
 			}
 		}
 

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
+}

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")
+}

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)
+		}
 	}
 }
 

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")
+	}
+}