s3tables, iceberg: log client refusals at V(1), not ERROR (#11896)

* s3tables, iceberg: log client refusals at V(1), not ERROR

Requests the S3 Tables and Iceberg REST APIs correctly refuse with a 4xx
(access denied, not authorized, no such namespace, already exists, not
empty, a commit conflict) were logged with glog.Errorf, so a client probing
for what it may do, or retrying an optimistic commit, filled the ERROR log
and hid real faults from anyone alerting on it.

- s3tables: HandleRequest wraps the ResponseWriter in a statusRecorder (with
  Unwrap for http.ResponseController) and logs a handler error by the status
  it answered: 4xx at V(1) as "<op> refused (<status>)", 5xx or no status at
  ERROR as before.
- s3tables: the "handleCreateNamespace called" trace moves from ERROR to V(3).
- iceberg: writeManagerError's mapping is split into classifyManagerError,
  shared with a new logManagerError that logs 4xx-mapped errors at V(1) and
  everything else at ERROR; used by CreateNamespace, CommitTable and
  CommitTransaction.
- storage: loading a remote-tier volume logged
  "readSuperBlock remote volume N: <nil>" at ERROR even when the read
  succeeded; it is now logged only when there is an error.

Tests: TestRequestRefusedWith4xxIsNotLoggedAsError, TestLogRequestErrorByStatus,
TestStatusRecorderKeepsTheFirstStatus, TestStatusRecorderUnwrapsForResponseController,
TestNoTraceLoggedAtErrorLevel (fails on master on the CreateNamespace trace),
TestLogManagerErrorRefusalsAreNotErrors, TestRemoteSuperBlockLogOnlyOnError.

* s3tables: do not log a malformed CreateNamespace body at ERROR

handleCreateNamespace logged a body it could not decode at ERROR before
answering 400; the dispatcher already logs that refusal once at V(1).

Also drop statusRecorder.Flush: it made the recorder an http.Flusher even
over a writer that cannot flush, so http.NewResponseController reported
success instead of ErrNotSupported. Unwrap already lets the controller
reach the wrapped writer.

* iceberg: require exactly one log line per classified manager error

The test accepted a refusal that produced no log, or both logs. Require
one V(1) refusal and no ERROR for a 4xx, and the reverse for a fault.

---------

Co-authored-by: Javier de la Torre <jatorre@lakehousebox.com>

weed/s3api/s3tables/handler.go

@@ -127,6 +127,10 @@ func (h *S3TablesHandler) HandleRequest(w http.ResponseWriter, r *http.Request,
 
 	glog.V(3).Infof("S3Tables: handling operation %s", operation)
 
+	// the status the handler answers decides how its error is logged (logRequestError)
+	sw := &statusRecorder{ResponseWriter: w}
+	w = sw
+
 	var err error
 	switch operation {
 	// Table Bucket operations
@@ -223,10 +227,51 @@ func (h *S3TablesHandler) HandleRequest(w http.ResponseWriter, r *http.Request,
 	}
 
 	if err != nil {
-		glog.Errorf("S3Tables: error handling %s: %v", operation, err)
+		logRequestError(operation, sw.status, err)
 	}
 }
 
+// A refusal the handler answered with a 4xx (access denied, not authorized,
+// not found, already exists, not empty) is the API working as intended, not a
+// server fault; it is logged at V(1). A 5xx, or an error returned without any
+// status written, stays at ERROR.
+var (
+	logClientRefusal = func(format string, args ...interface{}) { glog.V(1).Infof(format, args...) }
+	logServerError   = glog.Errorf
+)
+
+func logRequestError(operation string, status int, err error) {
+	if status >= 400 && status < 500 {
+		logClientRefusal("S3Tables: %s refused (%d): %v", operation, status, err)
+		return
+	}
+	logServerError("S3Tables: error handling %s: %v", operation, err)
+}
+
+// statusRecorder remembers the first status written through it.
+type statusRecorder struct {
+	http.ResponseWriter
+	status int
+}
+
+func (s *statusRecorder) WriteHeader(code int) {
+	if s.status == 0 {
+		s.status = code
+	}
+	s.ResponseWriter.WriteHeader(code)
+}
+
+func (s *statusRecorder) Write(b []byte) (int, error) {
+	if s.status == 0 {
+		s.status = http.StatusOK
+	}
+	return s.ResponseWriter.Write(b)
+}
+
+// Unwrap lets http.NewResponseController reach the underlying writer, so it
+// flushes (or reports ErrNotSupported) exactly as that writer does.
+func (s *statusRecorder) Unwrap() http.ResponseWriter { return s.ResponseWriter }
+
 // Principal/authorization helpers
 
 // getAccountID returns a stable caller identifier for ownership and permission checks.

weed/s3api/s3tables/handler_log_level_test.go

@@ -0,0 +1,123 @@
+package s3tables
+
+import (
+	"errors"
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/seaweedfs/seaweedfs/weed/glog"
+)
+
+// captureLogs swaps the two log sinks for recorders and restores them when the test ends.
+func captureLogs(t *testing.T) (refusals, serverErrors *[]string) {
+	t.Helper()
+	var r, s []string
+	oldR, oldS := logClientRefusal, logServerError
+	logClientRefusal = func(f string, a ...interface{}) { r = append(r, fmt.Sprintf(f, a...)) }
+	logServerError = func(f string, a ...interface{}) { s = append(s, fmt.Sprintf(f, a...)) }
+	t.Cleanup(func() { logClientRefusal, logServerError = oldR, oldS })
+	return &r, &s
+}
+
+// A refusal the API answers with a 4xx is not a server error.
+func TestRequestRefusedWith4xxIsNotLoggedAsError(t *testing.T) {
+	refusals, serverErrors := captureLogs(t)
+	h := NewS3TablesHandler()
+	req := httptest.NewRequest(http.MethodPost, "/", strings.NewReader("not json"))
+	req.Header.Set("X-Amz-Target", "S3Tables.ListNamespaces")
+	rec := httptest.NewRecorder()
+	h.HandleRequest(rec, req, nil)
+	if rec.Code < 400 || rec.Code >= 500 {
+		t.Fatalf("the probe request must be refused with a 4xx for this test to mean anything, got %d", rec.Code) // positive control
+	}
+	if len(*serverErrors) != 0 {
+		t.Fatalf("a %d refusal was logged at ERROR: %v", rec.Code, *serverErrors)
+	}
+	if len(*refusals) != 1 || !strings.Contains((*refusals)[0], "ListNamespaces refused") {
+		t.Fatalf("the refusal must still be logged once (at V(1)), got %v", *refusals)
+	}
+}
+
+func TestLogRequestErrorByStatus(t *testing.T) {
+	for _, c := range []struct {
+		status    int
+		wantError bool
+	}{{http.StatusForbidden, false}, {http.StatusNotFound, false}, {http.StatusConflict, false},
+		{http.StatusInternalServerError, true}, {http.StatusServiceUnavailable, true}, {0, true}} {
+		refusals, serverErrors := captureLogs(t)
+		logRequestError("Op", c.status, errors.New("boom"))
+		if gotError := len(*serverErrors) == 1 && len(*refusals) == 0; gotError != c.wantError {
+			t.Errorf("status %d: ERROR=%v, want %v (refusals %v, errors %v)", c.status, gotError, c.wantError, *refusals, *serverErrors)
+		}
+	}
+}
+
+func TestStatusRecorderKeepsTheFirstStatus(t *testing.T) {
+	rec := httptest.NewRecorder()
+	sw := &statusRecorder{ResponseWriter: rec}
+	_, _ = sw.Write([]byte("x"))
+	sw.WriteHeader(http.StatusInternalServerError)
+	if sw.status != http.StatusOK {
+		t.Fatalf("an implicit 200 by Write must win, got %d", sw.status)
+	}
+	sw2 := &statusRecorder{ResponseWriter: httptest.NewRecorder()}
+	sw2.WriteHeader(http.StatusForbidden)
+	if sw2.status != http.StatusForbidden {
+		t.Fatalf("got %d", sw2.status)
+	}
+}
+
+func TestStatusRecorderUnwrapsForResponseController(t *testing.T) {
+	sw := &statusRecorder{ResponseWriter: httptest.NewRecorder()}
+	if err := http.NewResponseController(sw).Flush(); err != nil {
+		t.Fatalf("ResponseController through the recorder: %v", err)
+	}
+	if sw.Unwrap() == nil {
+		t.Fatal("Unwrap must return the wrapped writer")
+	}
+}
+
+// A malformed CreateNamespace body is answered with a 400; neither the
+// dispatcher nor the handler itself may log it at ERROR.
+func TestMalformedCreateNamespaceIsNotLoggedAsError(t *testing.T) {
+	refusals, serverErrors := captureLogs(t)
+
+	before := glog.Stats.Error.Lines()
+	glog.Errorf("S3Tables test: positive control for the ERROR line counter")
+	if glog.Stats.Error.Lines() != before+1 {
+		t.Fatal("the ERROR line counter did not see a direct glog.Errorf") // positive control
+	}
+
+	h := NewS3TablesHandler()
+	req := httptest.NewRequest(http.MethodPost, "/", strings.NewReader("not json"))
+	req.Header.Set("X-Amz-Target", "S3Tables.CreateNamespace")
+	rec := httptest.NewRecorder()
+	before = glog.Stats.Error.Lines()
+	h.HandleRequest(rec, req, nil)
+	errorLines := glog.Stats.Error.Lines() - before
+	if rec.Code != http.StatusBadRequest {
+		t.Fatalf("a malformed body must be refused with 400, got %d", rec.Code)
+	}
+	if errorLines != 0 || len(*serverErrors) != 0 {
+		t.Fatalf("a 400 refusal was logged at ERROR: %d direct line(s), dispatcher %v", errorLines, *serverErrors)
+	}
+	if len(*refusals) != 1 || !strings.Contains((*refusals)[0], "CreateNamespace refused") {
+		t.Fatalf("the refusal must still be logged once (at V(1)), got %v", *refusals)
+	}
+}
+
+// The recorder must not claim to flush a writer that cannot.
+func TestStatusRecorderFlushFollowsTheWrappedWriter(t *testing.T) {
+	type plainWriter struct{ http.ResponseWriter }
+	sw := &statusRecorder{ResponseWriter: plainWriter{httptest.NewRecorder()}}
+	if err := http.NewResponseController(sw).Flush(); !errors.Is(err, http.ErrNotSupported) {
+		t.Fatalf("Flush through a recorder over a non-flushing writer: %v, want ErrNotSupported", err)
+	}
+	rec := httptest.NewRecorder()
+	if err := http.NewResponseController(&statusRecorder{ResponseWriter: rec}).Flush(); err != nil || !rec.Flushed {
+		t.Fatalf("Flush through a recorder over a flushing writer: err=%v flushed=%v", err, rec.Flushed) // positive control
+	}
+}

weed/s3api/s3tables/handler_namespace.go

@@ -36,10 +36,9 @@ func (h *S3TablesHandler) mayRepairOwnerlessBucket(r *http.Request) bool {
 
 // handleCreateNamespace creates a new namespace in a table bucket
 func (h *S3TablesHandler) handleCreateNamespace(w http.ResponseWriter, r *http.Request, filerClient FilerClient) error {
-	glog.Errorf("S3Tables: handleCreateNamespace called")
+	glog.V(3).Infof("S3Tables: handleCreateNamespace called")
 	var req CreateNamespaceRequest
 	if err := h.readRequestBody(r, &req); err != nil {
-		glog.Errorf("S3Tables: handleCreateNamespace failed to read request body: %v", err)
 		h.writeError(w, http.StatusBadRequest, ErrCodeInvalidRequest, err.Error())
 		return err
 	}

weed/s3api/s3tables/handler_no_trace_errorf_test.go

@@ -0,0 +1,39 @@
+package s3tables
+
+import (
+	"os"
+	"path/filepath"
+	"regexp"
+	"strings"
+	"testing"
+)
+
+// glog.Errorf with a constant message and no format verb is a trace, not an
+// error report: every CreateNamespace call logged
+// "S3Tables: handleCreateNamespace called" at ERROR.
+func TestNoTraceLoggedAtErrorLevel(t *testing.T) {
+	files, err := filepath.Glob("*.go")
+	if err != nil || len(files) == 0 {
+		t.Fatalf("no sources found (%v)", err) // positive control: the scan must see the package
+	}
+	re := regexp.MustCompile(`glog\.Errorf\("([^"]*)"\)`)
+	scanned := 0
+	for _, f := range files {
+		if strings.HasSuffix(f, "_test.go") {
+			continue
+		}
+		b, err := os.ReadFile(f)
+		if err != nil {
+			t.Fatal(err)
+		}
+		scanned++
+		for _, m := range re.FindAllStringSubmatch(string(b), -1) {
+			if !strings.Contains(m[1], "%") {
+				t.Errorf("%s: glog.Errorf(%q) logs a constant trace at ERROR; use glog.V(n).Infof", f, m[1])
+			}
+		}
+	}
+	if scanned < 5 {
+		t.Fatalf("scanned only %d source files", scanned)
+	}
+}