From ebac6b7c9761a5e129bd06f2237999ea08d6da7b Mon Sep 17 00:00:00 2001 From: Samuel Berthe Date: Wed, 26 Apr 2023 21:01:03 +0200 Subject: [PATCH] feat(tracing): add request id --- README.md | 12 ++++++------ examples/example.go | 2 +- go.mod | 1 + go.sum | 2 ++ middleware.go | 34 +++++++++++++++++++++++++++++++++- 5 files changed, 43 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 9dcfad6..72801ae 100644 --- a/README.md +++ b/README.md @@ -70,7 +70,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time=2023-04-10T14:00:0.000000+02:00 level=INFO msg="HTTP Request" status=200 method=GET path=/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 +// time=2023-04-10T14:00:0.000000+02:00 level=INFO msg="Incoming request" status=200 method=GET path=/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 ``` ### Using custom time formatters @@ -112,7 +112,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time="2023-04-10 14:00:00" level=INFO msg="HTTP Request" status=200 method=GET path=/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-04-10 14:00:00" level=INFO msg="Incoming request" status=200 method=GET path=/pong ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time="2023-04-10 14:00:00" ``` ### Using custom logger sub-group @@ -146,7 +146,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time=2023-04-10T14:00:0.000000+02:00 level=INFO msg="HTTP Request" http.status=200 http.method=GET http.path=/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-04-10T14:00:0.000000+02:00 level=INFO msg="Incoming request" http.status=200 http.method=GET http.path=/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 ``` ### Add logger to a single route @@ -177,7 +177,7 @@ router.GET("/pong", sloggin.New(logger), func(c *gin.Context) { router.Run(":1234") // output: -// time="2023-04-10 14:00:00" level=INFO msg="HTTP Request" status=200 method=GET path=/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-04-10 14:00:00" level=INFO msg="Incoming request" status=200 method=GET path=/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 @@ -215,7 +215,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// time=2023-04-10T14:00:0.000000+02:00 level=INFO msg="HTTP 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 ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00.000+02:00 +// 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 ip=127.0.0.1 latency=25.5µs user-agent=curl/7.77.0 time=2023-04-10T14:00:00.000+02:00 ``` ### JSON output @@ -249,7 +249,7 @@ router.GET("/pong", func(c *gin.Context) { router.Run(":1234") // output: -// {"time":"2023-04-10T14:00:0.000000+02:00","level":"INFO","msg":"HTTP 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-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"} ``` ## 🤝 Contributing diff --git a/examples/example.go b/examples/example.go index 6b9fcf4..06829de 100644 --- a/examples/example.go +++ b/examples/example.go @@ -44,5 +44,5 @@ func main() { } // output: - // time=2023-04-10T14:00:0.000000+00:00 level=ERROR msg="HTTP Request" gin_mode=GIN_MODE http.status=200 http.method=GET http.path=/pong http.ip=127.0.0.1 http.latency=25.5µs http.user-agent=curl/7.77.0 http.time=2023-04-10T14:00:00.000+00:00 + // time=2023-04-10T14:00:0.000000+00:00 level=ERROR msg="Incoming request" gin_mode=GIN_MODE http.status=200 http.method=GET http.path=/pong http.ip=127.0.0.1 http.latency=25.5µs http.user-agent=curl/7.77.0 http.time=2023-04-10T14:00:00.000+00:00 } diff --git a/go.mod b/go.mod index 7a568da..77b7508 100644 --- a/go.mod +++ b/go.mod @@ -34,5 +34,6 @@ require ( require ( github.com/gin-gonic/gin v1.9.0 + github.com/google/uuid v1.3.0 github.com/samber/slog-formatter v0.3.3 ) diff --git a/go.sum b/go.sum index 36a2912..53bc94d 100644 --- a/go.sum +++ b/go.sum @@ -24,6 +24,8 @@ github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaS github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.8 h1:e6P7q2lk1O+qJJb4BtCQXlK8vWEO8V1ZeuEdJNOqZyg= github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= +github.com/google/uuid v1.3.0 h1:t6JiXgmwXMjEs8VusXIJk2BXHsn+wx8BZdTaoZ5fu7I= +github.com/google/uuid v1.3.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM= github.com/json-iterator/go v1.1.12/go.mod h1:e30LSqwooZae/UwlEbR2852Gd8hjQvJoHmT4TnhNGBo= github.com/klauspost/cpuid/v2 v2.0.9 h1:lgaqFMSdTdQYdZ04uHyN2d/eKdOMyi2YLSvlQIBFYa4= diff --git a/middleware.go b/middleware.go index 9e28da2..dfc7092 100644 --- a/middleware.go +++ b/middleware.go @@ -6,13 +6,18 @@ import ( "time" "github.com/gin-gonic/gin" + "github.com/google/uuid" "golang.org/x/exp/slog" ) +const requestIDCtx = "slog-gin.request-id" + type Config struct { DefaultLevel slog.Level ClientErrorLevel slog.Level ServerErrorLevel slog.Level + + WithRequestID bool } // New returns a gin.HandlerFunc (middleware) that logs requests using slog. @@ -24,14 +29,23 @@ func New(logger *slog.Logger) gin.HandlerFunc { DefaultLevel: slog.LevelInfo, ClientErrorLevel: slog.LevelWarn, ServerErrorLevel: slog.LevelError, + + WithRequestID: true, }) } +// NewWithConfig returns a gin.HandlerFunc (middleware) that logs requests using slog. func NewWithConfig(logger *slog.Logger, config Config) gin.HandlerFunc { return func(c *gin.Context) { start := time.Now() path := c.Request.URL.Path + requestID := uuid.New().String() + if config.WithRequestID { + c.Set(requestIDCtx, requestID) + c.Header("X-Request-ID", requestID) + } + c.Next() end := time.Now() @@ -47,13 +61,31 @@ func NewWithConfig(logger *slog.Logger, config Config) gin.HandlerFunc { slog.Time("time", end), } + if config.WithRequestID { + attributes = append(attributes, slog.String("request-id", requestID)) + } + switch { case c.Writer.Status() >= http.StatusBadRequest && c.Writer.Status() < http.StatusInternalServerError: logger.LogAttrs(context.Background(), config.ClientErrorLevel, c.Errors.String(), attributes...) case c.Writer.Status() >= http.StatusInternalServerError: logger.LogAttrs(context.Background(), config.ServerErrorLevel, c.Errors.String(), attributes...) default: - logger.LogAttrs(context.Background(), config.DefaultLevel, "HTTP Request", attributes...) + logger.LogAttrs(context.Background(), config.DefaultLevel, "Incoming request", attributes...) } } } + +// GetRequestID returns the request identifier +func GetRequestID(c *gin.Context) string { + requestID, ok := c.Get(requestIDCtx) + if !ok { + return "" + } + + if id, ok := requestID.(string); ok { + return id + } + + return "" +}