diff --git a/README.md b/README.md index 957b4f5..2039f7e 100644 --- a/README.md +++ b/README.md @@ -81,7 +81,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time=2023-04-10T14:00:0.000000Z level=INFO msg="Incoming request" status=200 method=GET path=/pong route=/pong ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00.000Z +// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Incoming request" 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="" ``` ### OTEL @@ -200,7 +200,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time="2023-04-10 14:00:00" level=INFO msg="Incoming request" status=200 method=GET path=/pong route=/pong ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time="2023-04-10 14:00:00" +// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Incoming request" 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="" ``` ### Using custom logger sub-group @@ -223,7 +223,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time=2023-04-10T14:00:0.000000+02:00 level=INFO msg="Incoming request" http.status=200 http.method=GET http.path=/pong http.route=/pong http.ip=127.0.0.1 http.latency=20.125µs http.user-agent=curl/7.77.0 time=2023-04-10T14:00:00.000+02:00 +// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Incoming request" 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="" ``` ### Add logger to a single route @@ -241,9 +241,6 @@ router.GET("/pong", sloggin.New(logger), func(c *gin.Context) { }) router.Run(":1234") - -// output: -// time="2023-04-10 14:00:00" level=INFO msg="Incoming request" status=200 method=GET path=/pong route=/pong ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time="2023-04-10 14:00:00" ``` ### Adding custom attributes @@ -272,7 +269,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time=2023-04-10T14:00:0.000000+02:00 level=INFO msg="Incoming request" environment=production server=gin/1.9.0 gin_mode=release server_start_time=2023-04-10T10:00:00.000+02:00 status=200 method=GET path=/pong route=/pong ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00.000+02:00 foo=bar +// time=2023-10-15T20:32:58.926+02:00 level=INFO msg="Incoming request" environment=production server=gin/1.9.0 gin_mode=release 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="" foo=bar ``` ### JSON output @@ -295,7 +292,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// {"time":"2023-04-10T14:00:0.000000+02:00","level":"INFO","msg":"Incoming request","gin_mode":"GIN_MODE","status":200,"method":"GET","path":"/pong","ip":"127.0.0.1","latency":15542,"user-agent":"curl/7.77.0","time":"2023-04-10T14:00:0.000000+02:00"} +// {"time":"2023-10-15T20:32:58.926+02:00","level":"INFO","msg":"Incoming request","gin_mode":"GIN_MODE","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":""}} ``` ## 🤝 Contributing diff --git a/dump.go b/dump.go index ff17ab4..514114d 100644 --- a/dump.go +++ b/dump.go @@ -2,6 +2,7 @@ package sloggin import ( "bytes" + "io" "github.com/gin-gonic/gin" ) @@ -10,22 +11,65 @@ type bodyWriter struct { gin.ResponseWriter body *bytes.Buffer maxSize int + bytes int } // 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 gin.ResponseWriter, maxSize int) *bodyWriter { +func newBodyWriter(writer gin.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 index 70ad00b..135a20f 100644 --- a/middleware.go +++ b/middleware.go @@ -1,8 +1,6 @@ package sloggin import ( - "bytes" - "io" "net/http" "strings" "time" @@ -71,7 +69,8 @@ func New(logger *slog.Logger) gin.HandlerFunc { WithResponseHeader: false, WithSpanID: false, WithTraceID: false, - Filters: []Filter{}, + + Filters: []Filter{}, }) } @@ -111,86 +110,107 @@ func NewWithConfig(logger *slog.Logger, config Config) gin.HandlerFunc { } // 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(c.Request.Body, RequestBodyMaxSize, config.WithRequestBody) + c.Request.Body = br // dump response body - if config.WithResponseBody { - c.Writer = newBodyWriter(c.Writer, ResponseBodyMaxSize) - } + bw := newBodyWriter(c.Writer, ResponseBodyMaxSize, config.WithResponseBody) + c.Writer = bw c.Next() + status := c.Writer.Status() + method := c.Request.Method + host := c.Request.Host + route := c.FullPath() end := time.Now() latency := end.Sub(start) - status := c.Writer.Status() + userAgent := c.Request.UserAgent() + ip := c.ClientIP() + referer := c.Request.Referer() - attributes := []slog.Attr{ - slog.Int("status", status), - slog.String("method", c.Request.Method), + 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", c.FullPath()), - slog.String("ip", c.ClientIP()), - slog.Duration("latency", latency), - slog.Time("time", end), + slog.String("route", route), + slog.String("ip", ip), + slog.String("referer", referer), } - if config.WithUserAgent { - attributes = append(attributes, slog.String("user-agent", c.Request.UserAgent())) + responseAttributes := []slog.Attr{ + slog.Time("time", end), + slog.Duration("latency", latency), + slog.Int("status", status), } if config.WithRequestID { - 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.WithResponseBody { - if w, ok := c.Writer.(*bodyWriter); ok { - attributes = append(attributes, slog.Group("response", slog.String("body", w.body.String()))) - } + if config.WithUserAgent { + requestAttributes = append(requestAttributes, slog.String("user-agent", userAgent)) } + + // response body + responseAttributes = append(responseAttributes, slog.Int("length", bw.bytes)) + if config.WithResponseBody { + responseAttributes = append(responseAttributes, slog.String("body", bw.body.String())) + } + + // response headers if config.WithResponseHeader { for k, v := range c.Writer.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, ok := c.Get(customAttributesCtxKey); ok { switch attrs := v.(type) {