From bbe537c60cbf992af6625707d47cf6a5b64839a7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?V=C3=ADctor=20Rold=C3=A1n=20Betancort?= Date: Thu, 26 Oct 2023 12:58:24 +0100 Subject: [PATCH 1/2] log payloads and duration as an integer in order to better troubleshoot certain situations, it would be useful to load request and response payloads. Also in certain log aggregators it's not possible to convert duration fields that are represented as a string, and this is useful in order to filter requests by a specific duration threshold. This commit changes the duration function to log it as an integer --- pkg/cmd/server/defaults.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/pkg/cmd/server/defaults.go b/pkg/cmd/server/defaults.go index 11f6bd788e..1e8d413730 100644 --- a/pkg/cmd/server/defaults.go +++ b/pkg/cmd/server/defaults.go @@ -6,6 +6,7 @@ import ( "fmt" "net/http" "net/http/pprof" + "time" "github.com/fatih/color" "github.com/go-logr/zerologr" @@ -116,7 +117,10 @@ var defaultGRPCLogOptions = []grpclog.Option{ return grpclog.DefaultServerCodeToLevel(code) }), // changes default logging behaviour to only log finish call message - grpclog.WithLogOnEvents(grpclog.FinishCall), + grpclog.WithLogOnEvents(grpclog.PayloadReceived, grpclog.PayloadSent, grpclog.FinishCall), + grpclog.WithDurationField(func(duration time.Duration) grpclog.Fields { + return grpclog.Fields{"grpc.time_ms", duration.Milliseconds()} + }), } const ( From 1b8fa4c73fa578baf7b13d88b8f1a4030adeb33e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?V=C3=ADctor=20Rold=C3=A1n=20Betancort?= Date: Thu, 26 Oct 2023 18:31:56 +0100 Subject: [PATCH 2/2] add options for request/response logs --- pkg/cmd/serve.go | 4 ++ pkg/cmd/server/defaults.go | 52 +++++++++++++++++++------- pkg/cmd/server/server.go | 17 ++++++++- pkg/cmd/server/server_test.go | 6 ++- pkg/cmd/server/zz_generated.options.go | 18 +++++++++ 5 files changed, 79 insertions(+), 18 deletions(-) diff --git a/pkg/cmd/serve.go b/pkg/cmd/serve.go index 66dffd96ed..de641e7720 100644 --- a/pkg/cmd/serve.go +++ b/pkg/cmd/serve.go @@ -47,6 +47,10 @@ func RegisterServeFlags(cmd *cobra.Command, config *server.Config) error { config.DispatchClusterMetricsEnabled = true config.DispatchClientMetricsEnabled = true + // Flags for logging + cmd.Flags().BoolVar(&config.EnableRequestLogs, "grpc-log-requests-enabled", false, "logs API request payloads") + cmd.Flags().BoolVar(&config.EnableResponseLogs, "grpc-log-responses-enabled", false, "logs API response payloads") + // Flags for the gRPC API server util.RegisterGRPCServerFlags(cmd.Flags(), &config.GRPCServer, "grpc", "gRPC", ":50051", true) cmd.Flags().StringSliceVar(&config.PresharedSecureKey, PresharedKeyFlag, []string{}, "preshared key(s) to require for authenticated requests") diff --git a/pkg/cmd/server/defaults.go b/pkg/cmd/server/defaults.go index 1e8d413730..c94b0e4fbb 100644 --- a/pkg/cmd/server/defaults.go +++ b/pkg/cmd/server/defaults.go @@ -116,8 +116,6 @@ var defaultGRPCLogOptions = []grpclog.Option{ } return grpclog.DefaultServerCodeToLevel(code) }), - // changes default logging behaviour to only log finish call message - grpclog.WithLogOnEvents(grpclog.PayloadReceived, grpclog.PayloadSent, grpclog.FinishCall), grpclog.WithDurationField(func(duration time.Duration) grpclog.Fields { return grpclog.Fields{"grpc.time_ms", duration.Milliseconds()} }), @@ -138,8 +136,18 @@ const ( DefaultInternalMiddlewareServerSpecific = "servicespecific" ) +type MiddlewareOption struct { + logger zerolog.Logger + authFunc grpcauth.AuthFunc + enableVersionResponse bool + dispatcher dispatch.Dispatcher + ds datastore.Datastore + enableRequestLog bool + enableResponseLog bool +} + // DefaultUnaryMiddleware generates the default middleware chain used for the public SpiceDB Unary gRPC methods -func DefaultUnaryMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc, enableVersionResponse bool, dispatcher dispatch.Dispatcher, ds datastore.Datastore) (*MiddlewareChain[grpc.UnaryServerInterceptor], error) { +func DefaultUnaryMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.UnaryServerInterceptor], error) { chain, err := NewMiddlewareChain([]ReferenceableMiddleware[grpc.UnaryServerInterceptor]{ NewUnaryMiddleware(). WithName(DefaultMiddlewareRequestID). @@ -153,7 +161,7 @@ func DefaultUnaryMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc, e NewUnaryMiddleware(). WithName(DefaultMiddlewareGRPCLog). - WithInterceptor(grpclog.UnaryServerInterceptor(InterceptorLogger(logger), defaultGRPCLogOptions...)). + WithInterceptor(grpclog.UnaryServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts)...)). Done(), NewUnaryMiddleware(). @@ -168,25 +176,25 @@ func DefaultUnaryMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc, e NewUnaryMiddleware(). WithName(DefaultMiddlewareGRPCAuth). - WithInterceptor(grpcauth.UnaryServerInterceptor(authFunc)). + WithInterceptor(grpcauth.UnaryServerInterceptor(opts.authFunc)). EnsureAlreadyExecuted(DefaultMiddlewareGRPCProm). // so that prom middleware reports auth failures Done(), NewUnaryMiddleware(). WithName(DefaultMiddlewareServerVersion). - WithInterceptor(serverversion.UnaryServerInterceptor(enableVersionResponse)). + WithInterceptor(serverversion.UnaryServerInterceptor(opts.enableVersionResponse)). Done(), NewUnaryMiddleware(). WithName(DefaultInternalMiddlewareDispatch). WithInternal(true). - WithInterceptor(dispatchmw.UnaryServerInterceptor(dispatcher)). + WithInterceptor(dispatchmw.UnaryServerInterceptor(opts.dispatcher)). Done(), NewUnaryMiddleware(). WithName(DefaultInternalMiddlewareDatastore). WithInternal(true). - WithInterceptor(datastoremw.UnaryServerInterceptor(ds)). + WithInterceptor(datastoremw.UnaryServerInterceptor(opts.ds)). Done(), NewUnaryMiddleware(). @@ -205,7 +213,7 @@ func DefaultUnaryMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc, e } // DefaultStreamingMiddleware generates the default middleware chain used for the public SpiceDB Streaming gRPC methods -func DefaultStreamingMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc, enableVersionResponse bool, dispatcher dispatch.Dispatcher, ds datastore.Datastore) (*MiddlewareChain[grpc.StreamServerInterceptor], error) { +func DefaultStreamingMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.StreamServerInterceptor], error) { chain, err := NewMiddlewareChain([]ReferenceableMiddleware[grpc.StreamServerInterceptor]{ NewStreamMiddleware(). WithName(DefaultMiddlewareRequestID). @@ -219,7 +227,7 @@ func DefaultStreamingMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFun NewStreamMiddleware(). WithName(DefaultMiddlewareGRPCLog). - WithInterceptor(grpclog.StreamServerInterceptor(InterceptorLogger(logger), defaultGRPCLogOptions...)). + WithInterceptor(grpclog.StreamServerInterceptor(InterceptorLogger(opts.logger), determineEventsToLog(opts)...)). Done(), NewStreamMiddleware(). @@ -234,25 +242,25 @@ func DefaultStreamingMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFun NewStreamMiddleware(). WithName(DefaultMiddlewareGRPCAuth). - WithInterceptor(grpcauth.StreamServerInterceptor(authFunc)). + WithInterceptor(grpcauth.StreamServerInterceptor(opts.authFunc)). EnsureInterceptorAlreadyExecuted(DefaultMiddlewareGRPCProm). // so that prom middleware reports auth failures Done(), NewStreamMiddleware(). WithName(DefaultMiddlewareServerVersion). - WithInterceptor(serverversion.StreamServerInterceptor(enableVersionResponse)). + WithInterceptor(serverversion.StreamServerInterceptor(opts.enableVersionResponse)). Done(), NewStreamMiddleware(). WithName(DefaultInternalMiddlewareDispatch). WithInternal(true). - WithInterceptor(dispatchmw.StreamServerInterceptor(dispatcher)). + WithInterceptor(dispatchmw.StreamServerInterceptor(opts.dispatcher)). Done(), NewStreamMiddleware(). WithName(DefaultInternalMiddlewareDatastore). WithInternal(true). - WithInterceptor(datastoremw.StreamServerInterceptor(ds)). + WithInterceptor(datastoremw.StreamServerInterceptor(opts.ds)). Done(), NewStreamMiddleware(). @@ -270,6 +278,22 @@ func DefaultStreamingMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFun return &chain, err } +func determineEventsToLog(opts MiddlewareOption) []grpclog.Option { + eventsToLog := []grpclog.LoggableEvent{grpclog.FinishCall} + if opts.enableRequestLog { + eventsToLog = append(eventsToLog, grpclog.PayloadReceived) + } + + if opts.enableResponseLog { + eventsToLog = append(eventsToLog, grpclog.PayloadSent) + } + + logOnEvents := grpclog.WithLogOnEvents(eventsToLog...) + grpcLogOptions := append(defaultGRPCLogOptions, logOnEvents) + + return grpcLogOptions +} + // DefaultDispatchMiddleware generates the default middleware chain used for the internal dispatch SpiceDB gRPC API func DefaultDispatchMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc, ds datastore.Datastore) ([]grpc.UnaryServerInterceptor, []grpc.StreamServerInterceptor) { return []grpc.UnaryServerInterceptor{ diff --git a/pkg/cmd/server/server.go b/pkg/cmd/server/server.go index 3c51393ff1..e8a0870f80 100644 --- a/pkg/cmd/server/server.go +++ b/pkg/cmd/server/server.go @@ -127,6 +127,10 @@ type Config struct { TelemetryCAOverridePath string `debugmap:"visible"` TelemetryEndpoint string `debugmap:"visible"` TelemetryInterval time.Duration `debugmap:"visible"` + + // Logs + EnableRequestLogs bool `debugmap:"visible"` + EnableResponseLogs bool `debugmap:"visible"` } type closeableStack struct { @@ -349,12 +353,21 @@ func (c *Config) Complete(ctx context.Context) (RunnableServer, error) { watchServiceOption = services.WatchServiceDisabled } - defaultUnaryMiddlewareChain, err := DefaultUnaryMiddleware(log.Logger, c.GRPCAuthFunc, !c.DisableVersionResponse, dispatcher, ds) + opts := MiddlewareOption{ + log.Logger, + c.GRPCAuthFunc, + !c.DisableVersionResponse, + dispatcher, + ds, + c.EnableRequestLogs, + c.EnableResponseLogs, + } + defaultUnaryMiddlewareChain, err := DefaultUnaryMiddleware(opts) if err != nil { return nil, fmt.Errorf("error building default middlewares: %w", err) } - defaultStreamingMiddlewareChain, err := DefaultStreamingMiddleware(log.Logger, c.GRPCAuthFunc, !c.DisableVersionResponse, dispatcher, ds) + defaultStreamingMiddlewareChain, err := DefaultStreamingMiddleware(opts) if err != nil { return nil, fmt.Errorf("error building default middlewares: %w", err) } diff --git a/pkg/cmd/server/server_test.go b/pkg/cmd/server/server_test.go index 1650e73625..f87f3f3847 100644 --- a/pkg/cmd/server/server_test.go +++ b/pkg/cmd/server/server_test.go @@ -230,7 +230,8 @@ func TestModifyUnaryMiddleware(t *testing.T) { }, }} - defaultMw, err := DefaultUnaryMiddleware(logging.Logger, nil, false, nil, nil) + opt := MiddlewareOption{logging.Logger, nil, false, nil, nil, false, false} + defaultMw, err := DefaultUnaryMiddleware(opt) require.NoError(t, err) unary, err := c.buildUnaryMiddleware(defaultMw) @@ -255,7 +256,8 @@ func TestModifyStreamingMiddleware(t *testing.T) { }, }} - defaultMw, err := DefaultStreamingMiddleware(logging.Logger, nil, false, nil, nil) + opt := MiddlewareOption{logging.Logger, nil, false, nil, nil, false, false} + defaultMw, err := DefaultStreamingMiddleware(opt) require.NoError(t, err) streaming, err := c.buildStreamingMiddleware(defaultMw) diff --git a/pkg/cmd/server/zz_generated.options.go b/pkg/cmd/server/zz_generated.options.go index 2cf7cd1a93..00615b9beb 100644 --- a/pkg/cmd/server/zz_generated.options.go +++ b/pkg/cmd/server/zz_generated.options.go @@ -88,6 +88,8 @@ func (c *Config) ToOption() ConfigOption { to.TelemetryCAOverridePath = c.TelemetryCAOverridePath to.TelemetryEndpoint = c.TelemetryEndpoint to.TelemetryInterval = c.TelemetryInterval + to.EnableRequestLogs = c.EnableRequestLogs + to.EnableResponseLogs = c.EnableResponseLogs } } @@ -140,6 +142,8 @@ func (c Config) DebugMap() map[string]any { debugMap["TelemetryCAOverridePath"] = helpers.DebugValue(c.TelemetryCAOverridePath, false) debugMap["TelemetryEndpoint"] = helpers.DebugValue(c.TelemetryEndpoint, false) debugMap["TelemetryInterval"] = helpers.DebugValue(c.TelemetryInterval, false) + debugMap["EnableRequestLogs"] = helpers.DebugValue(c.EnableRequestLogs, false) + debugMap["EnableResponseLogs"] = helpers.DebugValue(c.EnableResponseLogs, false) return debugMap } @@ -564,3 +568,17 @@ func WithTelemetryInterval(telemetryInterval time.Duration) ConfigOption { c.TelemetryInterval = telemetryInterval } } + +// WithEnableRequestLogs returns an option that can set EnableRequestLogs on a Config +func WithEnableRequestLogs(enableRequestLogs bool) ConfigOption { + return func(c *Config) { + c.EnableRequestLogs = enableRequestLogs + } +} + +// WithEnableResponseLogs returns an option that can set EnableResponseLogs on a Config +func WithEnableResponseLogs(enableResponseLogs bool) ConfigOption { + return func(c *Config) { + c.EnableResponseLogs = enableResponseLogs + } +}