From f76ccb25f1eee8684e545ec00f8f2934fec98f09 Mon Sep 17 00:00:00 2001 From: Sai Date: Wed, 12 Dec 2018 10:05:16 +0900 Subject: [PATCH] Add LoggerWithFormatter method (#1677) * Add LoggerWithFormatter * Add tests for LoggerWithFormatter & LoggerWithConfig * Add note for README * Add tests for DefaultLogFormatter * Add comment * Change DefaultLogFormatter to a private method --- README.md | 38 ++++++++++ logger.go | 116 +++++++++++++++++++++++------ logger_test.go | 194 ++++++++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 324 insertions(+), 24 deletions(-) diff --git a/README.md b/README.md index e7b92b2deb..c1f902a9f6 100644 --- a/README.md +++ b/README.md @@ -35,6 +35,7 @@ Gin is a web framework written in Go (Golang). It features a martini-like API wi - [Blank Gin without middleware by default](#blank-gin-without-middleware-by-default) - [Using middleware](#using-middleware) - [How to write log file](#how-to-write-log-file) + - [Custom Log Format](#custom-log-format) - [Model binding and validation](#model-binding-and-validation) - [Custom Validators](#custom-validators) - [Only Bind Query String](#only-bind-query-string) @@ -528,6 +529,43 @@ func main() { } ``` +### Custom Log Format +```go +func main() { + router := gin.New() + + // LoggerWithFormatter middleware will write the logs to gin.DefaultWriter + // By default gin.DefaultWriter = os.Stdout + router.Use(gin.LoggerWithFormatter(func(param gin.LogFormatterParams) string { + + // your custom format + return fmt.Sprintf("%s - [%s] \"%s %s %s %d %s \"%s\" %s\"\n", + param.ClientIP, + param.TimeStamp.Format(time.RFC1123), + param.Method, + param.Path, + param.Request.Proto, + param.StatusCode, + param.Latency, + param.Request.UserAgent(), + param.ErrorMessage, + ) + })) + router.Use(gin.Recovery()) + + router.GET("/ping", func(c *gin.Context) { + c.String(200, "pong") + }) + + router.Run(":8080") +} +``` + +**Sample Output** +``` +::1 - [Fri, 07 Dec 2018 17:04:38 JST] "GET /ping HTTP/1.1 200 122.767µs "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/71.0.3578.80 Safari/537.36" " +``` + ### Model binding and validation To bind a request body into a type, use model binding. We currently support binding of JSON, XML, YAML and standard form values (foo=bar&boo=baz). diff --git a/logger.go b/logger.go index 74dd2e6fa6..a64af69710 100644 --- a/logger.go +++ b/logger.go @@ -26,6 +26,56 @@ var ( disableColor = false ) +// LoggerConfig defines the config for Logger middleware. +type LoggerConfig struct { + // Optional. Default value is gin.defaultLogFormatter + Formatter LogFormatter + + // Output is a writer where logs are written. + // Optional. Default value is gin.DefaultWriter. + Output io.Writer + + // SkipPathes is a url path array which logs are not written. + // Optional. + SkipPathes []string +} + +// LogFormatter gives the signature of the formatter function passed to LoggerWithFormatter +type LogFormatter func(params LogFormatterParams) string + +// LogFormatterParams is the structure any formatter will be handed when time to log comes +type LogFormatterParams struct { + Request *http.Request + TimeStamp time.Time + StatusCode int + Latency time.Duration + ClientIP string + Method string + Path string + ErrorMessage string + IsTerm bool +} + +// defaultLogFormatter is the default log format function Logger middleware uses. +var defaultLogFormatter = func(param LogFormatterParams) string { + var statusColor, methodColor, resetColor string + if param.IsTerm { + statusColor = colorForStatus(param.StatusCode) + methodColor = colorForMethod(param.Method) + resetColor = reset + } + + return fmt.Sprintf("[GIN] %v |%s %3d %s| %13v | %15s |%s %-7s %s %s\n%s", + param.TimeStamp.Format("2006/01/02 - 15:04:05"), + statusColor, param.StatusCode, resetColor, + param.Latency, + param.ClientIP, + methodColor, param.Method, resetColor, + param.Path, + param.ErrorMessage, + ) +} + // DisableConsoleColor disables color output in the console. func DisableConsoleColor() { disableColor = true @@ -50,12 +100,39 @@ func ErrorLoggerT(typ ErrorType) HandlerFunc { // Logger instances a Logger middleware that will write the logs to gin.DefaultWriter. // By default gin.DefaultWriter = os.Stdout. func Logger() HandlerFunc { - return LoggerWithWriter(DefaultWriter) + return LoggerWithConfig(LoggerConfig{}) +} + +// LoggerWithFormatter instance a Logger middleware with the specified log format function. +func LoggerWithFormatter(f LogFormatter) HandlerFunc { + return LoggerWithConfig(LoggerConfig{ + Formatter: f, + }) } // LoggerWithWriter instance a Logger middleware with the specified writer buffer. // Example: os.Stdout, a file opened in write mode, a socket... func LoggerWithWriter(out io.Writer, notlogged ...string) HandlerFunc { + return LoggerWithConfig(LoggerConfig{ + Output: out, + SkipPathes: notlogged, + }) +} + +// LoggerWithConfig instance a Logger middleware with config. +func LoggerWithConfig(conf LoggerConfig) HandlerFunc { + formatter := conf.Formatter + if formatter == nil { + formatter = defaultLogFormatter + } + + out := conf.Output + if out == nil { + out = DefaultWriter + } + + notlogged := conf.SkipPathes + isTerm := true if w, ok := out.(*os.File); !ok || @@ -85,34 +162,27 @@ func LoggerWithWriter(out io.Writer, notlogged ...string) HandlerFunc { // Log only when path is not being skipped if _, ok := skip[path]; !ok { - // Stop timer - end := time.Now() - latency := end.Sub(start) - - clientIP := c.ClientIP() - method := c.Request.Method - statusCode := c.Writer.Status() - var statusColor, methodColor, resetColor string - if isTerm { - statusColor = colorForStatus(statusCode) - methodColor = colorForMethod(method) - resetColor = reset + param := LogFormatterParams{ + Request: c.Request, + IsTerm: isTerm, } - comment := c.Errors.ByType(ErrorTypePrivate).String() + + // Stop timer + param.TimeStamp = time.Now() + param.Latency = param.TimeStamp.Sub(start) + + param.ClientIP = c.ClientIP() + param.Method = c.Request.Method + param.StatusCode = c.Writer.Status() + param.ErrorMessage = c.Errors.ByType(ErrorTypePrivate).String() if raw != "" { path = path + "?" + raw } - fmt.Fprintf(out, "[GIN] %v |%s %3d %s| %13v | %15s |%s %-7s %s %s\n%s", - end.Format("2006/01/02 - 15:04:05"), - statusColor, statusCode, resetColor, - latency, - clientIP, - methodColor, method, resetColor, - path, - comment, - ) + param.Path = path + + fmt.Fprintf(out, formatter(param)) } } } diff --git a/logger_test.go b/logger_test.go index 6118cb0499..909ddd3908 100644 --- a/logger_test.go +++ b/logger_test.go @@ -7,8 +7,10 @@ package gin import ( "bytes" "errors" + "fmt" "net/http" "testing" + "time" "github.com/stretchr/testify/assert" ) @@ -79,7 +81,179 @@ func TestLogger(t *testing.T) { assert.Contains(t, buffer.String(), "404") assert.Contains(t, buffer.String(), "GET") assert.Contains(t, buffer.String(), "/notfound") +} + +func TestLoggerWithConfig(t *testing.T) { + buffer := new(bytes.Buffer) + router := New() + router.Use(LoggerWithConfig(LoggerConfig{Output: buffer})) + router.GET("/example", func(c *Context) {}) + router.POST("/example", func(c *Context) {}) + router.PUT("/example", func(c *Context) {}) + router.DELETE("/example", func(c *Context) {}) + router.PATCH("/example", func(c *Context) {}) + router.HEAD("/example", func(c *Context) {}) + router.OPTIONS("/example", func(c *Context) {}) + + performRequest(router, "GET", "/example?a=100") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "GET") + assert.Contains(t, buffer.String(), "/example") + assert.Contains(t, buffer.String(), "a=100") + + // I wrote these first (extending the above) but then realized they are more + // like integration tests because they test the whole logging process rather + // than individual functions. Im not sure where these should go. + buffer.Reset() + performRequest(router, "POST", "/example") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "POST") + assert.Contains(t, buffer.String(), "/example") + + buffer.Reset() + performRequest(router, "PUT", "/example") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "PUT") + assert.Contains(t, buffer.String(), "/example") + + buffer.Reset() + performRequest(router, "DELETE", "/example") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "DELETE") + assert.Contains(t, buffer.String(), "/example") + + buffer.Reset() + performRequest(router, "PATCH", "/example") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "PATCH") + assert.Contains(t, buffer.String(), "/example") + + buffer.Reset() + performRequest(router, "HEAD", "/example") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "HEAD") + assert.Contains(t, buffer.String(), "/example") + + buffer.Reset() + performRequest(router, "OPTIONS", "/example") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "OPTIONS") + assert.Contains(t, buffer.String(), "/example") + + buffer.Reset() + performRequest(router, "GET", "/notfound") + assert.Contains(t, buffer.String(), "404") + assert.Contains(t, buffer.String(), "GET") + assert.Contains(t, buffer.String(), "/notfound") +} + +func TestLoggerWithFormatter(t *testing.T) { + buffer := new(bytes.Buffer) + + d := DefaultWriter + DefaultWriter = buffer + defer func() { + DefaultWriter = d + }() + + router := New() + router.Use(LoggerWithFormatter(func(param LogFormatterParams) string { + return fmt.Sprintf("[FORMATTER TEST] %v | %3d | %13v | %15s | %-7s %s\n%s", + param.TimeStamp.Format("2006/01/02 - 15:04:05"), + param.StatusCode, + param.Latency, + param.ClientIP, + param.Method, + param.Path, + param.ErrorMessage, + ) + })) + router.GET("/example", func(c *Context) {}) + performRequest(router, "GET", "/example?a=100") + + // output test + assert.Contains(t, buffer.String(), "[FORMATTER TEST]") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "GET") + assert.Contains(t, buffer.String(), "/example") + assert.Contains(t, buffer.String(), "a=100") +} + +func TestLoggerWithConfigFormatting(t *testing.T) { + var gotParam LogFormatterParams + buffer := new(bytes.Buffer) + + router := New() + router.Use(LoggerWithConfig(LoggerConfig{ + Output: buffer, + Formatter: func(param LogFormatterParams) string { + // for assert test + gotParam = param + + return fmt.Sprintf("[FORMATTER TEST] %v | %3d | %13v | %15s | %-7s %s\n%s", + param.TimeStamp.Format("2006/01/02 - 15:04:05"), + param.StatusCode, + param.Latency, + param.ClientIP, + param.Method, + param.Path, + param.ErrorMessage, + ) + }, + })) + router.GET("/example", func(c *Context) { + // set dummy ClientIP + c.Request.Header.Set("X-Forwarded-For", "20.20.20.20") + }) + performRequest(router, "GET", "/example?a=100") + + // output test + assert.Contains(t, buffer.String(), "[FORMATTER TEST]") + assert.Contains(t, buffer.String(), "200") + assert.Contains(t, buffer.String(), "GET") + assert.Contains(t, buffer.String(), "/example") + assert.Contains(t, buffer.String(), "a=100") + + // LogFormatterParams test + assert.NotNil(t, gotParam.Request) + assert.NotEmpty(t, gotParam.TimeStamp) + assert.Equal(t, 200, gotParam.StatusCode) + assert.NotEmpty(t, gotParam.Latency) + assert.Equal(t, "20.20.20.20", gotParam.ClientIP) + assert.Equal(t, "GET", gotParam.Method) + assert.Equal(t, "/example?a=100", gotParam.Path) + assert.Empty(t, gotParam.ErrorMessage) + +} + +func TestDefaultLogFormatter(t *testing.T) { + timeStamp := time.Unix(1544173902, 0).UTC() + + termFalseParam := LogFormatterParams{ + TimeStamp: timeStamp, + StatusCode: 200, + Latency: time.Second * 5, + ClientIP: "20.20.20.20", + Method: "GET", + Path: "/", + ErrorMessage: "", + IsTerm: false, + } + + termTrueParam := LogFormatterParams{ + TimeStamp: timeStamp, + StatusCode: 200, + Latency: time.Second * 5, + ClientIP: "20.20.20.20", + Method: "GET", + Path: "/", + ErrorMessage: "", + IsTerm: true, + } + + assert.Equal(t, "[GIN] 2018/12/07 - 09:11:42 | 200 | 5s | 20.20.20.20 | GET /\n", defaultLogFormatter(termFalseParam)) + assert.Equal(t, "[GIN] 2018/12/07 - 09:11:42 |\x1b[97;42m 200 \x1b[0m| 5s | 20.20.20.20 |\x1b[97;44m GET \x1b[0m /\n", defaultLogFormatter(termTrueParam)) } func TestColorForMethod(t *testing.T) { @@ -127,7 +301,7 @@ func TestErrorLogger(t *testing.T) { assert.Equal(t, "hola!{\"error\":\"this is an error\"}", w.Body.String()) } -func TestSkippingPaths(t *testing.T) { +func TestLoggerWithWriterSkippingPaths(t *testing.T) { buffer := new(bytes.Buffer) router := New() router.Use(LoggerWithWriter(buffer, "/skipped")) @@ -142,6 +316,24 @@ func TestSkippingPaths(t *testing.T) { assert.Contains(t, buffer.String(), "") } +func TestLoggerWithConfigSkippingPaths(t *testing.T) { + buffer := new(bytes.Buffer) + router := New() + router.Use(LoggerWithConfig(LoggerConfig{ + Output: buffer, + SkipPathes: []string{"/skipped"}, + })) + router.GET("/logged", func(c *Context) {}) + router.GET("/skipped", func(c *Context) {}) + + performRequest(router, "GET", "/logged") + assert.Contains(t, buffer.String(), "200") + + buffer.Reset() + performRequest(router, "GET", "/skipped") + assert.Contains(t, buffer.String(), "") +} + func TestDisableConsoleColor(t *testing.T) { New() assert.False(t, disableColor)