From e8775a9c934ac322d33a317fd8703b30e59a057a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?V=C3=ADctor=20Rold=C3=A1n=20Betancort?= Date: Fri, 1 Mar 2024 13:53:06 +0000 Subject: [PATCH] move health check logs to debug level they introduce noise in SpiceDB logs --- pkg/cmd/server/defaults.go | 78 +++++++++++++++++++++++++++----------- 1 file changed, 56 insertions(+), 22 deletions(-) diff --git a/pkg/cmd/server/defaults.go b/pkg/cmd/server/defaults.go index 3d25fda5f2..9b1ab4e8e3 100644 --- a/pkg/cmd/server/defaults.go +++ b/pkg/cmd/server/defaults.go @@ -11,8 +11,10 @@ import ( "github.com/fatih/color" "github.com/go-logr/zerologr" grpcprom "github.com/grpc-ecosystem/go-grpc-middleware/providers/prometheus" + "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors" grpcauth "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/auth" grpclog "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging" + "github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/selector" "github.com/jzelinskie/cobrautil/v2" "github.com/jzelinskie/cobrautil/v2/cobraotel" "github.com/jzelinskie/cobrautil/v2/cobrazerolog" @@ -113,19 +115,22 @@ func MetricsHandler(telemetryRegistry *prometheus.Registry, c *Config) http.Hand return mux } -var defaultGRPCLogOptions = []grpclog.Option{ - // the server has a deadline set, so we consider it a normal condition - // this makes sure we don't log them as errors - grpclog.WithLevels(func(code codes.Code) grpclog.Level { - if code == codes.DeadlineExceeded { - return grpclog.LevelInfo - } - return grpclog.DefaultServerCodeToLevel(code) - }), - grpclog.WithDurationField(func(duration time.Duration) grpclog.Fields { - return grpclog.Fields{"grpc.time_ms", duration.Milliseconds()} - }), -} +// the server has a deadline set, so we consider it a normal condition +// this makes sure we don't log them as errors +var defaultCodeToLevel = grpclog.WithLevels(func(code codes.Code) grpclog.Level { + if code == codes.DeadlineExceeded { + return grpclog.LevelInfo + } + return grpclog.DefaultServerCodeToLevel(code) +}) + +var durationFieldOption = grpclog.WithDurationField(func(duration time.Duration) grpclog.Fields { + return grpclog.Fields{"grpc.time_ms", duration.Milliseconds()} +}) + +var alwaysDebugOption = grpclog.WithLevels(func(code codes.Code) grpclog.Level { + return grpclog.LevelDebug +}) const ( DefaultMiddlewareRequestID = "requestid" @@ -162,6 +167,20 @@ func init() { GRPCMetricsUnaryInterceptor, GRPCMetricsStreamingInterceptor = createServerMetrics() } +const healthCheckRoute = "/grpc.health.v1.Health/Check" + +func matchesRoute(route string) func(_ context.Context, c interceptors.CallMeta) bool { + return func(_ context.Context, c interceptors.CallMeta) bool { + return c.FullMethod() == route + } +} + +func doesNotMatchRoute(route string) func(_ context.Context, c interceptors.CallMeta) bool { + return func(_ context.Context, c interceptors.CallMeta) bool { + return c.FullMethod() != route + } +} + // DefaultUnaryMiddleware generates the default middleware chain used for the public SpiceDB Unary gRPC methods func DefaultUnaryMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.UnaryServerInterceptor], error) { chain, err := NewMiddlewareChain([]ReferenceableMiddleware[grpc.UnaryServerInterceptor]{ @@ -175,9 +194,18 @@ func DefaultUnaryMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.UnaryS WithInterceptor(logmw.UnaryServerInterceptor(logmw.ExtractMetadataField("x-request-id", "requestID"))). Done(), + NewUnaryMiddleware(). + WithName(DefaultMiddlewareGRPCLog + "-debug"). + WithInterceptor(selector.UnaryServerInterceptor( + grpclog.UnaryServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts), alwaysDebugOption, durationFieldOption), + selector.MatchFunc(matchesRoute(healthCheckRoute)))). + Done(), + NewUnaryMiddleware(). WithName(DefaultMiddlewareGRPCLog). - WithInterceptor(grpclog.UnaryServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts)...)). + WithInterceptor(selector.UnaryServerInterceptor( + grpclog.UnaryServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts), defaultCodeToLevel, durationFieldOption), + selector.MatchFunc(doesNotMatchRoute(healthCheckRoute)))). Done(), NewUnaryMiddleware(). @@ -241,9 +269,18 @@ func DefaultStreamingMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.St WithInterceptor(logmw.StreamServerInterceptor(logmw.ExtractMetadataField("x-request-id", "requestID"))). Done(), + NewStreamMiddleware(). + WithName(DefaultMiddlewareGRPCLog + "-debug"). + WithInterceptor(selector.StreamServerInterceptor( + grpclog.StreamServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts), alwaysDebugOption, durationFieldOption), + selector.MatchFunc(matchesRoute(healthCheckRoute)))). + Done(), + NewStreamMiddleware(). WithName(DefaultMiddlewareGRPCLog). - WithInterceptor(grpclog.StreamServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts)...)). + WithInterceptor(selector.StreamServerInterceptor( + grpclog.StreamServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts), defaultCodeToLevel, durationFieldOption), + selector.MatchFunc(doesNotMatchRoute(healthCheckRoute)))). Done(), NewStreamMiddleware(). @@ -294,7 +331,7 @@ func DefaultStreamingMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.St return &chain, err } -func determineEventsToLog(opts MiddlewareOption) []grpclog.Option { +func determineEventsToLog(opts MiddlewareOption) grpclog.Option { eventsToLog := []grpclog.LoggableEvent{grpclog.FinishCall} if opts.enableRequestLog { eventsToLog = append(eventsToLog, grpclog.PayloadReceived) @@ -304,10 +341,7 @@ func determineEventsToLog(opts MiddlewareOption) []grpclog.Option { eventsToLog = append(eventsToLog, grpclog.PayloadSent) } - logOnEvents := grpclog.WithLogOnEvents(eventsToLog...) - grpcLogOptions := append(defaultGRPCLogOptions, logOnEvents) - - return grpcLogOptions + return grpclog.WithLogOnEvents(eventsToLog...) } // DefaultDispatchMiddleware generates the default middleware chain used for the internal dispatch SpiceDB gRPC API @@ -315,7 +349,7 @@ func DefaultDispatchMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc return []grpc.UnaryServerInterceptor{ requestid.UnaryServerInterceptor(requestid.GenerateIfMissing(true)), logmw.UnaryServerInterceptor(logmw.ExtractMetadataField("x-request-id", "requestID")), - grpclog.UnaryServerInterceptor(InterceptorLogger(logger), defaultGRPCLogOptions...), + grpclog.UnaryServerInterceptor(InterceptorLogger(logger), defaultCodeToLevel, durationFieldOption), otelgrpc.UnaryServerInterceptor(), // nolint: staticcheck GRPCMetricsUnaryInterceptor, grpcauth.UnaryServerInterceptor(authFunc), @@ -324,7 +358,7 @@ func DefaultDispatchMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc }, []grpc.StreamServerInterceptor{ requestid.StreamServerInterceptor(requestid.GenerateIfMissing(true)), logmw.StreamServerInterceptor(logmw.ExtractMetadataField("x-request-id", "requestID")), - grpclog.StreamServerInterceptor(InterceptorLogger(logger), defaultGRPCLogOptions...), + grpclog.StreamServerInterceptor(InterceptorLogger(logger), defaultCodeToLevel, durationFieldOption), otelgrpc.StreamServerInterceptor(), // nolint: staticcheck GRPCMetricsStreamingInterceptor, grpcauth.StreamServerInterceptor(authFunc),