From c11631ec11ed695d5ed02e57812b52dd15c90dd9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Wei=C3=9Fe?= <66256922+daniel-weisse@users.noreply.github.com> Date: Thu, 29 Aug 2024 10:44:22 +0200 Subject: [PATCH] logging: reduce grpc logging noise (#3329) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Normalize gRPC logs to print at warn level only * Fix grpcLogger level enablement --------- Signed-off-by: Daniel Weiße --- bootstrapper/cmd/bootstrapper/main.go | 6 +---- .../internal/initserver/initserver.go | 2 +- debugd/internal/debugd/server/server.go | 4 +-- .../internal/recoveryserver/recoveryserver.go | 2 +- internal/logger/grpclogger.go | 22 +++++++++------- internal/logger/levelhandler.go | 26 +++++++++---------- internal/logger/log.go | 5 ++++ joinservice/internal/server/server.go | 5 ++-- keyservice/internal/server/server.go | 6 +++-- upgrade-agent/cmd/main.go | 6 +---- upgrade-agent/internal/server/server.go | 2 +- verify/server/server.go | 5 ++-- 12 files changed, 48 insertions(+), 43 deletions(-) diff --git a/bootstrapper/cmd/bootstrapper/main.go b/bootstrapper/cmd/bootstrapper/main.go index 23b2cf474..ebd5a82c5 100644 --- a/bootstrapper/cmd/bootstrapper/main.go +++ b/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() diff --git a/bootstrapper/internal/initserver/initserver.go b/bootstrapper/internal/initserver/initserver.go index 9c2ef36a9..a65a5f8b7 100644 --- a/bootstrapper/internal/initserver/initserver.go +++ b/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) diff --git a/debugd/internal/debugd/server/server.go b/debugd/internal/debugd/server/server.go index a644e7c9d..64bbbc042 100644 --- a/debugd/internal/debugd/server/server.go +++ b/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), diff --git a/disk-mapper/internal/recoveryserver/recoveryserver.go b/disk-mapper/internal/recoveryserver/recoveryserver.go index 5234d2e63..f4a58724e 100644 --- a/disk-mapper/internal/recoveryserver/recoveryserver.go +++ b/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) diff --git a/internal/logger/grpclogger.go b/internal/logger/grpclogger.go index 716b0e495..d67e4af8e 100644 --- a/internal/logger/grpclogger.go +++ b/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 { diff --git a/internal/logger/levelhandler.go b/internal/logger/levelhandler.go index f0e4e1544..201bc90a0 100644 --- a/internal/logger/levelhandler.go +++ b/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 } diff --git a/internal/logger/log.go b/internal/logger/log.go index d8d62b13a..0b6426b6e 100644 --- a/internal/logger/log.go +++ b/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) diff --git a/joinservice/internal/server/server.go b/joinservice/internal/server/server.go index 0b8a98f10..21bb24d67 100644 --- a/joinservice/internal/server/server.go +++ b/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) diff --git a/keyservice/internal/server/server.go b/keyservice/internal/server/server.go index b7517bceb..8ff9bed8a 100644 --- a/keyservice/internal/server/server.go +++ b/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())) diff --git a/upgrade-agent/cmd/main.go b/upgrade-agent/cmd/main.go index fe16caa13..ba2906bc7 100644 --- a/upgrade-agent/cmd/main.go +++ b/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) diff --git a/upgrade-agent/internal/server/server.go b/upgrade-agent/internal/server/server.go index ea18e3d57..1c8ff41b8 100644 --- a/upgrade-agent/internal/server/server.go +++ b/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) diff --git a/verify/server/server.go b/verify/server/server.go index c8d7b2c82..16ab70b07 100644 --- a/verify/server/server.go +++ b/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)