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
2018-12-12 10:05:16 +09:00
parent cce49582d6
commit f76ccb25f1
3 changed files with 324 additions and 24 deletions
--- 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).
--- 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))
 		}
 	}
 }
--- 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)