From f56450d8cecf162d101ee5794b290d9bb619a807 Mon Sep 17 00:00:00 2001 From: Vishal Rana Date: Thu, 12 Jan 2017 09:09:51 -0800 Subject: [PATCH] Fixed #821 Signed-off-by: Vishal Rana --- db/db.go | 16 --- db/model.go | 26 ----- middleware/logger.go | 160 +++++++++++++++------------ middleware/logger_test.go | 46 +++----- website/content/middleware/logger.md | 49 ++++---- 5 files changed, 129 insertions(+), 168 deletions(-) delete mode 100644 db/db.go delete mode 100644 db/model.go diff --git a/db/db.go b/db/db.go deleted file mode 100644 index 20abbb8c..00000000 --- a/db/db.go +++ /dev/null @@ -1,16 +0,0 @@ -package db - -type ( - // DB defines the interface for general database operations. - DB interface { - Logger - } - - // Logger defines the interface for logger middleware. - Logger interface { - Log(*Request) error - } - - // Mongo implements `DB` - Mongo struct{} -) diff --git a/db/model.go b/db/model.go deleted file mode 100644 index 635222e4..00000000 --- a/db/model.go +++ /dev/null @@ -1,26 +0,0 @@ -package db - -import "time" - -type ( - // Request defines the data to be logged by logger middleware. - Request struct { - // ID string `json:"id,omitempty"` (Request ID - Not implemented) - Time *time.Time `json:"time,omitempty"` // http://stackoverflow.com/questions/32643815/golang-json-omitempty-with-time-time-field - RemoteIP string `json:"remote_ip,omitempty"` - URI string `json:"uri,omitempty"` - Host string `json:"host,omitempty"` - Method string `json:"method,omitempty"` - Path string `json:"path,omitempty"` - Referer string `json:"referer,omitempty"` - UserAgent string `json:"user_agent,omitempty"` - Status int `json:"status,omitempty"` - Latency time.Duration `json:"latency,omitempty"` - LatencyHuman string `json:"latency_human,omitempty"` - BytesIn int64 `json:"bytes_in"` // Allow 0 value - BytesOut int64 `json:"bytes_out"` // As aboves - Header map[string]string `json:"header,omitempty"` - Form map[string]string `json:"form,omitempty"` - Query map[string]string `json:"query,omitempty"` - } -) diff --git a/middleware/logger.go b/middleware/logger.go index 80774cdc..e312d90f 100644 --- a/middleware/logger.go +++ b/middleware/logger.go @@ -1,16 +1,18 @@ package middleware import ( + "bytes" "io" "os" "strconv" "strings" + "sync" "time" - "encoding/json" - "github.com/labstack/echo" - "github.com/labstack/echo/db" + "github.com/labstack/gommon/color" + isatty "github.com/mattn/go-isatty" + "github.com/valyala/fasttemplate" ) type ( @@ -19,9 +21,12 @@ type ( // Skipper defines a function to skip middleware. Skipper Skipper - // Availabe logger fields: + // Tags to constructed the logger format. // - // - time + // - time_unix + // - time_unix_nano + // - time_rfc3339 + // - time_rfc3339_nano // - id (Request ID - Not implemented) // - remote_ip // - uri @@ -31,51 +36,39 @@ type ( // - referer // - user_agent // - status - // - latency (In nanosecond) + // - latency (In microseconds) // - latency_human (Human readable) // - bytes_in (Bytes received) // - bytes_out (Bytes sent) // - header: // - query: // - form: + // + // Example "${remote_ip} ${status}" + // + // Optional. Default value DefaultLoggerConfig.Format. + Format string `json:"format"` - // Optional. Default value DefaultLoggerConfig.Fields. - Fields []string `json:"fields"` + // Output is a writer where logs are written. + // Optional. Default value os.Stdout. + Output io.Writer - // Output is where logs are written. - // Optional. Default value &Stream{os.Stdout}. - Output db.Logger - } - - // Stream implements `db.Logger`. - Stream struct { - io.Writer + template *fasttemplate.Template + color *color.Color + pool sync.Pool } ) -// LogRequest encodes `db.Request` into a stream. -func (s *Stream) Log(r *db.Request) error { - enc := json.NewEncoder(s) - return enc.Encode(r) -} - var ( // DefaultLoggerConfig is the default Logger middleware config. DefaultLoggerConfig = LoggerConfig{ Skipper: defaultSkipper, - Fields: []string{ - "time", - "remote_ip", - "host", - "method", - "uri", - "status", - "latency", - "latency_human", - "bytes_in", - "bytes_out", - }, - Output: &Stream{os.Stdout}, + Format: `{"time":"${time_rfc3339_nano}","remote_ip":"${remote_ip}","host":"${host}",` + + `"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` + + `"latency_human":"${latency_human}","bytes_in":${bytes_in},` + + `"bytes_out":${bytes_out}}` + "\n", + Output: os.Stdout, + color: color.New(), } ) @@ -91,13 +84,24 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { if config.Skipper == nil { config.Skipper = DefaultLoggerConfig.Skipper } - if len(config.Fields) == 0 { - config.Fields = DefaultLoggerConfig.Fields + if config.Format == "" { + config.Format = DefaultLoggerConfig.Format } if config.Output == nil { config.Output = DefaultLoggerConfig.Output } + config.template = fasttemplate.New(config.Format, "${", "}") + config.color = color.New() + if w, ok := config.Output.(*os.File); !ok || !isatty.IsTerminal(w.Fd()) { + config.color.Disable() + } + config.pool = sync.Pool{ + New: func() interface{} { + return bytes.NewBuffer(make([]byte, 256)) + }, + } + return func(next echo.HandlerFunc) echo.HandlerFunc { return func(c echo.Context) (err error) { if config.Skipper(c) { @@ -111,67 +115,79 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { c.Error(err) } stop := time.Now() - request := &db.Request{ - Header: make(map[string]string), - Query: make(map[string]string), - Form: make(map[string]string), - } + buf := config.pool.Get().(*bytes.Buffer) + buf.Reset() + defer config.pool.Put(buf) - for _, f := range config.Fields { - switch f { - case "time": - t := time.Now() - request.Time = &t + _, err = config.template.ExecuteFunc(buf, func(w io.Writer, tag string) (int, error) { + switch tag { + case "time_unix": + return buf.WriteString(strconv.FormatInt(time.Now().Unix(), 10)) + case "time_unix_nano": + return buf.WriteString(strconv.FormatInt(time.Now().UnixNano(), 10)) + case "time_rfc3339": + return buf.WriteString(time.Now().Format(time.RFC3339)) + case "time_rfc3339_nano": + return buf.WriteString(time.Now().Format(time.RFC3339Nano)) case "remote_ip": - request.RemoteIP = c.RealIP() + return buf.WriteString(c.RealIP()) case "host": - request.Host = req.Host + return buf.WriteString(req.Host) case "uri": - request.URI = req.RequestURI + return buf.WriteString(req.RequestURI) case "method": - request.Method = req.Method + return buf.WriteString(req.Method) case "path": p := req.URL.Path if p == "" { p = "/" } - request.Path = p + return buf.WriteString(p) case "referer": - request.Referer = req.Referer() + return buf.WriteString(req.Referer()) case "user_agent": - request.UserAgent = req.UserAgent() + return buf.WriteString(req.UserAgent()) case "status": - request.Status = res.Status + n := res.Status + s := config.color.Green(n) + switch { + case n >= 500: + s = config.color.Red(n) + case n >= 400: + s = config.color.Yellow(n) + case n >= 300: + s = config.color.Cyan(n) + } + return buf.WriteString(s) case "latency": - request.Latency = stop.Sub(start) + l := stop.Sub(start).Nanoseconds() + return buf.WriteString(strconv.FormatInt(l, 10)) case "latency_human": - request.LatencyHuman = stop.Sub(start).String() + return buf.WriteString(stop.Sub(start).String()) case "bytes_in": cl := req.Header.Get(echo.HeaderContentLength) if cl == "" { cl = "0" } - l, _ := strconv.ParseInt(cl, 10, 64) - request.BytesIn = l + return buf.WriteString(cl) case "bytes_out": - request.BytesOut = res.Size + return buf.WriteString(strconv.FormatInt(res.Size, 10)) default: switch { - case strings.HasPrefix(f, "header:"): - k := f[7:] - request.Header[k] = c.Request().Header.Get(k) - case strings.HasPrefix(f, "query:"): - k := f[6:] - request.Query[k] = c.QueryParam(k) - case strings.HasPrefix(f, "form:"): - k := f[5:] - request.Form[k] = c.FormValue(k) + case strings.HasPrefix(tag, "header:"): + return buf.Write([]byte(c.Request().Header.Get(tag[7:]))) + case strings.HasPrefix(tag, "query:"): + return buf.Write([]byte(c.QueryParam(tag[6:]))) + case strings.HasPrefix(tag, "form:"): + return buf.Write([]byte(c.FormValue(tag[5:]))) } } + return 0, nil + }) + if err == nil { + config.Output.Write(buf.Bytes()) } - - // Write - return config.Output.Log(request) + return } } } diff --git a/middleware/logger_test.go b/middleware/logger_test.go index 877e18b5..5eacb51f 100644 --- a/middleware/logger_test.go +++ b/middleware/logger_test.go @@ -81,54 +81,44 @@ func TestLoggerIPAddress(t *testing.T) { assert.Contains(t, ip, buf.String()) } -func TestLoggerFields(t *testing.T) { +func TestLoggerTemplate(t *testing.T) { buf := new(bytes.Buffer) e := echo.New() e.Use(LoggerWithConfig(LoggerConfig{ - Fields: []string{ - "time", - "remote_ip", - "host", - "user_agent", - "method", - "uri", - "path", - "referer", - "status", - "latency", - "latency_human", - "bytes_in", - "bytes_out", - "header:X-Custom-Header", - "query:user", - "form:user", - }, - Output: &Stream{buf}, + Format: `{"time":"${time_rfc3339_nano}","remote_ip":"${remote_ip}","host":"${host}","user_agent":"${user_agent}",` + + `"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` + + `"latency_human":"${latency_human}","bytes_in":${bytes_in}, "path":"${path}", "referer":"${referer}",` + + `"bytes_out":${bytes_out},"ch":"${header:X-Custom-Header}",` + + `"us":"${query:username}", "cf":"${form:username}"}` + "\n", + Output: buf, })) e.GET("/", func(c echo.Context) error { - return c.String(http.StatusOK, "OK") + return c.String(http.StatusOK, "Header Logged") }) - req, _ := http.NewRequest(echo.GET, "/?user=joe", nil) + req, _ := http.NewRequest(echo.GET, "/?username=apagano-param&password=secret", nil) req.RequestURI = "/" req.Header.Add(echo.HeaderXRealIP, "127.0.0.1") req.Header.Add("Referer", "google.com") - req.Header.Add("User-Agent", "test-agent") + req.Header.Add("User-Agent", "echo-tests-agent") req.Header.Add("X-Custom-Header", "AAA-CUSTOM-VALUE") req.Form = url.Values{ - "user": []string{"jon"}, + "username": []string{"apagano-form"}, + "password": []string{"secret-form"}, } rec := httptest.NewRecorder() e.ServeHTTP(rec, req) cases := map[string]bool{ - "time": true, - "joe": true, - "jon": true, + "apagano-param": true, + "apagano-form": true, "AAA-CUSTOM-VALUE": true, + "BBB-CUSTOM-VALUE": false, + "secret-form": false, + "hexvalue": false, "GET": true, "127.0.0.1": true, "\"path\":\"/\"": true, @@ -136,7 +126,7 @@ func TestLoggerFields(t *testing.T) { "\"status\":200": true, "\"bytes_in\":0": true, "google.com": true, - "test-agent": true, + "echo-tests-agent": true, } for token, present := range cases { diff --git a/website/content/middleware/logger.md b/website/content/middleware/logger.md index 71a0a238..81ff003c 100644 --- a/website/content/middleware/logger.md +++ b/website/content/middleware/logger.md @@ -16,7 +16,7 @@ Logger middleware logs the information about each HTTP request. *Sample Output* ```js -{"time":"2017-01-11T19:58:51.322299983-08:00","remote_ip":"::1","uri":"/","host":"localhost:1323","method":"GET","status":200,"latency":10667,"latency_human":"10.667µs","bytes_in":0,"bytes_out":2} +{"time":"2017-01-12T08:58:07.372015644-08:00","remote_ip":"::1","host":"localhost:1323","method":"GET","uri":"/","status":200, "latency":14743,"latency_human":"14.743µs","bytes_in":0,"bytes_out":2} ``` ## Custom Configuration @@ -24,9 +24,8 @@ Logger middleware logs the information about each HTTP request. *Usage* ```go -e := echo.New() e.Use(middleware.LoggerWithConfig(middleware.LoggerConfig{ - Fields: []string{"method", "uri", "status"}, + Format: "method=${method}, uri=${uri}, status=${status}\n", })) ``` @@ -35,19 +34,23 @@ Example above uses a `Format` which logs request method and request URI. *Sample Output* ```sh -{"uri":"/","method":"GET","status":200,"bytes_in":0,"bytes_out":0} +method=GET, uri=/, status=200 ``` ## Configuration ```go +// LoggerConfig defines the config for Logger middleware. LoggerConfig struct { // Skipper defines a function to skip middleware. Skipper Skipper - // Availabe logger fields: + // Tags to constructed the logger format. // - // - time + // - time_unix + // - time_unix_nano + // - time_rfc3339 + // - time_rfc3339_nano // - id (Request ID - Not implemented) // - remote_ip // - uri @@ -57,20 +60,22 @@ LoggerConfig struct { // - referer // - user_agent // - status - // - latency (In nanosecond) + // - latency (In microseconds) // - latency_human (Human readable) // - bytes_in (Bytes received) // - bytes_out (Bytes sent) // - header: // - query: // - form: + // + // Example "${remote_ip} ${status}" + // + // Optional. Default value DefaultLoggerConfig.Format. + Format string `json:"format"` - // Optional. Default value DefaultLoggerConfig.Fields. - Fields []string `json:"fields"` - - // Output is where logs are written. - // Optional. Default value &Stream{os.Stdout}. - Output db.Logger + // Output is a writer where logs are written. + // Optional. Default value os.Stdout. + Output io.Writer } ``` @@ -79,18 +84,10 @@ LoggerConfig struct { ```go DefaultLoggerConfig = LoggerConfig{ Skipper: defaultSkipper, - Fields: []string{ - "time", - "remote_ip", - "host", - "method", - "uri", - "status", - "latency", - "latency_human", - "bytes_in", - "bytes_out", - }, - Output: &Stream{os.Stdout}, + Format: `{"time":"${time_rfc3339_nano}","remote_ip":"${remote_ip}","host":"${host}",` + + `"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` + + `"latency_human":"${latency_human}","bytes_in":${bytes_in},` + + `"bytes_out":${bytes_out}}` + "\n", + Output: os.Stdout } ```