Logger middleware interface (#820)

* Modified logger format

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

* Logger middleware via struct

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

* Fixed time format

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

db/db.go

@@ -0,0 +1,16 @@
+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

@@ -0,0 +1,26 @@
+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"`
+		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"`
+		BytesOut     int64             `json:"bytes_out"`
+		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,18 +1,16 @@
 package middleware
 
 import (
-	"bytes"
 	"io"
 	"os"
 	"strconv"
 	"strings"
-	"sync"
 	"time"
 
+	"encoding/json"
+
 	"github.com/labstack/echo"
-	"github.com/labstack/gommon/color"
+	"github.com/labstack/echo/db"
-	isatty "github.com/mattn/go-isatty"
-	"github.com/valyala/fasttemplate"
 )
 
 type (
@@ -21,8 +19,9 @@ type (
 		// Skipper defines a function to skip middleware.
 		Skipper Skipper
 
-		// Log format which can be constructed using the following tags:
+		// Availabe logger fields:
 		//
+		// - time_unix
 		// - time_rfc3339
 		// - id (Request ID - Not implemented)
 		// - remote_ip
@@ -33,39 +32,51 @@ type (
 		// - referer
 		// - user_agent
 		// - status
-		// - latency (In microseconds)
+		// - latency (In nanosecond)
 		// - 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"`
 
-		// Output is a writer where logs are written.
+		// Optional. Default value DefaultLoggerConfig.Fields.
-		// Optional. Default value os.Stdout.
+		Fields []string `json:"fields"`
-		Output io.Writer
 
-		template *fasttemplate.Template
+		// Output is where logs are written.
-		color    *color.Color
+		// Optional. Default value &Stream{os.Stdout}.
-		pool     sync.Pool
+		Output db.Logger
+	}
+
+	// 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,
-		Format: `{"time":"${time_rfc3339}","remote_ip":"${remote_ip}","host":"${host}",` +
+		Fields: []string{
-			`"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` +
+			"time",
-			`"latency_human":"${latency_human}","bytes_in":${bytes_in},` +
+			"remote_ip",
-			`"bytes_out":${bytes_out}}` + "\n",
+			"host",
-		Output: os.Stdout,
+			"method",
-		color:  color.New(),
+			"uri",
+			"status",
+			"latency",
+			"latency_human",
+			"bytes_in",
+			"bytes_out",
+		},
+		Output: &Stream{os.Stdout},
 	}
 )
 
@@ -81,24 +92,13 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc {
 	if config.Skipper == nil {
 		config.Skipper = DefaultLoggerConfig.Skipper
 	}
-	if config.Format == "" {
+	if len(config.Fields) == 0 {
-		config.Format = DefaultLoggerConfig.Format
+		config.Fields = DefaultLoggerConfig.Fields
 	}
 	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) {
@@ -112,74 +112,66 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc {
 				c.Error(err)
 			}
 			stop := time.Now()
-			buf := config.pool.Get().(*bytes.Buffer)
+			request := &db.Request{
-			buf.Reset()
+				Header: make(map[string]string),
-			defer config.pool.Put(buf)
+				Query:  make(map[string]string),
+				Form:   make(map[string]string),
+			}
 
-			_, err = config.template.ExecuteFunc(buf, func(w io.Writer, tag string) (int, error) {
+			for _, f := range config.Fields {
-				switch tag {
+				switch f {
-				case "time_rfc3339":
+				case "time":
-					return w.Write([]byte(time.Now().Format(time.RFC3339)))
+					request.Time = time.Now()
 				case "remote_ip":
-					ra := c.RealIP()
+					request.RemoteIP = c.RealIP()
-					return w.Write([]byte(ra))
 				case "host":
-					return w.Write([]byte(req.Host))
+					request.Host = req.Host
 				case "uri":
-					return w.Write([]byte(req.RequestURI))
+					request.URI = req.RequestURI
 				case "method":
-					return w.Write([]byte(req.Method))
+					request.Method = req.Method
 				case "path":
 					p := req.URL.Path
 					if p == "" {
 						p = "/"
 					}
-					return w.Write([]byte(p))
+					request.Path = p
 				case "referer":
-					return w.Write([]byte(req.Referer()))
+					request.Referer = req.Referer()
 				case "user_agent":
-					return w.Write([]byte(req.UserAgent()))
+					request.UserAgent = req.UserAgent()
 				case "status":
-					n := res.Status
+					request.Status = 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 w.Write([]byte(s))
 				case "latency":
-					l := stop.Sub(start).Nanoseconds() / 1000
+					request.Latency = stop.Sub(start)
-					return w.Write([]byte(strconv.FormatInt(l, 10)))
 				case "latency_human":
-					return w.Write([]byte(stop.Sub(start).String()))
+					request.LatencyHuman = stop.Sub(start).String()
 				case "bytes_in":
-					b := req.Header.Get(echo.HeaderContentLength)
+					cl := req.Header.Get(echo.HeaderContentLength)
-					if b == "" {
+					if cl == "" {
-						b = "0"
+						cl = "0"
 					}
-					return w.Write([]byte(b))
+					l, _ := strconv.ParseInt(cl, 10, 64)
+					request.BytesIn = l
 				case "bytes_out":
-					return w.Write([]byte(strconv.FormatInt(res.Size, 10)))
+					request.BytesOut = res.Size
 				default:
 					switch {
-					case strings.HasPrefix(tag, "header:"):
+					case strings.HasPrefix(f, "header:"):
-						return buf.Write([]byte(c.Request().Header.Get(tag[7:])))
+						k := f[7:]
-					case strings.HasPrefix(tag, "query:"):
+						request.Header[k] = c.Request().Header.Get(k)
-						return buf.Write([]byte(c.QueryParam(tag[6:])))
+					case strings.HasPrefix(f, "query:"):
-					case strings.HasPrefix(tag, "form:"):
+						k := f[6:]
-						return buf.Write([]byte(c.FormValue(tag[5:])))
+						request.Query[k] = c.QueryParam(k)
+					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,44 +81,54 @@ func TestLoggerIPAddress(t *testing.T) {
 	assert.Contains(t, ip, buf.String())
 }
 
-func TestLoggerTemplate(t *testing.T) {
+func TestLoggerFields(t *testing.T) {
 	buf := new(bytes.Buffer)
 
 	e := echo.New()
 	e.Use(LoggerWithConfig(LoggerConfig{
-		Format: `{"time":"${time_rfc3339}","remote_ip":"${remote_ip}","host":"${host}","user_agent":"${user_agent}",` +
+		Fields: []string{
-			`"method":"${method}","uri":"${uri}","status":${status}, "latency":${latency},` +
+			"time",
-			`"latency_human":"${latency_human}","bytes_in":${bytes_in}, "path":"${path}", "referer":"${referer}",` +
+			"remote_ip",
-			`"bytes_out":${bytes_out},"ch":"${header:X-Custom-Header}",` +
+			"host",
-			`"us":"${query:username}", "cf":"${form:username}"}` + "\n",
+			"user_agent",
-		Output: buf,
+			"method",
+			"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, "Header Logged")
+		return c.String(http.StatusOK, "OK")
 	})
 
-	req, _ := http.NewRequest(echo.GET, "/?username=apagano-param&password=secret", nil)
+	req, _ := http.NewRequest(echo.GET, "/?user=joe", nil)
 	req.RequestURI = "/"
 	req.Header.Add(echo.HeaderXRealIP, "127.0.0.1")
 	req.Header.Add("Referer", "google.com")
-	req.Header.Add("User-Agent", "echo-tests-agent")
+	req.Header.Add("User-Agent", "test-agent")
 	req.Header.Add("X-Custom-Header", "AAA-CUSTOM-VALUE")
 	req.Form = url.Values{
-		"username": []string{"apagano-form"},
+		"user": []string{"jon"},
-		"password": []string{"secret-form"},
 	}
 
 	rec := httptest.NewRecorder()
 	e.ServeHTTP(rec, req)
 
 	cases := map[string]bool{
-		"apagano-param":    true,
+		"time":             true,
-		"apagano-form":     true,
+		"joe":              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,
@@ -126,7 +136,7 @@ func TestLoggerTemplate(t *testing.T) {
 		"\"status\":200":   true,
 		"\"bytes_in\":0":   true,
 		"google.com":       true,
-		"echo-tests-agent": true,
+		"test-agent":       true,
 	}
 
 	for token, present := range cases {