From f48342cc78dabd7810dee5af14206642b654a342 Mon Sep 17 00:00:00 2001 From: Michelangelo Mori Date: Wed, 11 Sep 2024 18:47:58 +0200 Subject: [PATCH 1/2] Add request id to logs. This change adds a GRPC interceptor that fetches the header `Grpc-Metadata-Request-Id` and adds it to the logger. It also returns the request id to the client in the trailer, which is helpful for debugging. CLI command `minder history list` was modified to show its usage, but those changes should be reverted. --- internal/controlplane/server.go | 1 + internal/logger/logging_interceptor.go | 43 ++++++++++++++++++++++++++ 2 files changed, 44 insertions(+) diff --git a/internal/controlplane/server.go b/internal/controlplane/server.go index 59263c53dd..707c979b4c 100644 --- a/internal/controlplane/server.go +++ b/internal/controlplane/server.go @@ -251,6 +251,7 @@ func (s *Server) StartGRPCServer(ctx context.Context) error { // TODO: this has no test coverage! util.SanitizingInterceptor(), logger.Interceptor(s.cfg.LoggingConfig), + logger.RequestIDInterceptor(), TokenValidationInterceptor, EntityContextProjectInterceptor, ProjectAuthorizationInterceptor, diff --git a/internal/logger/logging_interceptor.go b/internal/logger/logging_interceptor.go index 9c317dbf20..b9c2ae4944 100644 --- a/internal/logger/logging_interceptor.go +++ b/internal/logger/logging_interceptor.go @@ -21,6 +21,7 @@ import ( "path" "time" + "github.com/google/uuid" "github.com/rs/zerolog" "google.golang.org/grpc" "google.golang.org/grpc/metadata" @@ -101,3 +102,45 @@ func Interceptor(cfg config.LoggingConfig) grpc.UnaryServerInterceptor { return resp, err } } + +// RequestIDInterceptor traces request ids. +// +// It tries to use the request id from the request context, creating a +// new one if that is missing. It also sends back in the trailer the +// request id, ensuring that the client receives it. +func RequestIDInterceptor() grpc.UnaryServerInterceptor { + return func(ctx context.Context, req interface{}, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { + rID := maybeGetRequestID(ctx) + ctx = zerolog.Ctx(ctx).With().Str("request_id", rID).Logger().WithContext(ctx) + + resp, err := handler(ctx, req) + + if err := grpc.SetTrailer(ctx, metadata.Pairs("request-id", rID)); err != nil { + zerolog.Ctx(ctx).Trace().Err(err).Msg("unable to attach request id to trailer") + } + + return resp, err + } +} + +func maybeGetRequestID(ctx context.Context) string { + var rID string + if md, ok := metadata.FromIncomingContext(ctx); ok { + if rIDs, ok := md["request-id"]; ok { + if len(rIDs) != 0 { + rID = rIDs[0] + } + } + } + + if rID == "" { + return uuid.New().String() + } + + if _, err := uuid.Parse(rID); err != nil { + zerolog.Ctx(ctx).Trace().Err(err).Msg("request id is not valid uuid") + return uuid.New().String() + } + + return rID +} From f2b1f944f4967f4210a321e8efbca84627d22992 Mon Sep 17 00:00:00 2001 From: Michelangelo Mori Date: Tue, 15 Oct 2024 14:26:09 +0200 Subject: [PATCH 2/2] Make server decide the value of request-id. Also, use header rather than trailer. --- internal/controlplane/server.go | 4 ++- internal/logger/logging_interceptor.go | 34 +++++--------------------- 2 files changed, 9 insertions(+), 29 deletions(-) diff --git a/internal/controlplane/server.go b/internal/controlplane/server.go index 707c979b4c..c107553cf8 100644 --- a/internal/controlplane/server.go +++ b/internal/controlplane/server.go @@ -250,8 +250,10 @@ func (s *Server) StartGRPCServer(ctx context.Context) error { interceptors := []grpc.UnaryServerInterceptor{ // TODO: this has no test coverage! util.SanitizingInterceptor(), + // This adds `Grpc-Metadata-Request-Id` to the + // response. + logger.RequestIDInterceptor("request-id"), logger.Interceptor(s.cfg.LoggingConfig), - logger.RequestIDInterceptor(), TokenValidationInterceptor, EntityContextProjectInterceptor, ProjectAuthorizationInterceptor, diff --git a/internal/logger/logging_interceptor.go b/internal/logger/logging_interceptor.go index b9c2ae4944..c0562f4a53 100644 --- a/internal/logger/logging_interceptor.go +++ b/internal/logger/logging_interceptor.go @@ -105,42 +105,20 @@ func Interceptor(cfg config.LoggingConfig) grpc.UnaryServerInterceptor { // RequestIDInterceptor traces request ids. // -// It tries to use the request id from the request context, creating a -// new one if that is missing. It also sends back in the trailer the -// request id, ensuring that the client receives it. -func RequestIDInterceptor() grpc.UnaryServerInterceptor { +// It's job is to add a request id (UUID) to the context so that all +// subsequent logs inherit it, making it easier to track down problems +// on a per-request basis. It also sends back it back in a header. +func RequestIDInterceptor(headerSuffix string) grpc.UnaryServerInterceptor { return func(ctx context.Context, req interface{}, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) { - rID := maybeGetRequestID(ctx) + rID := uuid.New().String() ctx = zerolog.Ctx(ctx).With().Str("request_id", rID).Logger().WithContext(ctx) resp, err := handler(ctx, req) - if err := grpc.SetTrailer(ctx, metadata.Pairs("request-id", rID)); err != nil { + if err := grpc.SendHeader(ctx, metadata.Pairs(headerSuffix, rID)); err != nil { zerolog.Ctx(ctx).Trace().Err(err).Msg("unable to attach request id to trailer") } return resp, err } } - -func maybeGetRequestID(ctx context.Context) string { - var rID string - if md, ok := metadata.FromIncomingContext(ctx); ok { - if rIDs, ok := md["request-id"]; ok { - if len(rIDs) != 0 { - rID = rIDs[0] - } - } - } - - if rID == "" { - return uuid.New().String() - } - - if _, err := uuid.Parse(rID); err != nil { - zerolog.Ctx(ctx).Trace().Err(err).Msg("request id is not valid uuid") - return uuid.New().String() - } - - return rID -}