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 11f6bd788e..c94b0e4fbb 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" @@ -115,8 +116,9 @@ var defaultGRPCLogOptions = []grpclog.Option{ } return grpclog.DefaultServerCodeToLevel(code) }), - // changes default logging behaviour to only log finish call message - grpclog.WithLogOnEvents(grpclog.FinishCall), + grpclog.WithDurationField(func(duration time.Duration) grpclog.Fields { + return grpclog.Fields{"grpc.time_ms", duration.Milliseconds()} + }), } const ( @@ -134,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). @@ -149,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(). @@ -164,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(). @@ -201,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). @@ -215,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(). @@ -230,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(). @@ -266,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 + } +}