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