From bf120ff4b9040629acf6ce537c24748fc83229cd Mon Sep 17 00:00:00 2001 From: Daniele Martinoli <86618610+dmartinol@users.noreply.github.com> Date: Wed, 2 Aug 2023 15:47:29 +0200 Subject: [PATCH 1/2] closes #58 --- logger.go | 60 +++++++++++++++++++++++++++++++++++++++------- logger_test.go | 64 ++++++++++++++++++++++++++++++++++++++++++++++++++ options.go | 20 ++++++++++++++++ 3 files changed, 135 insertions(+), 9 deletions(-) diff --git a/logger.go b/logger.go index c894c606..eaa180a4 100644 --- a/logger.go +++ b/logger.go @@ -1,10 +1,12 @@ package logger import ( + "bytes" "io" "net/http" "os" "regexp" + "strings" "time" "github.com/gin-gonic/gin" @@ -30,6 +32,22 @@ type config struct { clientErrorLevel zerolog.Level // the log level used for request with status code >= 500 serverErrorLevel zerolog.Level + // whether to log response body for request with status code >= 400 + logErrorResponseBody bool + // whether to log response body for request with status code < 400 + logResponseBody bool + // max len of response body message (whatever the status code) + maxResponseBodyLen int +} + +type bodyLogWriter struct { + gin.ResponseWriter + body *bytes.Buffer +} + +func (w bodyLogWriter) Write(b []byte) (int, error) { + w.body.Write(b) + return w.ResponseWriter.Write(b) } var isTerm bool = isatty.IsTerminal(os.Stdout.Fd()) @@ -37,10 +55,13 @@ var isTerm bool = isatty.IsTerminal(os.Stdout.Fd()) // SetLogger initializes the logging middleware. func SetLogger(opts ...Option) gin.HandlerFunc { cfg := &config{ - defaultLevel: zerolog.InfoLevel, - clientErrorLevel: zerolog.WarnLevel, - serverErrorLevel: zerolog.ErrorLevel, - output: gin.DefaultWriter, + defaultLevel: zerolog.InfoLevel, + clientErrorLevel: zerolog.WarnLevel, + serverErrorLevel: zerolog.ErrorLevel, + output: gin.DefaultWriter, + logErrorResponseBody: false, + logResponseBody: false, + maxResponseBodyLen: 50, } // Loop through each option @@ -80,6 +101,11 @@ func SetLogger(opts ...Option) gin.HandlerFunc { path = path + "?" + raw } + var blw *bodyLogWriter + if cfg.logErrorResponseBody || cfg.logResponseBody { + blw = &bodyLogWriter{body: bytes.NewBufferString(""), ResponseWriter: c.Writer} + c.Writer = blw + } c.Next() track := true @@ -100,10 +126,26 @@ func SetLogger(opts ...Option) gin.HandlerFunc { } latency := end.Sub(start) - l = l.With(). - Int("status", c.Writer.Status()). + statusCode := c.Writer.Status() + var response string + withResponse := (cfg.logErrorResponseBody && statusCode >= 400) || (cfg.logResponseBody && statusCode < 400) + if withResponse && blw.body != nil { + response = blw.body.String() + response = strings.TrimPrefix(response, "\"") + response = strings.TrimSuffix(response, "\"") + if len(response) > cfg.maxResponseBodyLen { + response = response[:cfg.maxResponseBodyLen] + "..." + } + } + + ctx := l.With(). + Int("status", statusCode). Str("method", c.Request.Method). - Str("path", c.Request.URL.Path). + Str("path", c.Request.URL.Path) + if withResponse { + ctx = ctx.Logger().With().Str("response", response) + } + l = ctx.Logger().With(). Str("ip", c.ClientIP()). Dur("latency", latency). Str("user_agent", c.Request.UserAgent()).Logger() @@ -114,12 +156,12 @@ func SetLogger(opts ...Option) gin.HandlerFunc { } switch { - case c.Writer.Status() >= http.StatusBadRequest && c.Writer.Status() < http.StatusInternalServerError: + case statusCode >= http.StatusBadRequest && statusCode < http.StatusInternalServerError: { l.WithLevel(cfg.clientErrorLevel). Msg(msg) } - case c.Writer.Status() >= http.StatusInternalServerError: + case statusCode >= http.StatusInternalServerError: { l.WithLevel(cfg.serverErrorLevel). Msg(msg) diff --git a/logger_test.go b/logger_test.go index a9cd7118..9d26a6b8 100644 --- a/logger_test.go +++ b/logger_test.go @@ -5,6 +5,7 @@ import ( "net/http" "net/http/httptest" "regexp" + "strings" "testing" "github.com/gin-gonic/gin" @@ -183,6 +184,69 @@ func TestLoggerParseLevel(t *testing.T) { } } +func TestLoggerWithErrorResponse(t *testing.T) { + buffer := new(bytes.Buffer) + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(SetLogger(WithWriter(buffer), WithLogErrorResponseBody(true))) + r.GET("/example", func(c *gin.Context) {}) + r.POST("/example", func(c *gin.Context) { + c.String(http.StatusBadRequest, "bad status") + }) + + performRequest(r, "GET", "/example?a=100") + assert.NotContains(t, buffer.String(), "response= ") + + buffer.Reset() + performRequest(r, "POST", "/example?a=100") + assert.Contains(t, buffer.String(), "response=") + assert.Contains(t, buffer.String(), "\"bad status\"") +} + +func TestLoggerWithResponse(t *testing.T) { + buffer := new(bytes.Buffer) + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(SetLogger(WithWriter(buffer), WithLogResponseBody(true))) + r.GET("/example", func(c *gin.Context) {}) + r.POST("/example", func(c *gin.Context) { + c.String(http.StatusOK, "example response") + }) + + performRequest(r, "GET", "/example?a=100") + assert.Contains(t, buffer.String(), "response=") + + buffer.Reset() + performRequest(r, "POST", "/example?a=100") + assert.Contains(t, buffer.String(), "response=") + assert.Contains(t, buffer.String(), "\"example response\"") +} + +func TestLoggerWithTruncatedResponse(t *testing.T) { + longMessage := strings.Repeat("X", 20) + truncatedMessage := strings.Repeat("X", 10) + "..." + buffer := new(bytes.Buffer) + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(SetLogger(WithWriter(buffer), WithLogErrorResponseBody(true), WithLogResponseBody(true), WithMaxResponseBodyLen(10))) + r.GET("/example", func(c *gin.Context) { + c.String(http.StatusBadRequest, longMessage) + }) + r.POST("/example", func(c *gin.Context) { + // c.String(http.StatusOK, strings.Repeat("X", 20)) + c.String(http.StatusOK, longMessage) + }) + + performRequest(r, "GET", "/example?a=100") + assert.Contains(t, buffer.String(), "response=") + assert.Contains(t, buffer.String(), truncatedMessage) + + buffer.Reset() + performRequest(r, "POST", "/example?a=100") + assert.Contains(t, buffer.String(), "response=") + assert.Contains(t, buffer.String(), truncatedMessage) +} + func BenchmarkLogger(b *testing.B) { gin.SetMode(gin.ReleaseMode) r := gin.New() diff --git a/options.go b/options.go index 362e4db4..a7cd8e0b 100644 --- a/options.go +++ b/options.go @@ -74,3 +74,23 @@ func WithServerErrorLevel(lvl zerolog.Level) Option { c.serverErrorLevel = lvl }) } + +func WithLogErrorResponseBody(logErrorResponseBody bool) Option { + return optionFunc(func(c *config) { + c.logErrorResponseBody = logErrorResponseBody + }) +} + +func WithLogResponseBody(logResponseBody bool) Option { + return optionFunc(func(c *config) { + c.logResponseBody = logResponseBody + }) +} + +func WithMaxResponseBodyLen(maxResponseBodyLen int) Option { + return optionFunc(func(c *config) { + if maxResponseBodyLen > 0 { + c.maxResponseBodyLen = maxResponseBodyLen + } + }) +} From 09c134c4b1d8fd8d3e82077cd431b7ba9b9f3d25 Mon Sep 17 00:00:00 2001 From: Daniele Martinoli <86618610+dmartinol@users.noreply.github.com> Date: Wed, 2 Aug 2023 17:25:53 +0200 Subject: [PATCH 2/2] allow to log request body --- logger.go | 24 ++++++++++++++++++++++ logger_test.go | 55 +++++++++++++++++++++++++++++++++++++++++++++++++- options.go | 14 +++++++++++++ 3 files changed, 92 insertions(+), 1 deletion(-) diff --git a/logger.go b/logger.go index eaa180a4..bef3ff9c 100644 --- a/logger.go +++ b/logger.go @@ -38,6 +38,10 @@ type config struct { logResponseBody bool // max len of response body message (whatever the status code) maxResponseBodyLen int + // whether to log request body + logRequestBody bool + // max len of log request body + maxRequestBodyLen int } type bodyLogWriter struct { @@ -62,6 +66,8 @@ func SetLogger(opts ...Option) gin.HandlerFunc { logErrorResponseBody: false, logResponseBody: false, maxResponseBodyLen: 50, + logRequestBody: false, + maxRequestBodyLen: 50, } // Loop through each option @@ -106,6 +112,21 @@ func SetLogger(opts ...Option) gin.HandlerFunc { blw = &bodyLogWriter{body: bytes.NewBufferString(""), ResponseWriter: c.Writer} c.Writer = blw } + + var requestBody string + if cfg.logRequestBody && c.Request.Body != nil { + body, err := io.ReadAll(c.Request.Body) + if err != nil { + body = []byte(err.Error()) + } + + requestBody = string(body) + if len(requestBody) > cfg.maxRequestBodyLen { + requestBody = requestBody[:cfg.maxRequestBodyLen] + "..." + } + c.Request.Body = io.NopCloser(bytes.NewReader(body)) + } + c.Next() track := true @@ -142,6 +163,9 @@ func SetLogger(opts ...Option) gin.HandlerFunc { Int("status", statusCode). Str("method", c.Request.Method). Str("path", c.Request.URL.Path) + if cfg.logRequestBody { + ctx = ctx.Logger().With().Str("body", requestBody) + } if withResponse { ctx = ctx.Logger().With().Str("response", response) } diff --git a/logger_test.go b/logger_test.go index 9d26a6b8..79bb4764 100644 --- a/logger_test.go +++ b/logger_test.go @@ -19,7 +19,16 @@ type header struct { } func performRequest(r http.Handler, method, path string, headers ...header) *httptest.ResponseRecorder { - req := httptest.NewRequest(method, path, nil) + return performRequestWithBody(r, method, path, "", headers...) +} + +func performRequestWithBody(r http.Handler, method, path string, body string, headers ...header) *httptest.ResponseRecorder { + var req *http.Request + if body != "" { + req = httptest.NewRequest(method, path, bytes.NewBuffer([]byte(body))) + } else { + req = httptest.NewRequest(method, path, nil) + } for _, h := range headers { req.Header.Add(h.Key, h.Value) } @@ -247,6 +256,50 @@ func TestLoggerWithTruncatedResponse(t *testing.T) { assert.Contains(t, buffer.String(), truncatedMessage) } +func TestLoggerWithRequest(t *testing.T) { + buffer := new(bytes.Buffer) + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(SetLogger(WithWriter(buffer), WithLogRequestBody(true))) + r.GET("/example", func(c *gin.Context) {}) + r.POST("/example", func(c *gin.Context) { + c.String(http.StatusOK, "example response") + }) + + performRequestWithBody(r, "GET", "/example?a=100", "GET body") + assert.Contains(t, buffer.String(), "body=\"GET body\"") + + buffer.Reset() + performRequestWithBody(r, "POST", "/example?a=100", "POST body") + assert.Contains(t, buffer.String(), "body=\"POST body\"") + + buffer.Reset() + longBody := strings.Repeat("X", 20) + performRequestWithBody(r, "POST", "/example?a=100", longBody) + assert.Contains(t, buffer.String(), "body="+longBody+" ") +} + +func TestLoggerWithTruncatedRequest(t *testing.T) { + longBody := strings.Repeat("X", 20) + truncatedBody := strings.Repeat("X", 10) + "..." + + buffer := new(bytes.Buffer) + gin.SetMode(gin.ReleaseMode) + r := gin.New() + r.Use(SetLogger(WithWriter(buffer), WithLogRequestBody(true), WithMaxRequestBodyLen(10))) + r.GET("/example", func(c *gin.Context) {}) + r.POST("/example", func(c *gin.Context) { + c.String(http.StatusOK, "example response") + }) + + performRequestWithBody(r, "GET", "/example?a=100", longBody) + assert.Contains(t, buffer.String(), "body="+truncatedBody+"") + + buffer.Reset() + performRequestWithBody(r, "POST", "/example?a=100", longBody) + assert.Contains(t, buffer.String(), "body="+truncatedBody+"") +} + func BenchmarkLogger(b *testing.B) { gin.SetMode(gin.ReleaseMode) r := gin.New() diff --git a/options.go b/options.go index a7cd8e0b..009bb37f 100644 --- a/options.go +++ b/options.go @@ -94,3 +94,17 @@ func WithMaxResponseBodyLen(maxResponseBodyLen int) Option { } }) } + +func WithLogRequestBody(logRequestBody bool) Option { + return optionFunc(func(c *config) { + c.logRequestBody = logRequestBody + }) +} + +func WithMaxRequestBodyLen(maxRequestBodyLen int) Option { + return optionFunc(func(c *config) { + if maxRequestBodyLen > 0 { + c.maxRequestBodyLen = maxRequestBodyLen + } + }) +}