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] 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 c894c60..eaa180a 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 a9cd711..9d26a6b 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 362e4db..a7cd8e0 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 + } + }) +}