diff --git a/echo.go b/echo.go index a28fa0c1a..3292aa1a9 100644 --- a/echo.go +++ b/echo.go @@ -357,6 +357,11 @@ func (e *Echo) Routers() map[string]*Router { // DefaultHTTPErrorHandler is the default HTTP error handler. It sends a JSON response // with status code. +// +// NOTE: In case errors happens in middleware call-chain that is returning from handler (which did not return an error). +// When handler has already sent response (ala c.JSON()) and there is error in middleware that is returning from +// handler. Then the error that global error handler received will be ignored because we have already "commited" the +// response and status code header has been sent to the client. func (e *Echo) DefaultHTTPErrorHandler(err error, c Context) { if c.Response().Committed { diff --git a/go.mod b/go.mod index 9cd3529bd..d2c884abd 100644 --- a/go.mod +++ b/go.mod @@ -6,11 +6,12 @@ require ( github.com/golang-jwt/jwt v3.2.2+incompatible github.com/labstack/gommon v0.3.0 github.com/mattn/go-colorable v0.1.8 // indirect + github.com/mattn/go-isatty v0.0.14 // indirect github.com/stretchr/testify v1.4.0 github.com/valyala/fasttemplate v1.2.1 - golang.org/x/crypto v0.0.0-20210322153248-0c34fe9e7dc2 - golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4 - golang.org/x/sys v0.0.0-20210403161142-5e06dd20ab57 // indirect - golang.org/x/text v0.3.6 // indirect + golang.org/x/crypto v0.0.0-20210817164053-32db794688a5 + golang.org/x/net v0.0.0-20210907225631-ff17edfbf26d + golang.org/x/sys v0.0.0-20210908160347-a851e7ddeee0 // indirect + golang.org/x/text v0.3.7 // indirect golang.org/x/time v0.0.0-20201208040808-7e3f01d25324 ) diff --git a/go.sum b/go.sum index 027e96600..92dbd77db 100644 --- a/go.sum +++ b/go.sum @@ -9,8 +9,9 @@ github.com/mattn/go-colorable v0.1.8 h1:c1ghPdyEDarC70ftn0y+A/Ee++9zz8ljHG1b13eJ github.com/mattn/go-colorable v0.1.8/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc= github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= github.com/mattn/go-isatty v0.0.9/go.mod h1:YNRxwqDuOph6SZLI9vUUz6OYw3QyUt7WiY2yME+cCiQ= -github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY= github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU= +github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y= +github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= @@ -21,23 +22,26 @@ github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyC github.com/valyala/fasttemplate v1.0.1/go.mod h1:UQGH1tvbgY+Nz5t2n7tXsz52dQxojPUpymEIMZ47gx8= github.com/valyala/fasttemplate v1.2.1 h1:TVEnxayobAdVkhQfrfes2IzOB6o+z4roRkPF52WA1u4= github.com/valyala/fasttemplate v1.2.1/go.mod h1:KHLXt3tVN2HBp8eijSv/kGJopbvo7S+qRAEEKiv+SiQ= -golang.org/x/crypto v0.0.0-20210322153248-0c34fe9e7dc2 h1:It14KIkyBFYkHkwZ7k45minvA9aorojkyjGk9KJ5B/w= -golang.org/x/crypto v0.0.0-20210322153248-0c34fe9e7dc2/go.mod h1:T9bdIzuCu7OtxOm1hfPfRQxPLYneinmdGuTeoZ9dtd4= +golang.org/x/crypto v0.0.0-20210817164053-32db794688a5 h1:HWj/xjIHfjYU5nVXpTM0s39J9CbLn7Cc5a7IC5rwsMQ= +golang.org/x/crypto v0.0.0-20210817164053-32db794688a5/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= -golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4 h1:4nGaVu0QrbjT/AK2PRLuQfQuh6DJve+pELhqTdAj3x0= -golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM= +golang.org/x/net v0.0.0-20210907225631-ff17edfbf26d h1:kuk8nKPQ25KCDODLCDXt99tnTVeOyOM8HGvtJ0NzAvw= +golang.org/x/net v0.0.0-20210907225631-ff17edfbf26d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y= golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20190813064441-fde4db37ae7a/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200116001909-b77594299b42/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20200223170610-d5e6a3e2c0ae/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20210403161142-5e06dd20ab57 h1:F5Gozwx4I1xtr/sr/8CFbb57iKi3297KFs0QDbGN60A= -golang.org/x/sys v0.0.0-20210403161142-5e06dd20ab57/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20210908160347-a851e7ddeee0 h1:6xxeVXiyYpF8WCTnKKCbjnEdsrwjZYY8TOuk7xP0chg= +golang.org/x/sys v0.0.0-20210908160347-a851e7ddeee0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= -golang.org/x/text v0.3.6 h1:aRYxNxv6iGQlyVaZmk6ZgYEDa+Jg18DxebPSrd6bg1M= golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= +golang.org/x/text v0.3.7 h1:olpwvP2KacW1ZWvsR7uQhoyTYvKAupfQrRGBFM352Gk= +golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ= golang.org/x/time v0.0.0-20201208040808-7e3f01d25324 h1:Hir2P/De0WpUhtrKGGjvSb2YxUgyZ7EFOSLIcSSpiwE= golang.org/x/time v0.0.0-20201208040808-7e3f01d25324/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= diff --git a/middleware/logger_test.go b/middleware/logger_test.go index 4d4515b19..394f62712 100644 --- a/middleware/logger_test.go +++ b/middleware/logger_test.go @@ -171,3 +171,76 @@ func TestLoggerCustomTimestamp(t *testing.T) { _, err := time.Parse(customTimeFormat, loggedTime) assert.Error(t, err) } + +func BenchmarkLoggerWithConfig_withoutMapFields(b *testing.B) { + e := echo.New() + + buf := new(bytes.Buffer) + mw := LoggerWithConfig(LoggerConfig{ + Format: `{"time":"${time_rfc3339_nano}","id":"${id}","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}, "protocol":"${protocol}"}` + "\n", + Output: buf, + })(func(c echo.Context) error { + c.Request().Header.Set(echo.HeaderXRequestID, "123") + c.FormValue("to force parse form") + return c.String(http.StatusTeapot, "OK") + }) + + f := make(url.Values) + f.Set("csrf", "token") + f.Add("multiple", "1") + f.Add("multiple", "2") + req := httptest.NewRequest(http.MethodPost, "/test?lang=en&checked=1&checked=2", strings.NewReader(f.Encode())) + req.Header.Set("Referer", "https://echo.labstack.com/") + req.Header.Set("User-Agent", "curl/7.68.0") + req.Header.Add(echo.HeaderContentType, echo.MIMEApplicationForm) + + b.ReportAllocs() + b.ResetTimer() + + for i := 0; i < b.N; i++ { + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + mw(c) + buf.Reset() + } +} + +func BenchmarkLoggerWithConfig_withMapFields(b *testing.B) { + e := echo.New() + + buf := new(bytes.Buffer) + mw := LoggerWithConfig(LoggerConfig{ + Format: `{"time":"${time_rfc3339_nano}","id":"${id}","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}", "protocol":"${protocol}"` + + `"us":"${query:username}", "cf":"${form:csrf}", "Referer2":"${header:Referer}"}` + "\n", + Output: buf, + })(func(c echo.Context) error { + c.Request().Header.Set(echo.HeaderXRequestID, "123") + c.FormValue("to force parse form") + return c.String(http.StatusTeapot, "OK") + }) + + f := make(url.Values) + f.Set("csrf", "token") + f.Add("multiple", "1") + f.Add("multiple", "2") + req := httptest.NewRequest(http.MethodPost, "/test?lang=en&checked=1&checked=2", strings.NewReader(f.Encode())) + req.Header.Set("Referer", "https://echo.labstack.com/") + req.Header.Set("User-Agent", "curl/7.68.0") + req.Header.Add(echo.HeaderContentType, echo.MIMEApplicationForm) + + b.ReportAllocs() + b.ResetTimer() + + for i := 0; i < b.N; i++ { + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + mw(c) + buf.Reset() + } +} diff --git a/middleware/request_logger.go b/middleware/request_logger.go new file mode 100644 index 000000000..7829a1fd1 --- /dev/null +++ b/middleware/request_logger.go @@ -0,0 +1,310 @@ +package middleware + +import ( + "errors" + "github.com/labstack/echo/v4" + "net/http" + "time" +) + +// Example for `fmt.Printf` +// e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ +// LogStatus: true, +// LogURI: true, +// LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { +// fmt.Printf("REQUEST: uri: %v, status: %v\n", v.URI, v.Status) +// return nil +// }, +// })) +// +// Example for Zerolog (https://github.com/rs/zerolog) +// logger := zerolog.New(os.Stdout) +// e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ +// LogURI: true, +// LogStatus: true, +// LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { +// logger.Info(). +// Str("URI", v.URI). +// Int("status", v.Status). +// Msg("request") +// +// return nil +// }, +// })) +// +// Example for Zap (https://github.com/uber-go/zap) +// logger, _ := zap.NewProduction() +// e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ +// LogURI: true, +// LogStatus: true, +// LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { +// logger.Info("request", +// zap.String("URI", v.URI), +// zap.Int("status", v.Status), +// ) +// +// return nil +// }, +// })) +// +// Example for Logrus (https://github.com/sirupsen/logrus) +// log := logrus.New() +// e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ +// LogURI: true, +// LogStatus: true, +// LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error { +// log.WithFields(logrus.Fields{ +// "URI": values.URI, +// "status": values.Status, +// }).Info("request") +// +// return nil +// }, +// })) + +// RequestLoggerConfig is configuration for Request Logger middleware. +type RequestLoggerConfig struct { + // Skipper defines a function to skip middleware. + Skipper Skipper + + // BeforeNextFunc defines a function that is called before next middleware or handler is called in chain. + BeforeNextFunc func(c echo.Context) + // LogValuesFunc defines a function that is called with values extracted by logger from request/response. + // Mandatory. + LogValuesFunc func(c echo.Context, v RequestLoggerValues) error + + // LogLatency instructs logger to record duration it took to execute rest of the handler chain (next(c) call). + LogLatency bool + // LogProtocol instructs logger to extract request protocol (i.e. `HTTP/1.1` or `HTTP/2`) + LogProtocol bool + // LogRemoteIP instructs logger to extract request remote IP. See `echo.Context.RealIP()` for implementation details. + LogRemoteIP bool + // LogHost instructs logger to extract request host value (i.e. `example.com`) + LogHost bool + // LogMethod instructs logger to extract request method value (i.e. `GET` etc) + LogMethod bool + // LogURI instructs logger to extract request URI (i.e. `/list?lang=en&page=1`) + LogURI bool + // LogURIPath instructs logger to extract request URI path part (i.e. `/list`) + LogURIPath bool + // LogRoutePath instructs logger to extract route path part to which request was matched to (i.e. `/user/:id`) + LogRoutePath bool + // LogRequestID instructs logger to extract request ID from request `X-Request-ID` header or response if request did not have value. + LogRequestID bool + // LogReferer instructs logger to extract request referer values. + LogReferer bool + // LogUserAgent instructs logger to extract request user agent values. + LogUserAgent bool + // LogStatus instructs logger to extract response status code. If handler chain returns an echo.HTTPError, + // the status code is extracted from the echo.HTTPError returned + LogStatus bool + // LogError instructs logger to extract error returned from executed handler chain. + LogError bool + // LogContentLength instructs logger to extract content length header value. Note: this value could be different from + // actual request body size as it could be spoofed etc. + LogContentLength bool + // LogResponseSize instructs logger to extract response content length value. Note: when used with Gzip middleware + // this value may not be always correct. + LogResponseSize bool + // LogHeaders instructs logger to extract given list of headers from request. Note: request can contain more than + // one header with same value so slice of values is been logger for each given header. + // + // Note: header values are converted to canonical form with http.CanonicalHeaderKey as this how request parser converts header + // names to. For example, the canonical key for "accept-encoding" is "Accept-Encoding". + LogHeaders []string + // LogQueryParams instructs logger to extract given list of query parameters from request URI. Note: request can + // contain more than one query parameter with same name so slice of values is been logger for each given query param name. + LogQueryParams []string + // LogFormValues instructs logger to extract given list of form values from request body+URI. Note: request can + // contain more than one form value with same name so slice of values is been logger for each given form value name. + LogFormValues []string + + timeNow func() time.Time +} + +// RequestLoggerValues contains extracted values from logger. +type RequestLoggerValues struct { + // Latency is duration it took to execute rest of the handler chain (next(c) call). + Latency time.Duration + // Protocol is request protocol (i.e. `HTTP/1.1` or `HTTP/2`) + Protocol string + // RemoteIP is request remote IP. See `echo.Context.RealIP()` for implementation details. + RemoteIP string + // Host is request host value (i.e. `example.com`) + Host string + // Method is request method value (i.e. `GET` etc) + Method string + // URI is request URI (i.e. `/list?lang=en&page=1`) + URI string + // URIPath is request URI path part (i.e. `/list`) + URIPath string + // RoutePath is route path part to which request was matched to (i.e. `/user/:id`) + RoutePath string + // RequestID is request ID from request `X-Request-ID` header or response if request did not have value. + RequestID string + // Referer is request referer values. + Referer string + // UserAgent is request user agent values. + UserAgent string + // Status is response status code. Then handler returns an echo.HTTPError then code from there. + Status int + // Error is error returned from executed handler chain. + Error error + // ContentLength is content length header value. Note: this value could be different from actual request body size + // as it could be spoofed etc. + ContentLength string + // ResponseSize is response content length value. Note: when used with Gzip middleware this value may not be always correct. + ResponseSize int64 + // Headers are list of headers from request. Note: request can contain more than one header with same value so slice + // of values is been logger for each given header. + // Note: header values are converted to canonical form with http.CanonicalHeaderKey as this how request parser converts header + // names to. For example, the canonical key for "accept-encoding" is "Accept-Encoding". + Headers map[string][]string + // QueryParams are list of query parameters from request URI. Note: request can contain more than one query parameter + // with same name so slice of values is been logger for each given query param name. + QueryParams map[string][]string + // FormValues are list of form values from request body+URI. Note: request can contain more than one form value with + // same name so slice of values is been logger for each given form value name. + FormValues map[string][]string +} + +// RequestLoggerWithConfig returns a RequestLogger middleware with config. +func RequestLoggerWithConfig(config RequestLoggerConfig) echo.MiddlewareFunc { + mw, err := config.ToMiddleware() + if err != nil { + panic(err) + } + return mw +} + +// ToMiddleware converts RequestLoggerConfig into middleware or returns an error for invalid configuration. +func (config RequestLoggerConfig) ToMiddleware() (echo.MiddlewareFunc, error) { + if config.Skipper == nil { + config.Skipper = DefaultSkipper + } + now = time.Now + if config.timeNow != nil { + now = config.timeNow + } + + if config.LogValuesFunc == nil { + return nil, errors.New("missing LogValuesFunc callback function for request logger middleware") + } + + logHeaders := len(config.LogHeaders) > 0 + headers := append([]string(nil), config.LogHeaders...) + for i, v := range headers { + headers[i] = http.CanonicalHeaderKey(v) + } + + logQueryParams := len(config.LogQueryParams) > 0 + logFormValues := len(config.LogFormValues) > 0 + + return func(next echo.HandlerFunc) echo.HandlerFunc { + return func(c echo.Context) error { + if config.Skipper(c) { + return next(c) + } + + req := c.Request() + res := c.Response() + start := now() + + if config.BeforeNextFunc != nil { + config.BeforeNextFunc(c) + } + err := next(c) + + v := RequestLoggerValues{} + if config.LogLatency { + v.Latency = now().Sub(start) + } + if config.LogProtocol { + v.Protocol = req.Proto + } + if config.LogRemoteIP { + v.RemoteIP = c.RealIP() + } + if config.LogHost { + v.Host = req.Host + } + if config.LogMethod { + v.Method = req.Method + } + if config.LogURI { + v.URI = req.RequestURI + } + if config.LogURIPath { + p := req.URL.Path + if p == "" { + p = "/" + } + v.URIPath = p + } + if config.LogRoutePath { + v.RoutePath = c.Path() + } + if config.LogRequestID { + id := req.Header.Get(echo.HeaderXRequestID) + if id == "" { + id = res.Header().Get(echo.HeaderXRequestID) + } + v.RequestID = id + } + if config.LogReferer { + v.Referer = req.Referer() + } + if config.LogUserAgent { + v.UserAgent = req.UserAgent() + } + if config.LogStatus { + v.Status = res.Status + if err != nil { + if httpErr, ok := err.(*echo.HTTPError); ok { + v.Status = httpErr.Code + } + } + } + if config.LogError && err != nil { + v.Error = err + } + if config.LogContentLength { + v.ContentLength = req.Header.Get(echo.HeaderContentLength) + } + if config.LogResponseSize { + v.ResponseSize = res.Size + } + if logHeaders { + v.Headers = map[string][]string{} + for _, header := range headers { + if values, ok := req.Header[header]; ok { + v.Headers[header] = values + } + } + } + if logQueryParams { + queryParams := c.QueryParams() + v.QueryParams = map[string][]string{} + for _, param := range config.LogQueryParams { + if values, ok := queryParams[param]; ok { + v.QueryParams[param] = values + } + } + } + if logFormValues { + v.FormValues = map[string][]string{} + for _, formValue := range config.LogFormValues { + if values, ok := req.Form[formValue]; ok { + v.FormValues[formValue] = values + } + } + } + + if errOnLog := config.LogValuesFunc(c, v); errOnLog != nil { + return errOnLog + } + + return err + } + }, nil +} diff --git a/middleware/request_logger_test.go b/middleware/request_logger_test.go new file mode 100644 index 000000000..d5d9be08b --- /dev/null +++ b/middleware/request_logger_test.go @@ -0,0 +1,417 @@ +package middleware + +import ( + "github.com/labstack/echo/v4" + "github.com/stretchr/testify/assert" + "net/http" + "net/http/httptest" + "net/url" + "strconv" + "strings" + "testing" + "time" +) + +func TestRequestLoggerWithConfig(t *testing.T) { + e := echo.New() + + var expect RequestLoggerValues + e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ + LogRoutePath: true, + LogURI: true, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + expect = values + return nil + }, + })) + + e.GET("/test", func(c echo.Context) error { + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + rec := httptest.NewRecorder() + + e.ServeHTTP(rec, req) + + assert.Equal(t, http.StatusTeapot, rec.Code) + assert.Equal(t, "/test", expect.RoutePath) +} + +func TestRequestLoggerWithConfig_missingOnLogValuesPanics(t *testing.T) { + assert.Panics(t, func() { + RequestLoggerWithConfig(RequestLoggerConfig{ + LogValuesFunc: nil, + }) + }) +} + +func TestRequestLogger_skipper(t *testing.T) { + e := echo.New() + + loggerCalled := false + e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ + Skipper: func(c echo.Context) bool { + return true + }, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + loggerCalled = true + return nil + }, + })) + + e.GET("/test", func(c echo.Context) error { + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + rec := httptest.NewRecorder() + + e.ServeHTTP(rec, req) + + assert.Equal(t, http.StatusTeapot, rec.Code) + assert.False(t, loggerCalled) +} + +func TestRequestLogger_beforeNextFunc(t *testing.T) { + e := echo.New() + + var myLoggerInstance int + e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ + BeforeNextFunc: func(c echo.Context) { + c.Set("myLoggerInstance", 42) + }, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + myLoggerInstance = c.Get("myLoggerInstance").(int) + return nil + }, + })) + + e.GET("/test", func(c echo.Context) error { + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + rec := httptest.NewRecorder() + + e.ServeHTTP(rec, req) + + assert.Equal(t, http.StatusTeapot, rec.Code) + assert.Equal(t, 42, myLoggerInstance) +} + +func TestRequestLogger_logError(t *testing.T) { + e := echo.New() + + var expect RequestLoggerValues + e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ + LogError: true, + LogStatus: true, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + expect = values + return nil + }, + })) + + e.GET("/test", func(c echo.Context) error { + return echo.NewHTTPError(http.StatusNotAcceptable, "nope") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + rec := httptest.NewRecorder() + + e.ServeHTTP(rec, req) + + assert.Equal(t, http.StatusNotAcceptable, rec.Code) + assert.Equal(t, http.StatusNotAcceptable, expect.Status) + assert.EqualError(t, expect.Error, "code=406, message=nope") +} + +func TestRequestLogger_LogValuesFuncError(t *testing.T) { + e := echo.New() + + var expect RequestLoggerValues + e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ + LogError: true, + LogStatus: true, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + expect = values + return echo.NewHTTPError(http.StatusNotAcceptable, "LogValuesFuncError") + }, + })) + + e.GET("/test", func(c echo.Context) error { + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + rec := httptest.NewRecorder() + + e.ServeHTTP(rec, req) + + // NOTE: when global error handler received error returned from middleware the status has already + // been written to the client and response has been "commited" therefore global error handler does not do anything + // and error that bubbled up in middleware chain will not be reflected in response code. + assert.Equal(t, http.StatusTeapot, rec.Code) + assert.Equal(t, http.StatusTeapot, expect.Status) +} + +func TestRequestLogger_ID(t *testing.T) { + var testCases = []struct { + name string + whenFromRequest bool + expect string + }{ + { + name: "ok, ID is provided from request headers", + whenFromRequest: true, + expect: "123", + }, + { + name: "ok, ID is from response headers", + whenFromRequest: false, + expect: "321", + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + e := echo.New() + + var expect RequestLoggerValues + e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ + LogRequestID: true, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + expect = values + return nil + }, + })) + + e.GET("/test", func(c echo.Context) error { + c.Response().Header().Set(echo.HeaderXRequestID, "321") + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + if tc.whenFromRequest { + req.Header.Set(echo.HeaderXRequestID, "123") + } + rec := httptest.NewRecorder() + + e.ServeHTTP(rec, req) + + assert.Equal(t, http.StatusTeapot, rec.Code) + assert.Equal(t, tc.expect, expect.RequestID) + }) + } +} + +func TestRequestLogger_headerIsCaseInsensitive(t *testing.T) { + e := echo.New() + + var expect RequestLoggerValues + mw := RequestLoggerWithConfig(RequestLoggerConfig{ + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + expect = values + return nil + }, + LogHeaders: []string{"referer", "User-Agent"}, + })(func(c echo.Context) error { + c.Request().Header.Set(echo.HeaderXRequestID, "123") + c.FormValue("to force parse form") + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test?lang=en&checked=1&checked=2", nil) + req.Header.Set("referer", "https://echo.labstack.com/") + + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + + err := mw(c) + + assert.NoError(t, err) + assert.Len(t, expect.Headers, 1) + assert.Equal(t, []string{"https://echo.labstack.com/"}, expect.Headers["Referer"]) +} + +func TestRequestLogger_allFields(t *testing.T) { + e := echo.New() + + isFirstNowCall := true + var expect RequestLoggerValues + mw := RequestLoggerWithConfig(RequestLoggerConfig{ + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + expect = values + return nil + }, + LogLatency: true, + LogProtocol: true, + LogRemoteIP: true, + LogHost: true, + LogMethod: true, + LogURI: true, + LogURIPath: true, + LogRoutePath: true, + LogRequestID: true, + LogReferer: true, + LogUserAgent: true, + LogStatus: true, + LogError: true, + LogContentLength: true, + LogResponseSize: true, + LogHeaders: []string{"accept-encoding", "User-Agent"}, + LogQueryParams: []string{"lang", "checked"}, + LogFormValues: []string{"csrf", "multiple"}, + timeNow: func() time.Time { + if isFirstNowCall { + isFirstNowCall = false + return time.Unix(1631045377, 0) + } + return time.Unix(1631045377+10, 0) + }, + })(func(c echo.Context) error { + c.Request().Header.Set(echo.HeaderXRequestID, "123") + c.FormValue("to force parse form") + return c.String(http.StatusTeapot, "OK") + }) + + f := make(url.Values) + f.Set("csrf", "token") + f.Set("multiple", "1") + f.Add("multiple", "2") + reader := strings.NewReader(f.Encode()) + req := httptest.NewRequest(http.MethodPost, "/test?lang=en&checked=1&checked=2", reader) + req.Header.Set("Referer", "https://echo.labstack.com/") + req.Header.Set("User-Agent", "curl/7.68.0") + req.Header.Set(echo.HeaderContentLength, strconv.Itoa(int(reader.Size()))) + req.Header.Set(echo.HeaderContentType, echo.MIMEApplicationForm) + req.Header.Set(echo.HeaderXRealIP, "8.8.8.8") + + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + + c.SetPath("/test*") + + err := mw(c) + + assert.NoError(t, err) + assert.Equal(t, 10*time.Second, expect.Latency) + assert.Equal(t, "HTTP/1.1", expect.Protocol) + assert.Equal(t, "8.8.8.8", expect.RemoteIP) + assert.Equal(t, "example.com", expect.Host) + assert.Equal(t, http.MethodPost, expect.Method) + assert.Equal(t, "/test?lang=en&checked=1&checked=2", expect.URI) + assert.Equal(t, "/test", expect.URIPath) + assert.Equal(t, "/test*", expect.RoutePath) + assert.Equal(t, "123", expect.RequestID) + assert.Equal(t, "https://echo.labstack.com/", expect.Referer) + assert.Equal(t, "curl/7.68.0", expect.UserAgent) + assert.Equal(t, 418, expect.Status) + assert.Equal(t, nil, expect.Error) + assert.Equal(t, "32", expect.ContentLength) + assert.Equal(t, int64(2), expect.ResponseSize) + + assert.Len(t, expect.Headers, 1) + assert.Equal(t, []string{"curl/7.68.0"}, expect.Headers["User-Agent"]) + + assert.Len(t, expect.QueryParams, 2) + assert.Equal(t, []string{"en"}, expect.QueryParams["lang"]) + assert.Equal(t, []string{"1", "2"}, expect.QueryParams["checked"]) + + assert.Len(t, expect.FormValues, 2) + assert.Equal(t, []string{"token"}, expect.FormValues["csrf"]) + assert.Equal(t, []string{"1", "2"}, expect.FormValues["multiple"]) +} + +func BenchmarkRequestLogger_withoutMapFields(b *testing.B) { + e := echo.New() + + mw := RequestLoggerWithConfig(RequestLoggerConfig{ + Skipper: nil, + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + return nil + }, + LogLatency: true, + LogProtocol: true, + LogRemoteIP: true, + LogHost: true, + LogMethod: true, + LogURI: true, + LogURIPath: true, + LogRoutePath: true, + LogRequestID: true, + LogReferer: true, + LogUserAgent: true, + LogStatus: true, + LogError: true, + LogContentLength: true, + LogResponseSize: true, + })(func(c echo.Context) error { + c.Request().Header.Set(echo.HeaderXRequestID, "123") + return c.String(http.StatusTeapot, "OK") + }) + + req := httptest.NewRequest(http.MethodGet, "/test?lang=en", nil) + req.Header.Set("Referer", "https://echo.labstack.com/") + req.Header.Set("User-Agent", "curl/7.68.0") + + b.ReportAllocs() + b.ResetTimer() + + for i := 0; i < b.N; i++ { + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + mw(c) + } +} + +func BenchmarkRequestLogger_withMapFields(b *testing.B) { + e := echo.New() + + mw := RequestLoggerWithConfig(RequestLoggerConfig{ + LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { + return nil + }, + LogLatency: true, + LogProtocol: true, + LogRemoteIP: true, + LogHost: true, + LogMethod: true, + LogURI: true, + LogURIPath: true, + LogRoutePath: true, + LogRequestID: true, + LogReferer: true, + LogUserAgent: true, + LogStatus: true, + LogError: true, + LogContentLength: true, + LogResponseSize: true, + LogHeaders: []string{"accept-encoding", "User-Agent"}, + LogQueryParams: []string{"lang", "checked"}, + LogFormValues: []string{"csrf", "multiple"}, + })(func(c echo.Context) error { + c.Request().Header.Set(echo.HeaderXRequestID, "123") + c.FormValue("to force parse form") + return c.String(http.StatusTeapot, "OK") + }) + + f := make(url.Values) + f.Set("csrf", "token") + f.Add("multiple", "1") + f.Add("multiple", "2") + req := httptest.NewRequest(http.MethodPost, "/test?lang=en&checked=1&checked=2", strings.NewReader(f.Encode())) + req.Header.Set("Referer", "https://echo.labstack.com/") + req.Header.Set("User-Agent", "curl/7.68.0") + req.Header.Add(echo.HeaderContentType, echo.MIMEApplicationForm) + + b.ReportAllocs() + b.ResetTimer() + + for i := 0; i < b.N; i++ { + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + mw(c) + } +}