logging: reduce grpc logging noise (#3329)

* Normalize gRPC logs to print at warn level only
* Fix grpcLogger level enablement

---------

Signed-off-by: Daniel Weiße <dw@edgeless.systems>

bootstrapper/cmd/bootstrapper/main.go

@@ -46,11 +46,7 @@ func main() {
 	verbosity := flag.Int("v", 0, logger.CmdLineVerbosityDescription)
 	flag.Parse()
 	log := logger.NewJSONLogger(logger.VerbosityFromInt(*verbosity)).WithGroup("bootstrapper")
-	logger.ReplaceGRPCLogger(
-		slog.New(
-			logger.NewLevelHandler(logger.VerbosityFromInt(*verbosity), log.Handler()),
-		).WithGroup("gRPC"),
-	)
+	logger.ReplaceGRPCLogger(logger.GRPCLogger(log))
 
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()

bootstrapper/internal/initserver/initserver.go

@@ -109,7 +109,7 @@ func New(
 	grpcServer := grpc.NewServer(
 		grpc.Creds(atlscredentials.New(issuer, nil)),
 		grpc.KeepaliveParams(keepalive.ServerParameters{Time: 15 * time.Second}),
-		logger.GetServerUnaryInterceptor(log.WithGroup("gRPC")),
+		logger.GetServerUnaryInterceptor(logger.GRPCLogger(log)),
 	)
 	initproto.RegisterAPIServer(grpcServer, server)
 

debugd/internal/debugd/server/server.go

@@ -157,8 +157,8 @@ func Start(log *slog.Logger, wg *sync.WaitGroup, serv pb.DebugdServer) {
 	go func() {
 		defer wg.Done()
 
-		grpcLog := log.WithGroup("gRPC")
-		logger.ReplaceGRPCLogger(slog.New(logger.NewLevelHandler(slog.LevelWarn, grpcLog.Handler())))
+		grpcLog := logger.GRPCLogger(log)
+		logger.ReplaceGRPCLogger(grpcLog)
 
 		grpcServer := grpc.NewServer(
 			logger.GetServerStreamInterceptor(grpcLog),

disk-mapper/internal/recoveryserver/recoveryserver.go

@@ -59,7 +59,7 @@ func New(issuer atls.Issuer, factory kmsFactory, log *slog.Logger) *RecoveryServ
 
 	grpcServer := grpc.NewServer(
 		grpc.Creds(atlscredentials.New(issuer, nil)),
-		logger.GetServerStreamInterceptor(log.WithGroup("gRPC")),
+		logger.GetServerStreamInterceptor(logger.GRPCLogger(log)),
 	)
 	recoverproto.RegisterAPIServer(grpcServer, server)
 

internal/logger/grpclogger.go

@@ -19,24 +19,28 @@ import (
 
 func replaceGRPCLogger(log *slog.Logger) {
 	gl := &grpcLogger{
-		logger:    log.With(slog.String("system", "grpc"), slog.Bool("grpc_log", true)),
+		logger:    log,
 		verbosity: 0,
 	}
 	grpclog.SetLoggerV2(gl)
 }
 
 func (l *grpcLogger) log(level slog.Level, args ...interface{}) {
-	var pcs [1]uintptr
-	runtime.Callers(3, pcs[:])
-	r := slog.NewRecord(time.Now(), level, fmt.Sprint(args...), pcs[0])
-	_ = l.logger.Handler().Handle(context.Background(), r)
+	if l.logger.Enabled(context.Background(), level) {
+		var pcs [1]uintptr
+		runtime.Callers(3, pcs[:])
+		r := slog.NewRecord(time.Now(), level, fmt.Sprint(args...), pcs[0])
+		_ = l.logger.Handler().Handle(context.Background(), r)
+	}
 }
 
 func (l *grpcLogger) logf(level slog.Level, format string, args ...interface{}) {
-	var pcs [1]uintptr
-	runtime.Callers(3, pcs[:])
-	r := slog.NewRecord(time.Now(), level, fmt.Sprintf(format, args...), pcs[0])
-	_ = l.logger.Handler().Handle(context.Background(), r)
+	if l.logger.Enabled(context.Background(), level) {
+		var pcs [1]uintptr
+		runtime.Callers(3, pcs[:])
+		r := slog.NewRecord(time.Now(), level, fmt.Sprintf(format, args...), pcs[0])
+		_ = l.logger.Handler().Handle(context.Background(), r)
+	}
 }
 
 type grpcLogger struct {

internal/logger/levelhandler.go

@@ -13,45 +13,45 @@ import (
 
 // LevelHandler copied from the official LevelHandler example in the slog package documentation.
 
-// LevelHandler wraps a Handler with an Enabled method
+// levelHandler wraps a Handler with an Enabled method
 // that returns false for levels below a minimum.
-type LevelHandler struct {
+type levelHandler struct {
 	level   slog.Leveler
 	handler slog.Handler
 }
 
-// NewLevelHandler returns a LevelHandler with the given level.
+// newLevelHandler returns a LevelHandler with the given level.
 // All methods except Enabled delegate to h.
-func NewLevelHandler(level slog.Leveler, h slog.Handler) *LevelHandler {
+func newLevelHandler(level slog.Leveler, h slog.Handler) *levelHandler {
 	// Optimization: avoid chains of LevelHandlers.
-	if lh, ok := h.(*LevelHandler); ok {
+	if lh, ok := h.(*levelHandler); ok {
 		h = lh.Handler()
 	}
-	return &LevelHandler{level, h}
+	return &levelHandler{level, h}
 }
 
 // Enabled implements Handler.Enabled by reporting whether
 // level is at least as large as h's level.
-func (h *LevelHandler) Enabled(_ context.Context, level slog.Level) bool {
+func (h *levelHandler) Enabled(_ context.Context, level slog.Level) bool {
 	return level >= h.level.Level()
 }
 
 // Handle implements Handler.Handle.
-func (h *LevelHandler) Handle(ctx context.Context, r slog.Record) error {
+func (h *levelHandler) Handle(ctx context.Context, r slog.Record) error {
 	return h.handler.Handle(ctx, r)
 }
 
 // WithAttrs implements Handler.WithAttrs.
-func (h *LevelHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
-	return NewLevelHandler(h.level, h.handler.WithAttrs(attrs))
+func (h *levelHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return newLevelHandler(h.level, h.handler.WithAttrs(attrs))
 }
 
 // WithGroup implements Handler.WithGroup.
-func (h *LevelHandler) WithGroup(name string) slog.Handler {
-	return NewLevelHandler(h.level, h.handler.WithGroup(name))
+func (h *levelHandler) WithGroup(name string) slog.Handler {
+	return newLevelHandler(h.level, h.handler.WithGroup(name))
 }
 
 // Handler returns the Handler wrapped by h.
-func (h *LevelHandler) Handler() slog.Handler {
+func (h *levelHandler) Handler() slog.Handler {
 	return h.handler
 }

internal/logger/log.go

@@ -35,6 +35,11 @@ import (
 	"google.golang.org/grpc"
 )
 
+// GRPCLogger returns a logger at warn level for gRPC logging.
+func GRPCLogger(l *slog.Logger) *slog.Logger {
+	return slog.New(newLevelHandler(slog.LevelWarn, l.Handler())).WithGroup("gRPC")
+}
+
 // ReplaceGRPCLogger replaces grpc's internal logger with the given logger.
 func ReplaceGRPCLogger(l *slog.Logger) {
 	replaceGRPCLogger(l)

joinservice/internal/server/server.go

@@ -58,10 +58,11 @@ func New(
 
 // Run starts the gRPC server on the given port, using the provided tlsConfig.
 func (s *Server) Run(creds credentials.TransportCredentials, port string) error {
-	logger.ReplaceGRPCLogger(slog.New(logger.NewLevelHandler(slog.LevelWarn, s.log.Handler())).WithGroup("gRPC"))
+	grpcLog := logger.GRPCLogger(s.log)
+	logger.ReplaceGRPCLogger(grpcLog)
 	grpcServer := grpc.NewServer(
 		grpc.Creds(creds),
-		logger.GetServerUnaryInterceptor(s.log.WithGroup("gRPC")),
+		logger.GetServerUnaryInterceptor(grpcLog),
 	)
 
 	joinproto.RegisterAPIServer(grpcServer, s)

keyservice/internal/server/server.go

@@ -48,9 +48,11 @@ func (s *Server) Run(port string) error {
 		return fmt.Errorf("failed to listen on port %s: %v", port, err)
 	}
 
-	server := grpc.NewServer(logger.GetServerUnaryInterceptor(s.log.WithGroup("gRPC")))
+	grpcLog := logger.GRPCLogger(s.log)
+	logger.ReplaceGRPCLogger(grpcLog)
+
+	server := grpc.NewServer(logger.GetServerUnaryInterceptor(grpcLog))
 	keyserviceproto.RegisterAPIServer(server, s)
-	logger.ReplaceGRPCLogger(slog.New(logger.NewLevelHandler(slog.LevelWarn, s.log.Handler())).WithGroup("gRPC"))
 
 	// start the server
 	s.log.Info(fmt.Sprintf("Starting Constellation key management service on %s", listener.Addr().String()))

upgrade-agent/cmd/main.go

@@ -26,11 +26,7 @@ func main() {
 	verbosity := flag.Int("v", 0, logger.CmdLineVerbosityDescription)
 	flag.Parse()
 	log := logger.NewJSONLogger(logger.VerbosityFromInt(*verbosity)).WithGroup("upgrade-agent")
-	logger.ReplaceGRPCLogger(
-		slog.New(
-			logger.NewLevelHandler(logger.VerbosityFromInt(*verbosity), log.Handler()),
-		).WithGroup("gRPC"),
-	)
+	logger.ReplaceGRPCLogger(logger.GRPCLogger(log))
 
 	handler := file.NewHandler(afero.NewOsFs())
 	server, err := server.New(log, handler)

upgrade-agent/internal/server/server.go

@@ -54,7 +54,7 @@ func New(log *slog.Logger, fileHandler file.Handler) (*Server, error) {
 	}
 
 	grpcServer := grpc.NewServer(
-		logger.GetServerUnaryInterceptor(log.WithGroup("gRPC")),
+		logger.GetServerUnaryInterceptor(logger.GRPCLogger(log)),
 	)
 	upgradeproto.RegisterUpdateServer(grpcServer, server)
 

verify/server/server.go

@@ -56,9 +56,10 @@ func (s *Server) Run(httpListener, grpcListener net.Listener) error {
 	var wg sync.WaitGroup
 	var once sync.Once
 
-	logger.ReplaceGRPCLogger(slog.New(logger.NewLevelHandler(slog.LevelWarn, s.log.Handler()).WithGroup("grpc")))
+	grpcLog := logger.GRPCLogger(s.log)
+	logger.ReplaceGRPCLogger(grpcLog)
 	grpcServer := grpc.NewServer(
-		logger.GetServerUnaryInterceptor(s.log.WithGroup("gRPC")),
+		logger.GetServerUnaryInterceptor(grpcLog),
 		grpc.KeepaliveParams(keepalive.ServerParameters{Time: 15 * time.Second}),
 	)
 	verifyproto.RegisterAPIServer(grpcServer, s)