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] 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 + } +}