// SPDX-License-Identifier: MIT // SPDX-FileCopyrightText: © 2015 LabStack LLC and Echo contributors 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 actual RequestLoggerValues e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ LogError: true, LogStatus: true, LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { actual = 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, actual.Status) assert.EqualError(t, actual.Error, "code=406, message=nope") } func TestRequestLogger_HandleError(t *testing.T) { e := echo.New() var actual RequestLoggerValues e.Use(RequestLoggerWithConfig(RequestLoggerConfig{ timeNow: func() time.Time { return time.Unix(1631045377, 0).UTC() }, HandleError: true, LogError: true, LogStatus: true, LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error { actual = values return nil }, })) // to see if "HandleError" works we create custom error handler that uses its own status codes e.HTTPErrorHandler = func(err error, c echo.Context) { if c.Response().Committed { return } c.JSON(http.StatusTeapot, "custom error handler") } e.GET("/test", func(c echo.Context) error { return echo.NewHTTPError(http.StatusForbidden, "nope") }) req := httptest.NewRequest(http.MethodGet, "/test", nil) rec := httptest.NewRecorder() e.ServeHTTP(rec, req) assert.Equal(t, http.StatusTeapot, rec.Code) expect := RequestLoggerValues{ StartTime: time.Unix(1631045377, 0).UTC(), Status: http.StatusTeapot, Error: echo.NewHTTPError(http.StatusForbidden, "nope"), } assert.Equal(t, expect, actual) } 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 "committed" 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, time.Unix(1631045377, 0), expect.StartTime) 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) } }