Merge pull request #1615 from authzed/tweak-logs

log payloads, and add grpc duration as an integer

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")

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{

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)
 	}

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)