Fixed #821

Signed-off-by: Vishal Rana <vr@labstack.com>

db/db.go

@@ -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{}
-)

db/model.go

@@ -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"`
-	}
-)

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:<name>
 		// - query:<name>
 		// - form:<name>
+		//
+		// Example "${remote_ip} ${status}"
+		//
+		// Optional. Default value DefaultLoggerConfig.Format.
+		Format string `json:"format"`
 
-		// Optional. Default value DefaultLoggerConfig.Fields.
+		// Output is a writer where logs are written.
-		Fields []string `json:"fields"`
+		// Optional. Default value os.Stdout.
+		Output io.Writer
 
-		// Output is where logs are written.
+		template *fasttemplate.Template
-		// Optional. Default value &Stream{os.Stdout}.
+		color    *color.Color
-		Output db.Logger
+		pool     sync.Pool
-	}
-
-	// Stream implements `db.Logger`.
-	Stream struct {
-		io.Writer
 	}
 )
 
-// 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{
+		Format: `{"time":"${time_rfc3339_nano}","remote_ip":"${remote_ip}","host":"${host}",` +
-			"time",
+			`"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` +
-			"remote_ip",
+			`"latency_human":"${latency_human}","bytes_in":${bytes_in},` +
-			"host",
+			`"bytes_out":${bytes_out}}` + "\n",
-			"method",
+		Output: os.Stdout,
-			"uri",
+		color:  color.New(),
-			"status",
-			"latency",
-			"latency_human",
-			"bytes_in",
-			"bytes_out",
-		},
-		Output: &Stream{os.Stdout},
 	}
 )
 
@@ -91,13 +84,24 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc {
 	if config.Skipper == nil {
 		config.Skipper = DefaultLoggerConfig.Skipper
 	}
-	if len(config.Fields) == 0 {
+	if config.Format == "" {
-		config.Fields = DefaultLoggerConfig.Fields
+		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{
+			buf := config.pool.Get().(*bytes.Buffer)
-				Header: make(map[string]string),
+			buf.Reset()
-				Query:  make(map[string]string),
+			defer config.pool.Put(buf)
-				Form:   make(map[string]string),
-			}
 
-			for _, f := range config.Fields {
+			_, err = config.template.ExecuteFunc(buf, func(w io.Writer, tag string) (int, error) {
-				switch f {
+				switch tag {
-				case "time":
+				case "time_unix":
-					t := time.Now()
+					return buf.WriteString(strconv.FormatInt(time.Now().Unix(), 10))
-					request.Time = &t
+				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)
+					return buf.WriteString(cl)
-					request.BytesIn = l
 				case "bytes_out":
-					request.BytesOut = res.Size
+					return buf.WriteString(strconv.FormatInt(res.Size, 10))
 				default:
 					switch {
-					case strings.HasPrefix(f, "header:"):
+					case strings.HasPrefix(tag, "header:"):
-						k := f[7:]
+						return buf.Write([]byte(c.Request().Header.Get(tag[7:])))
-						request.Header[k] = c.Request().Header.Get(k)
+					case strings.HasPrefix(tag, "query:"):
-					case strings.HasPrefix(f, "query:"):
+						return buf.Write([]byte(c.QueryParam(tag[6:])))
-						k := f[6:]
+					case strings.HasPrefix(tag, "form:"):
-						request.Query[k] = c.QueryParam(k)
+						return buf.Write([]byte(c.FormValue(tag[5:])))
-					case strings.HasPrefix(f, "form:"):
-						k := f[5:]
-						request.Form[k] = c.FormValue(k)
 					}
 				}
+				return 0, nil
+			})
+			if err == nil {
+				config.Output.Write(buf.Bytes())
 			}
-
+			return
-			// Write
-			return config.Output.Log(request)
 		}
 	}
 }

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{
+		Format: `{"time":"${time_rfc3339_nano}","remote_ip":"${remote_ip}","host":"${host}","user_agent":"${user_agent}",` +
-			"time",
+			`"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` +
-			"remote_ip",
+			`"latency_human":"${latency_human}","bytes_in":${bytes_in}, "path":"${path}", "referer":"${referer}",` +
-			"host",
+			`"bytes_out":${bytes_out},"ch":"${header:X-Custom-Header}",` +
-			"user_agent",
+			`"us":"${query:username}", "cf":"${form:username}"}` + "\n",
-			"method",
+		Output: buf,
-			"uri",
-			"path",
-			"referer",
-			"status",
-			"latency",
-			"latency_human",
-			"bytes_in",
-			"bytes_out",
-			"header:X-Custom-Header",
-			"query:user",
-			"form:user",
-		},
-		Output: &Stream{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,
+		"apagano-param":    true,
-		"joe":              true,
+		"apagano-form":     true,
-		"jon":              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 {

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:<name>
   // - query:<name>
   // - form:<name>
+  //
+  // Example "${remote_ip} ${status}"
+  //
+  // Optional. Default value DefaultLoggerConfig.Format.
+  Format string `json:"format"`
 
-  // Optional. Default value DefaultLoggerConfig.Fields.
+  // Output is a writer where logs are written.
-  Fields []string `json:"fields"`
+  // Optional. Default value os.Stdout.
-
+  Output io.Writer
-  // Output is where logs are written.
-  // Optional. Default value &Stream{os.Stdout}.
-  Output db.Logger
 }
 ```
 
@@ -79,18 +84,10 @@ LoggerConfig struct {
 ```go
 DefaultLoggerConfig = LoggerConfig{
   Skipper: defaultSkipper,
-  Fields: []string{
+  Format: `{"time":"${time_rfc3339_nano}","remote_ip":"${remote_ip}","host":"${host}",` +
-    "time",
+    `"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` +
-    "remote_ip",
+    `"latency_human":"${latency_human}","bytes_in":${bytes_in},` +
-    "host",
+    `"bytes_out":${bytes_out}}` + "\n",
-    "method",
+  Output: os.Stdout
-    "uri",
-    "status",
-    "latency",
-    "latency_human",
-    "bytes_in",
-    "bytes_out",
-  },
-  Output: &Stream{os.Stdout},
 }
 ```