Additional configuration options for RequestLogger and Logger middleware (#2341)

aldas · web-flow · commit 8d4ac4c90769 · 2022-11-30T15:47:23.000+02:00
* Add `middleware.RequestLoggerConfig.HandleError` configuration option to handle error within middleware with global error handler thus setting response status code decided by error handler and not derived from error itself.
* Add `middleware.LoggerConfig.CustomTagFunc` so Logger middleware can add custom text to logged row.
diff --git a/context.go b/context.go
@@ -169,7 +169,11 @@ type (
 		// Redirect redirects the request to a provided URL with status code.
 		Redirect(code int, url string) error
 
-		// Error invokes the registered HTTP error handler. Generally used by middleware.
+		// Error invokes the registered global HTTP error handler. Generally used by middleware.
+		// A side-effect of calling global error handler is that now Response has been committed (sent to the client) and
+		// middlewares up in chain can not change Response status code or Response body anymore.
+		//
+		// Avoid using this method in handlers as no middleware will be able to effectively handle errors after that.
 		Error(err error)
 
 		// Handler returns the matched handler by router.
diff --git a/echo.go b/echo.go
@@ -116,7 +116,7 @@ type (
 	HandlerFunc func(c Context) error
 
 	// HTTPErrorHandler is a centralized HTTP error handler.
-	HTTPErrorHandler func(error, Context)
+	HTTPErrorHandler func(err error, c Context)
 
 	// Validator is the interface that wraps the Validate function.
 	Validator interface {
diff --git a/middleware/logger.go b/middleware/logger.go
@@ -47,6 +47,7 @@ type (
 		// - header:<NAME>
 		// - query:<NAME>
 		// - form:<NAME>
+		// - custom (see CustomTagFunc field)
 		//
 		// Example "${remote_ip} ${status}"
 		//
@@ -56,6 +57,11 @@ type (
 		// Optional. Default value DefaultLoggerConfig.CustomTimeFormat.
 		CustomTimeFormat string `yaml:"custom_time_format"`
 
+		// CustomTagFunc is function called for `${custom}` tag to output user implemented text by writing it to buf.
+		// Make sure that outputted text creates valid JSON string with other logged tags.
+		// Optional.
+		CustomTagFunc func(c echo.Context, buf *bytes.Buffer) (int, error)
+
 		// Output is a writer where logs in JSON format are written.
 		// Optional. Default value os.Stdout.
 		Output io.Writer
@@ -126,6 +132,11 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc {
 
 			if _, err = config.template.ExecuteFunc(buf, func(w io.Writer, tag string) (int, error) {
 				switch tag {
+				case "custom":
+					if config.CustomTagFunc == nil {
+						return 0, nil
+					}
+					return config.CustomTagFunc(c, buf)
 				case "time_unix":
 					return buf.WriteString(strconv.FormatInt(time.Now().Unix(), 10))
 				case "time_unix_milli":
diff --git a/middleware/logger_test.go b/middleware/logger_test.go
@@ -173,6 +173,28 @@ func TestLoggerCustomTimestamp(t *testing.T) {
 	assert.Error(t, err)
 }
 
+func TestLoggerCustomTagFunc(t *testing.T) {
+	e := echo.New()
+	buf := new(bytes.Buffer)
+	e.Use(LoggerWithConfig(LoggerConfig{
+		Format: `{"method":"${method}",${custom}}` + "\n",
+		CustomTagFunc: func(c echo.Context, buf *bytes.Buffer) (int, error) {
+			return buf.WriteString(`"tag":"my-value"`)
+		},
+		Output: buf,
+	}))
+
+	e.GET("/", func(c echo.Context) error {
+		return c.String(http.StatusOK, "custom time stamp test")
+	})
+
+	req := httptest.NewRequest(http.MethodGet, "/", nil)
+	rec := httptest.NewRecorder()
+	e.ServeHTTP(rec, req)
+
+	assert.Equal(t, `{"method":"GET","tag":"my-value"}`+"\n", buf.String())
+}
+
 func BenchmarkLoggerWithConfig_withoutMapFields(b *testing.B) {
 	e := echo.New()
 
diff --git a/middleware/request_logger.go b/middleware/request_logger.go
@@ -10,55 +10,88 @@ import (
 
 // Example for `fmt.Printf`
 // 	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
-//		LogStatus: true,
-//		LogURI:    true,
+//		LogStatus:   true,
+//		LogURI:      true,
+//		LogError:    true,
+//		HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code
 //		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
-//			fmt.Printf("REQUEST: uri: %v, status: %v\n", v.URI, v.Status)
+//			if v.Error == nil {
+//				fmt.Printf("REQUEST: uri: %v, status: %v\n", v.URI, v.Status)
+//			} else {
+//				fmt.Printf("REQUEST_ERROR: uri: %v, status: %v, err: %v\n", v.URI, v.Status, v.Error)
+//			}
 //			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,
+//		LogURI:      true,
+//		LogStatus:   true,
+//		LogError:    true,
+//		HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code
 //		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
-//			logger.Info().
-//				Str("URI", v.URI).
-//				Int("status", v.Status).
-//				Msg("request")
-//
+//			if v.Error == nil {
+//				logger.Info().
+//					Str("URI", v.URI).
+//					Int("status", v.Status).
+//					Msg("request")
+//			} else {
+//				logger.Error().
+//					Err(v.Error).
+//					Str("URI", v.URI).
+//					Int("status", v.Status).
+//					Msg("request error")
+//			}
 //			return nil
 //		},
 //	}))
 //
 // Example for Zap (https://github.com/uber-go/zap)
 // 	logger, _ := zap.NewProduction()
 //	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
-//		LogURI:    true,
-//		LogStatus: true,
+//		LogURI:      true,
+//		LogStatus:   true,
+//		LogError:    true,
+//		HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code
 //		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
-//			logger.Info("request",
-//				zap.String("URI", v.URI),
-//				zap.Int("status", v.Status),
-//			)
-//
+//			if v.Error == nil {
+//				logger.Info("request",
+//					zap.String("URI", v.URI),
+//					zap.Int("status", v.Status),
+//				)
+//			} else {
+//				logger.Error("request error",
+//					zap.String("URI", v.URI),
+//					zap.Int("status", v.Status),
+//					zap.Error(v.Error),
+//				)
+//			}
 //			return nil
 //		},
 //	}))
 //
 // Example for Logrus (https://github.com/sirupsen/logrus)
-// 	log := logrus.New()
+//  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")
-//
+//		LogURI:      true,
+//		LogStatus:   true,
+//		LogError:    true,
+//		HandleError: true, // forwards error to the global error handler, so it can decide appropriate status code
+//		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
+//			if v.Error == nil {
+//				log.WithFields(logrus.Fields{
+//					"URI":    v.URI,
+//					"status": v.Status,
+//				}).Info("request")
+//			} else {
+//				log.WithFields(logrus.Fields{
+//					"URI":    v.URI,
+//					"status": v.Status,
+//					"error":  v.Error,
+//				}).Error("request error")
+//			}
 //			return nil
 //		},
 //	}))
@@ -74,6 +107,13 @@ type RequestLoggerConfig struct {
 	// Mandatory.
 	LogValuesFunc func(c echo.Context, v RequestLoggerValues) error
 
+	// HandleError instructs logger to call global error handler when next middleware/handler returns an error.
+	// This is useful when you have custom error handler that can decide to use different status codes.
+	//
+	// A side-effect of calling global error handler is that now Response has been committed and sent to the client
+	// and middlewares up in chain can not change Response status code or response body.
+	HandleError bool
+
 	// 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`)
@@ -217,6 +257,9 @@ func (config RequestLoggerConfig) ToMiddleware() (echo.MiddlewareFunc, error) {
 				config.BeforeNextFunc(c)
 			}
 			err := next(c)
+			if config.HandleError {
+				c.Error(err)
+			}
 
 			v := RequestLoggerValues{
 				StartTime: start,
@@ -264,7 +307,9 @@ func (config RequestLoggerConfig) ToMiddleware() (echo.MiddlewareFunc, error) {
 			}
 			if config.LogStatus {
 				v.Status = res.Status
-				if err != nil {
+				if err != nil && !config.HandleError {
+					//  this block should not be executed in case of HandleError=true as the global error handler will decide
+					//  the status code. In that case status code could be different from what err contains.
 					var httpErr *echo.HTTPError
 					if errors.As(err, &httpErr) {
 						v.Status = httpErr.Code
@@ -310,6 +355,9 @@ func (config RequestLoggerConfig) ToMiddleware() (echo.MiddlewareFunc, error) {
 				return errOnLog
 			}
 
+			// in case of HandleError=true we are returning the error that we already have handled with global error handler
+			// this is deliberate as this error could be useful for upstream middlewares and default global error handler
+			// will ignore that error when it bubbles up in middleware chain.
 			return err
 		}
 	}, nil
diff --git a/middleware/request_logger_test.go b/middleware/request_logger_test.go
@@ -103,12 +103,12 @@ func TestRequestLogger_beforeNextFunc(t *testing.T) {
 func TestRequestLogger_logError(t *testing.T) {
 	e := echo.New()
 
-	var expect RequestLoggerValues
+	var actual RequestLoggerValues
 	e.Use(RequestLoggerWithConfig(RequestLoggerConfig{
 		LogError:  true,
 		LogStatus: true,
 		LogValuesFunc: func(c echo.Context, values RequestLoggerValues) error {
-			expect = values
+			actual = values
 			return nil
 		},
 	}))
@@ -123,8 +123,52 @@ func TestRequestLogger_logError(t *testing.T) {
 	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")
+	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) {
