More logging middleware configuration

- Allow excluding trace_id from logger attrs,
  for use primarily with TracingHandler
- Allow AfterRequest to return a null logger
  to skip logging.
- The logger passed to the request no longer has
  all the request fields. This is a massive number
  of fields which just spams logs. Instead,
  the trace_id can be used for correllation.

api/api_test.go

@@ -128,11 +128,27 @@ var _ = Describe("API", func() {
 		})
 		It("logs normal requests at info", func() {
 			e.GET("/", func(c echo.Context) error {
+				api.Logger(c).Debug("fromendpoint")
 				return c.String(200, "ok")
 			})
 			Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(200))
-			Expect(logHook.Records()).To(HaveLen(1))
-			Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelInfo))
+			Expect(logHook.Records()).To(HaveLen(2))
+			Expect(logHook.Records()[0].Record.Level).To(Equal(slog.LevelDebug))
+			Expect(logHook.Records()[0].AttrMap()).ToNot(HaveKey("request_method"))
+			Expect(logHook.Records()[0].AttrMap()).To(HaveKey("trace_id"))
+
+			Expect(logHook.Records()[1].Record.Level).To(Equal(slog.LevelInfo))
+			Expect(logHook.Records()[1].AttrMap()).To(And(
+				HaveKeyWithValue("request_protocol", "HTTP/1.1"),
+				HaveKeyWithValue("request_status", int64(200)),
+				HaveKeyWithValue("request_bytes_out", "2"),
+				HaveKeyWithValue("trace_id", HaveLen(36)),
+				HaveKeyWithValue("request_method", "GET"),
+				HaveKeyWithValue("request_path", "/"),
+				HaveKeyWithValue("request_referer", ""),
+				HaveKeyWithValue("request_bytes_in", "0"),
+				HaveKeyWithValue("request_latency_ms", BeNumerically(">=", 0)),
+			))
 		})
 		It("logs 500+ at error", func() {
 			e.GET("/", func(c echo.Context) error {
@@ -208,6 +224,35 @@ var _ = Describe("API", func() {
 				HaveKeyWithValue("after", BeEquivalentTo(2)),
 			))
 		})
+		It("skips logging if AfterRequest returns a null logger", func() {
+			e = api.New(api.Config{
+				Logger: logger,
+				LoggingMiddlwareConfig: api.LoggingMiddlwareConfig{
+					AfterRequest: func(echo.Context, *slog.Logger) *slog.Logger {
+						return nil
+					},
+				},
+			})
+			e.GET("/", func(c echo.Context) error {
+				return c.String(200, "ok")
+			})
+			Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(200))
+			Expect(logHook.Records()).To(BeEmpty())
+		})
+		It("skips the trace id if configured to skip", func() {
+			e = api.New(api.Config{
+				Logger: logger,
+				LoggingMiddlwareConfig: api.LoggingMiddlwareConfig{
+					SkipTraceAttrs: true,
+				},
+			})
+			e.GET("/", func(c echo.Context) error {
+				return c.String(200, "ok")
+			})
+			Expect(Serve(e, GetRequest("/"))).To(HaveResponseCode(200))
+			Expect(logHook.Records()).To(HaveLen(1))
+			Expect(logHook.Records()[0].AttrMap()).ToNot(HaveKey("trace_id"))
+		})
 	})
 
 	Describe("error handling", func() {

api/logging.go

@@ -30,6 +30,11 @@ type LoggingMiddlwareConfig struct {
 	RequestHeaders bool
 	// If true, log response headers.
 	ResponseHeaders bool
+	// If true, do not log trace_id to the logs.
+	// Use this when doing your own trace logging, like with logctx.TracingHandler.
+	// Note that the trace ID for the request is still available in the request.
+	SkipTraceAttrs bool
+
 	// If provided, the returned logger is stored in the context
 	// which is eventually passed to the handler.
 	// Use to add additional fields to the logger based on the request.
@@ -63,26 +68,9 @@ func LoggingMiddlewareWithConfig(outerLogger *slog.Logger, cfg LoggingMiddlwareC
 				bytesIn = "0"
 			}
 
-			logger := outerLogger.With(
-				"request_started_at", start.Format(time.RFC3339),
-				"request_remote_ip", c.RealIP(),
-				"request_method", req.Method,
-				"request_uri", req.RequestURI,
-				"request_protocol", req.Proto,
-				"request_host", req.Host,
-				"request_path", path,
-				"request_query", req.URL.RawQuery,
-				"request_referer", req.Referer(),
-				"request_user_agent", req.UserAgent(),
-				"request_bytes_in", bytesIn,
-				string(logctx.RequestTraceIdKey), TraceId(c),
-			)
-			if cfg.RequestHeaders {
-				for k, v := range req.Header {
-					if len(v) > 0 && k != "Authorization" && k != "Cookie" {
-						logger = logger.With("request_header."+k, v[0])
-					}
-				}
+			logger := outerLogger
+			if !cfg.SkipTraceAttrs {
+				logger = logger.With(string(logctx.RequestTraceIdKey), TraceId(c))
 			}
 			if cfg.BeforeRequest != nil {
 				logger = cfg.BeforeRequest(c, logger)
@@ -100,11 +88,30 @@ func LoggingMiddlewareWithConfig(outerLogger *slog.Logger, cfg LoggingMiddlwareC
 			res := c.Response()
 
 			logger = Logger(c).With(
+				"request_started_at", start.Format(time.RFC3339),
+				"request_remote_ip", c.RealIP(),
+				"request_method", req.Method,
+				"request_uri", req.RequestURI,
+				"request_protocol", req.Proto,
+				"request_host", req.Host,
+				"request_path", path,
+				"request_query", req.URL.RawQuery,
+				"request_referer", req.Referer(),
+				"request_user_agent", req.UserAgent(),
+				"request_bytes_in", bytesIn,
+
 				"request_finished_at", stop.Format(time.RFC3339),
 				"request_status", res.Status,
 				"request_latency_ms", int(stop.Sub(start))/1000/1000,
 				"request_bytes_out", strconv.FormatInt(res.Size, 10),
 			)
+			if cfg.RequestHeaders {
+				for k, v := range req.Header {
+					if len(v) > 0 && k != "Authorization" && k != "Cookie" {
+						logger = logger.With("request_header."+k, v[0])
+					}
+				}
+			}
 			if cfg.ResponseHeaders {
 				for k, v := range res.Header() {
 					if len(v) > 0 && k != "Set-Cookie" {
@@ -118,7 +125,9 @@ func LoggingMiddlewareWithConfig(outerLogger *slog.Logger, cfg LoggingMiddlwareC
 			if cfg.AfterRequest != nil {
 				logger = cfg.AfterRequest(c, logger)
 			}
-			cfg.DoLog(c, logger)
+			if logger != nil {
+				cfg.DoLog(c, logger)
+			}
 			// c.Error is already called
 			return nil
 		}