From 1b5b52f0f1ddbe078139fd4dfb126149decced15 Mon Sep 17 00:00:00 2001 From: zhangwenjian Date: Tue, 1 Sep 2026 11:35:45 +0800 Subject: [PATCH] =?UTF-8?q?perf=F0=9F=91=8C:=20only=20read=20the=20request?= =?UTF-8?q?=20body=20when=20the=20operation=20log=20will=20store=20it?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LoggerToFile is registered on the engine, so every POST, PUT, GET and DELETE had its body copied into memory - through a bytes.Buffer, a ReadAll and a string conversion - before any handler ran. The only consumer is operParam on the operation-log row, which is written when logger.enableddb is on, and that is off in the shipped configuration. There was no size limit either, and a file upload is a POST like any other: a 1MB request allocated 4.3MB here and a 16MB upload allocated about 67MB, to build a value nobody stored. The body is now read only when the operation log will use it, and at most 32KB of it. The handler still receives the whole request: it reads the copied part from memory and the rest from the connection, so what this holds is bounded however large the request is. 32KB also keeps the value inside the TEXT column it is written to. The bufio.Writer this replaces was never flushed. Nothing was truncated only because bytes.Buffer implements io.ReaderFrom, so io.Copy bypassed the buffer entirely - a different destination would have dropped the tail of every request body. --- common/middleware/logger.go | 66 +++++++++++--- common/middleware/logger_body_test.go | 124 ++++++++++++++++++++++++++ 2 files changed, 176 insertions(+), 14 deletions(-) create mode 100644 common/middleware/logger_body_test.go diff --git a/common/middleware/logger.go b/common/middleware/logger.go index 5a62425e..2a29d680 100644 --- a/common/middleware/logger.go +++ b/common/middleware/logger.go @@ -1,19 +1,19 @@ package middleware import ( - "bufio" "bytes" "encoding/json" + "errors" "go-admin/app/admin/service/dto" "go-admin/common" "io" - "io/ioutil" "net/http" "strings" "time" "github.com/gin-gonic/gin" "github.com/go-admin-team/go-admin-core/v2/jwtauth/user" + "github.com/go-admin-team/go-admin-core/v2/logger" "github.com/go-admin-team/go-admin-core/v2/sdk" "github.com/go-admin-team/go-admin-core/v2/sdk/api" "github.com/go-admin-team/go-admin-core/v2/sdk/config" @@ -28,19 +28,14 @@ func LoggerToFile() gin.HandlerFunc { // 开始时间 startTime := time.Now() // 处理请求 + // + // The body is only read when it has a destination. operParam below is + // the only consumer, and it is written when logger.enableddb is on - + // off in the shipped configuration, where reading the body was a copy + // of every request made and discarded. var body string - switch c.Request.Method { - case http.MethodPost, http.MethodPut, http.MethodGet, http.MethodDelete: - bf := bytes.NewBuffer(nil) - wt := bufio.NewWriter(bf) - _, err := io.Copy(wt, c.Request.Body) - if err != nil { - log.Warnf("copy body error, %s", err.Error()) - err = nil - } - rb, _ := ioutil.ReadAll(bf) - c.Request.Body = ioutil.NopCloser(bytes.NewBuffer(rb)) - body = string(rb) + if config.LoggerConfig.EnabledDB { + body = readOperParam(c, log) } c.Next() @@ -100,6 +95,49 @@ func LoggerToFile() gin.HandlerFunc { } } +// operParamLimit caps what is copied out of a request body for the operation +// log. A file upload is a POST like any other and reaches this middleware +// before any handler, so without a limit the whole upload is held in memory to +// write a log row - a 16MB upload allocated about 67MB. The limit also keeps +// the value inside the column, which is TEXT. +const operParamLimit = 32 << 10 + +// readOperParam copies the start of the request body for the operation log and +// leaves the request readable by the handler. +// +// The body is not buffered whole: the handler reads the part copied here from +// memory and the rest straight from the connection, so what this holds is +// bounded by operParamLimit however large the request is. +func readOperParam(c *gin.Context, log *logger.Helper) string { + switch c.Request.Method { + case http.MethodPost, http.MethodPut, http.MethodGet, http.MethodDelete: + default: + return "" + } + if c.Request.Body == nil { + return "" + } + + rest := c.Request.Body + head := make([]byte, operParamLimit) + n, err := io.ReadFull(rest, head) + if err != nil && !errors.Is(err, io.EOF) && !errors.Is(err, io.ErrUnexpectedEOF) { + log.Warnf("read body for the operation log: %s", err) + } + head = head[:n] + + c.Request.Body = readCloser{ + Reader: io.MultiReader(bytes.NewReader(head), rest), + Closer: rest, + } + return string(head) +} + +type readCloser struct { + io.Reader + io.Closer +} + // SetDBOperLog 写入操作日志表 fixme 该方法后续即将弃用 func SetDBOperLog(c *gin.Context, clientIP string, statusCode int, reqUri string, reqMethod string, latencyTime time.Duration, body string, result string, status int) { diff --git a/common/middleware/logger_body_test.go b/common/middleware/logger_body_test.go new file mode 100644 index 00000000..fb0ee4db --- /dev/null +++ b/common/middleware/logger_body_test.go @@ -0,0 +1,124 @@ +package middleware + +import ( + "bytes" + "io" + "net/http" + "net/http/httptest" + "runtime" + "strings" + "testing" + + "github.com/gin-gonic/gin" + "github.com/go-admin-team/go-admin-core/v2/sdk/config" +) + +// serveWithLogger runs one request through the logger middleware and returns +// what the handler saw, with logger.enableddb set as given. +func serveWithLogger(t testing.TB, enabledDB bool, method, body string) string { + t.Helper() + + prev := config.LoggerConfig.EnabledDB + config.LoggerConfig.EnabledDB = enabledDB + t.Cleanup(func() { config.LoggerConfig.EnabledDB = prev }) + + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(LoggerToFile()) + + var seen string + handler := func(c *gin.Context) { + b, err := io.ReadAll(c.Request.Body) + if err != nil { + t.Errorf("handler could not read the body: %v", err) + } + seen = string(b) + c.Status(http.StatusOK) + } + r.Handle(method, "/probe", handler) + + req := httptest.NewRequest(method, "/probe", strings.NewReader(body)) + req.Header.Set("Content-Type", "application/json") + r.ServeHTTP(httptest.NewRecorder(), req) + return seen +} + +// The middleware rewrites Request.Body so it can log the parameters. Whatever +// else it does, the handler has to receive the request the client sent - all +// of it, whether or not the operation log is on, and whether or not the body +// is longer than what gets logged. +func TestHandlerStillSeesTheWholeBody(t *testing.T) { + cases := []struct { + name string + enabledDB bool + body string + }{ + {"log off, short body", false, `{"username":"admin"}`}, + {"log on, short body", true, `{"username":"admin"}`}, + {"log off, empty body", false, ""}, + {"log on, empty body", true, ""}, + // Longer than operParamLimit: the logged copy is truncated, the body is not. + {"log on, body past the limit", true, strings.Repeat("x", operParamLimit+4096)}, + {"log off, body past the limit", false, strings.Repeat("y", operParamLimit+4096)}, + // Exactly at the boundary, where a fencepost error would show. + {"log on, body exactly at the limit", true, strings.Repeat("z", operParamLimit)}, + } + + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + for _, method := range []string{http.MethodPost, http.MethodPut, http.MethodDelete} { + if got := serveWithLogger(t, c.enabledDB, method, c.body); got != c.body { + t.Errorf("%s: handler saw %d bytes, the client sent %d", + method, len(got), len(c.body)) + } + } + }) + } +} + +// The body is read for one reason - operParam on the operation log row - and +// that row is only written when logger.enableddb is on. With it off, reading +// the body is a copy of every request made and thrown away, and a file upload +// is a POST like any other: 16MB of upload allocated about 67MB here. +// +// Allocation counts are deterministic across machines; wall-clock is not. +func TestBodyIsNotCopiedWhenTheOperationLogIsOff(t *testing.T) { + const size = 1 << 20 + body := strings.Repeat("x", size) + + prev := config.LoggerConfig.EnabledDB + config.LoggerConfig.EnabledDB = false + t.Cleanup(func() { config.LoggerConfig.EnabledDB = prev }) + + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(LoggerToFile()) + r.POST("/probe", func(c *gin.Context) { c.Status(http.StatusOK) }) + + payload := []byte(body) + run := func() { + req := httptest.NewRequest(http.MethodPost, "/probe", bytes.NewReader(payload)) + req.Header.Set("Content-Type", "application/json") + r.ServeHTTP(httptest.NewRecorder(), req) + } + + var before, after uint64 + before = heapAllocs() + run() + after = heapAllocs() + + // The handler never reads the body, so a request that does not copy it + // should allocate far less than the body's size. The old middleware + // allocated about four times the body. + if grew := after - before; grew > size/2 { + t.Errorf("a %d-byte request allocated %d bytes with the operation log off; "+ + "the body should not be read when nothing consumes it", size, grew) + } +} + +func heapAllocs() uint64 { + var m runtime.MemStats + runtime.GC() + runtime.ReadMemStats(&m) + return m.TotalAlloc +}