move attributes tot nested group - first commit of the year

samber · Jan 1, 2024 · 20c3de5 · 20c3de5
1 parent 0c7ed0f
commit 20c3de5
Show file tree

Hide file tree

Showing 3 changed files with 116 additions and 61 deletions.
diff --git a/README.md b/README.md
@@ -94,7 +94,7 @@ e.GET("/error", func(c echo.Context) error {
 e.Logger.Fatal(e.Start(":4242"))
 
 // output:
-// time=2023-04-10T14:00:00Z level=INFO msg="Success"  status=200 method=GET path=/ route=/ ip=::1 latency=25.958µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00Z request-id=229c7fc8-64f5-4467-bc4a-940700503b0d
+// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Success" env=production request.time=2023-10-15T20:32:58.626+02:00 request.method=GET request.path=/ request.route="" request.ip=127.0.0.1:63932 request.length=0 response.time=2023-10-15T20:32:58.926+02:00 response.latency=100ms response.status=200 response.length=7 id=229c7fc8-64f5-4467-bc4a-940700503b0d
 ```
 
 ### OTEL
@@ -222,7 +222,7 @@ e.GET("/error", func(c echo.Context) error {
 e.Logger.Fatal(e.Start(":4242"))
 
 // output:
-// time=2023-04-10T14:00:00Z level=INFO msg="Success"  status=200 method=GET path=/ route=/ ip=::1 latency=25.958µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00Z request-id=229c7fc8-64f5-4467-bc4a-940700503b0d
+// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Success" env=production request.time=2023-10-15T20:32:58Z request.method=GET request.path=/ request.route="" request.ip=127.0.0.1:63932 request.length=0 response.time=2023-10-15T20:32:58Z response.latency=100ms response.status=200 response.length=7 id=229c7fc8-64f5-4467-bc4a-940700503b0d
 ```
 
 ### Using custom logger sub-group
@@ -249,7 +249,7 @@ e.GET("/error", func(c echo.Context) error {
 e.Logger.Fatal(e.Start(":4242"))
 
 // output:
-// time=2023-04-10T14:00:00Z level=INFO msg="Success"  http.status=200 http.method=GET http.path=/ http.route=/ http.ip=::1 http.latency=25.958µs http.user-agent=curl/7.77.0 http.time=2023-04-10T14:00:00Z http.request-id=229c7fc8-64f5-4467-bc4a-940700503b0d
+// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Success" env=production http.request.time=2023-10-15T20:32:58.626+02:00 http.request.method=GET http.request.path=/ http.request.route="" http.request.ip=127.0.0.1:63932 http.request.length=0 http.response.time=2023-10-15T20:32:58.926+02:00 http.response.latency=100ms http.response.status=200 http.response.length=7 http.id=229c7fc8-64f5-4467-bc4a-940700503b0d
 ```
 
 ### Add logger to a single route
@@ -270,9 +270,6 @@ e.GET("/", func(c echo.Context) error {
 
 // Start server
 e.Logger.Fatal(e.Start(":4242"))
-
-// output:
-// time=2023-04-10T14:00:00Z level=INFO msg="Success"  status=200 method=GET path=/ route=/ ip=::1 latency=25.958µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00Z request-id=229c7fc8-64f5-4467-bc4a-940700503b0d
 ```
 
 ### Adding custom attributes
@@ -301,7 +298,7 @@ e.GET("/", func(c echo.Context) error {
 e.Logger.Fatal(e.Start(":4242"))
 
 // output:
-// time=2023-04-10T14:00:00Z level=INFO msg="Success" env=production status=200 method=GET path=/ route=/ ip=::1 latency=25.958µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00Z request-id=229c7fc8-64f5-4467-bc4a-940700503b0d foo=bar
+// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Success" env=production request.time=2023-10-15T20:32:58.626+02:00 request.method=GET request.path=/ request.route="" request.ip=127.0.0.1:63932 request.length=0 response.time=2023-10-15T20:32:58.926+02:00 response.latency=100ms response.status=200 response.length=7 id=229c7fc8-64f5-4467-bc4a-940700503b0d foo=bar
 ```
 
 ### JSON output
@@ -325,7 +322,7 @@ e.GET("/", func(c echo.Context) error {
 e.Logger.Fatal(e.Start(":4242"))
 
 // output:
-// {"time":"2023-04-10T14:00:00Z","level":"INFO","msg":"Success","env":"production","status":200,"method":"GET","path":"/","ip":"::1","latency":"25.958µs","user-agent":"curl/7.77.0","time":"2023-04-10T14:00:00Z","request-id":"04201917-d7ba-4b20-a3bb-2fffba5f2bd9"}
+// {"time":"2023-10-15T20:32:58.926+02:00","level":"INFO","msg":"Success","env":"production","http":{"request":{"time":"2023-10-15T20:32:58.626+02:00","method":"GET","path":"/","route":"","ip":"127.0.0.1:55296","length":0},"response":{"time":"2023-10-15T20:32:58.926+02:00","latency":100000,"status":200,"length":7},"id":"04201917-d7ba-4b20-a3bb-2fffba5f2bd9"}}
 ```
 
 ## 🤝 Contributing

diff --git a/dump.go b/dump.go
@@ -2,29 +2,73 @@ package slogecho
 
 import (
 	"bytes"
+	"io"
 	"net/http"
 )
 
 type bodyWriter struct {
 	http.ResponseWriter
 	body    *bytes.Buffer
 	maxSize int
+	bytes   int
 }
 
-// implements http.ResponseWriter
+// implements gin.ResponseWriter
 func (w bodyWriter) Write(b []byte) (int, error) {
-	if w.body.Len()+len(b) > w.maxSize {
-		w.body.Write(b[:w.maxSize-w.body.Len()])
-	} else {
-		w.body.Write(b)
+	if w.body != nil {
+		if w.body.Len()+len(b) > w.maxSize {
+			w.body.Write(b[:w.maxSize-w.body.Len()])
+		} else {
+			w.body.Write(b)
+		}
 	}
+	w.bytes += len(b)
 	return w.ResponseWriter.Write(b)
 }
 
-func newBodyWriter(writer http.ResponseWriter, maxSize int) *bodyWriter {
+func newBodyWriter(writer http.ResponseWriter, maxSize int, recordBody bool) *bodyWriter {
+	var body *bytes.Buffer
+	if recordBody {
+		body = bytes.NewBufferString("")
+	}
+
 	return &bodyWriter{
-		body:           bytes.NewBufferString(""),
 		ResponseWriter: writer,
+		body:           body,
 		maxSize:        maxSize,
 	}
 }
+
+type bodyReader struct {
+	io.ReadCloser
+	body    *bytes.Buffer
+	maxSize int
+	bytes   int
+}
+
+// implements io.Reader
+func (r *bodyReader) Read(b []byte) (int, error) {
+	n, err := r.ReadCloser.Read(b)
+	if r.body != nil {
+		if r.body.Len()+n > r.maxSize {
+			r.body.Write(b[:r.maxSize-r.body.Len()])
+		} else {
+			r.body.Write(b)
+		}
+	}
+	r.bytes += n
+	return n, err
+}
+
+func newBodyReader(reader io.ReadCloser, maxSize int, recordBody bool) *bodyReader {
+	var body *bytes.Buffer
+	if recordBody {
+		body = bytes.NewBufferString("")
+	}
+
+	return &bodyReader{
+		ReadCloser: reader,
+		body:       body,
+		maxSize:    maxSize,
+	}
+}
diff --git a/middleware.go b/middleware.go
@@ -1,9 +1,7 @@
 package slogecho
 
 import (
-	"bytes"
 	"errors"
-	"io"
 	"net/http"
 	"strings"
 	"time"
@@ -105,42 +103,32 @@ func NewWithConfig(logger *slog.Logger, config Config) echo.MiddlewareFunc {
 		return func(c echo.Context) (err error) {
 			req := c.Request()
 			res := c.Response()
-
 			start := time.Now()
+			path := req.URL.Path
 
 			// dump request body
-			var reqBody []byte
-			if config.WithRequestBody {
-				buf, err := io.ReadAll(c.Request().Body)
-				if err == nil {
-					c.Request().Body = io.NopCloser(bytes.NewBuffer(buf))
-					if len(buf) > RequestBodyMaxSize {
-						reqBody = buf[:RequestBodyMaxSize]
-					} else {
-						reqBody = buf
-					}
-				}
-			}
+			br := newBodyReader(req.Body, RequestBodyMaxSize, config.WithRequestBody)
+			req.Body = br
 
 			// dump response body
-			if config.WithResponseBody {
-				c.Response().Writer = newBodyWriter(c.Response().Writer, ResponseBodyMaxSize)
-			}
+			bw := newBodyWriter(res.Writer, ResponseBodyMaxSize, config.WithResponseBody)
+			res.Writer = bw
 
 			err = next(c)
 
 			if err != nil {
 				c.Error(err)
 			}
 
-			path := req.URL.Path
-			route := c.Path()
 			status := res.Status
 			method := req.Method
+			host := req.Host
+			route := c.Path()
 			end := time.Now()
 			latency := end.Sub(start)
-			ip := c.RealIP()
 			userAgent := req.UserAgent()
+			ip := c.RealIP()
+			referer := c.Request().Referer()
 
 			httpErr := new(echo.HTTPError)
 			if err != nil && errors.As(err, &httpErr) {
@@ -150,26 +138,22 @@ func NewWithConfig(logger *slog.Logger, config Config) echo.MiddlewareFunc {
 				}
 			}
 
-			attributes := []slog.Attr{
-				slog.Time("time", end),
-				slog.Duration("latency", latency),
+			baseAttributes := []slog.Attr{}
+
+			requestAttributes := []slog.Attr{
+				slog.Time("time", start),
 				slog.String("method", method),
+				slog.String("host", host),
 				slog.String("path", path),
 				slog.String("route", route),
-				slog.Int("status", status),
 				slog.String("ip", ip),
+				slog.String("referer", referer),
 			}
 
-			xForwardedFor, ok := c.Get(echo.HeaderXForwardedFor).(string)
-			if ok && len(xForwardedFor) > 0 {
-				ips := lo.Map(strings.Split(xForwardedFor, ","), func(ip string, _ int) string {
-					return strings.TrimSpace(ip)
-				})
-				attributes = append(attributes, slog.Any("x-forwarded-for", ips))
-			}
-
-			if config.WithUserAgent {
-				attributes = append(attributes, slog.String("user-agent", userAgent))
+			responseAttributes := []slog.Attr{
+				slog.Time("time", end),
+				slog.Duration("latency", latency),
+				slog.Int("status", status),
 			}
 
 			if config.WithRequestID {
@@ -178,48 +162,78 @@ func NewWithConfig(logger *slog.Logger, config Config) echo.MiddlewareFunc {
 					requestID = res.Header().Get(echo.HeaderXRequestID)
 				}
 				if requestID != "" {
-					attributes = append(attributes, slog.String("request-id", requestID))
+					baseAttributes = append(baseAttributes, slog.String("id", requestID))
 				}
 			}
 
 			// otel
 			if config.WithTraceID {
 				traceID := trace.SpanFromContext(c.Request().Context()).SpanContext().TraceID().String()
-				attributes = append(attributes, slog.String("trace-id", traceID))
+				baseAttributes = append(baseAttributes, slog.String("trace-id", traceID))
 			}
 			if config.WithSpanID {
 				spanID := trace.SpanFromContext(c.Request().Context()).SpanContext().SpanID().String()
-				attributes = append(attributes, slog.String("span-id", spanID))
+				baseAttributes = append(baseAttributes, slog.String("span-id", spanID))
 			}
 
-			// request
+			// request body
+			requestAttributes = append(requestAttributes, slog.Int("length", br.bytes))
 			if config.WithRequestBody {
-				attributes = append(attributes, slog.Group("request", slog.String("body", string(reqBody))))
+				requestAttributes = append(requestAttributes, slog.String("body", br.body.String()))
 			}
+
+			// request headers
 			if config.WithRequestHeader {
 				for k, v := range c.Request().Header {
 					if _, found := HiddenRequestHeaders[strings.ToLower(k)]; found {
 						continue
 					}
-					attributes = append(attributes, slog.Group("request", slog.Group("header", slog.Any(k, v))))
+					requestAttributes = append(requestAttributes, slog.Group("header", slog.Any(k, v)))
 				}
 			}
 
-			// response
+			if config.WithUserAgent {
+				requestAttributes = append(requestAttributes, slog.String("user-agent", userAgent))
+			}
+
+			xForwardedFor, ok := c.Get(echo.HeaderXForwardedFor).(string)
+			if ok && len(xForwardedFor) > 0 {
+				ips := lo.Map(strings.Split(xForwardedFor, ","), func(ip string, _ int) string {
+					return strings.TrimSpace(ip)
+				})
+				requestAttributes = append(requestAttributes, slog.Any("x-forwarded-for", ips))
+			}
+
+			// response body body
+			responseAttributes = append(responseAttributes, slog.Int("length", bw.bytes))
 			if config.WithResponseBody {
-				if w, ok := c.Response().Writer.(*bodyWriter); ok {
-					attributes = append(attributes, slog.Group("response", slog.String("body", w.body.String())))
-				}
+				responseAttributes = append(responseAttributes, slog.String("body", bw.body.String()))
 			}
+
+			// response headers
 			if config.WithResponseHeader {
 				for k, v := range c.Response().Header() {
 					if _, found := HiddenResponseHeaders[strings.ToLower(k)]; found {
 						continue
 					}
-					attributes = append(attributes, slog.Group("response", slog.Group("header", slog.Any(k, v))))
+					responseAttributes = append(responseAttributes, slog.Group("header", slog.Any(k, v)))
 				}
 			}
 
+			attributes := append(
+				[]slog.Attr{
+					{
+						Key:   "request",
+						Value: slog.GroupValue(requestAttributes...),
+					},
+					{
+						Key:   "response",
+						Value: slog.GroupValue(responseAttributes...),
+					},
+				},
+				baseAttributes...,
+			)
+
 			// custom context values
 			if v := c.Get(customAttributesCtxKey); v != nil {
 				switch attrs := v.(type) {