Merge branch 'pks-log-self-contained-middleware' into 'master'

log: Unify setup of the logging interceptors

See merge request https://gitlab.com/gitlab-org/gitaly/-/merge_requests/6408

Merged-by: Toon Claes <toon@gitlab.com>
Approved-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>
Approved-by: Toon Claes <toon@gitlab.com>
Co-authored-by: Patrick Steinhardt <psteinhardt@gitlab.com>

8 files changed, 72 insertions, 105 deletions

diff --git a/internal/gitaly/server/server.go b/internal/gitaly/server/server.go
index 594f9dced..ac7606601 100644
--- a/internal/gitaly/server/server.go
+++ b/internal/gitaly/server/server.go
@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"time"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	grpcmwtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
 	grpcprometheus "github.com/grpc-ecosystem/go-grpc-prometheus"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/server/auth"
@@ -22,7 +21,7 @@ import (
 	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/middleware/statushandler"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/protoregistry"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/helper/fieldextractors"
-	gitalylog "gitlab.com/gitlab-org/gitaly/v16/internal/log"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/structerr"
 	grpccorrelation "gitlab.com/gitlab-org/labkit/correlation/grpc"
 	grpctracing "gitlab.com/gitlab-org/labkit/tracing/grpc"
@@ -95,15 +94,12 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
 		[]grpc.DialOption{client.UnaryInterceptor()},
 	))
 
-	logMsgProducer := grpcmwlogrus.WithMessageProducer(
-		gitalylog.MessageProducer(
-			gitalylog.PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
-			customfieldshandler.FieldsProducer,
-			grpcstats.FieldsProducer,
-			featureflag.FieldsProducer,
-			structerr.FieldsProducer,
-		),
-	)
+	logFieldsProducers := []log.FieldsProducer{
+		customfieldshandler.FieldsProducer,
+		grpcstats.FieldsProducer,
+		featureflag.FieldsProducer,
+		structerr.FieldsProducer,
+	}
 
 	streamServerInterceptors := []grpc.StreamServerInterceptor{
 		grpcmwtags.StreamServerInterceptor(ctxTagOpts...),
@@ -111,12 +107,8 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
 		metadatahandler.StreamInterceptor,
 		grpcprometheus.StreamServerInterceptor,
 		customfieldshandler.StreamInterceptor,
-		s.logger.WithField("component", "gitaly.StreamServerInterceptor").StreamServerInterceptor(
-			grpcmwlogrus.WithTimestampFormat(gitalylog.LogTimestampFormat),
-			logMsgProducer,
-			gitalylog.DeciderOption(),
-		),
-		gitalylog.StreamLogDataCatcherServerInterceptor(),
+		s.logger.WithField("component", "gitaly.StreamServerInterceptor").StreamServerInterceptor(logFieldsProducers...),
+		log.StreamLogDataCatcherServerInterceptor(),
 		sentryhandler.StreamLogHandler,
 		statushandler.Stream, // Should be below LogHandler
 		auth.StreamServerInterceptor(s.cfg.Auth),
@@ -127,12 +119,8 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
 		metadatahandler.UnaryInterceptor,
 		grpcprometheus.UnaryServerInterceptor,
 		customfieldshandler.UnaryInterceptor,
-		s.logger.WithField("component", "gitaly.UnaryServerInterceptor").UnaryServerInterceptor(
-			grpcmwlogrus.WithTimestampFormat(gitalylog.LogTimestampFormat),
-			logMsgProducer,
-			gitalylog.DeciderOption(),
-		),
-		gitalylog.UnaryLogDataCatcherServerInterceptor(),
+		s.logger.WithField("component", "gitaly.UnaryServerInterceptor").UnaryServerInterceptor(logFieldsProducers...),
+		log.UnaryLogDataCatcherServerInterceptor(),
 		sentryhandler.UnaryLogHandler,
 		statushandler.Unary, // Should be below LogHandler
 		auth.UnaryServerInterceptor(s.cfg.Auth),
@@ -163,9 +151,9 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
 	unaryServerInterceptors = append(unaryServerInterceptors, cfg.unaryInterceptors...)
 
 	serverOptions := []grpc.ServerOption{
-		grpc.StatsHandler(gitalylog.PerRPCLogHandler{
+		grpc.StatsHandler(log.PerRPCLogHandler{
 			Underlying:     &grpcstats.PayloadBytes{},
-			FieldProducers: []gitalylog.FieldsProducer{grpcstats.FieldsProducer},
+			FieldProducers: []log.FieldsProducer{grpcstats.FieldsProducer},
 		}),
 		grpc.Creds(lm),
 		grpc.ChainStreamInterceptor(streamServerInterceptors...),
diff --git a/internal/grpc/grpcstats/stats_test.go b/internal/grpc/grpcstats/stats_test.go
index b3bfa881c..5a86ba2d0 100644
--- a/internal/grpc/grpcstats/stats_test.go
+++ b/internal/grpc/grpcstats/stats_test.go
@@ -8,7 +8,6 @@ import (
 	"sync"
 	"testing"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/client"
@@ -62,25 +61,11 @@ func TestPayloadBytes(t *testing.T) {
 			FieldProducers: []log.FieldsProducer{FieldsProducer},
 		}),
 		grpc.ChainUnaryInterceptor(
-			logger.UnaryServerInterceptor(
-				grpcmwlogrus.WithMessageProducer(
-					log.MessageProducer(
-						log.PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
-						FieldsProducer,
-					),
-				),
-			),
+			logger.UnaryServerInterceptor(FieldsProducer),
 			log.UnaryLogDataCatcherServerInterceptor(),
 		),
 		grpc.ChainStreamInterceptor(
-			logger.StreamServerInterceptor(
-				grpcmwlogrus.WithMessageProducer(
-					log.MessageProducer(
-						log.PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
-						FieldsProducer,
-					),
-				),
-			),
+			logger.StreamServerInterceptor(FieldsProducer),
 			log.StreamLogDataCatcherServerInterceptor(),
 		),
 	}
diff --git a/internal/grpc/middleware/customfieldshandler/customfields_handler_test.go b/internal/grpc/middleware/customfieldshandler/customfields_handler_test.go
index 15895b7ba..2ea6464ae 100644
--- a/internal/grpc/middleware/customfieldshandler/customfields_handler_test.go
+++ b/internal/grpc/middleware/customfieldshandler/customfields_handler_test.go
@@ -6,7 +6,6 @@ import (
 	"net"
 	"testing"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/catfile"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
@@ -15,6 +14,7 @@ import (
 	"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/service/ref"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/transaction"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/backchannel"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/grpcstats"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper/testcfg"
@@ -27,20 +27,20 @@ import (
 func createNewServer(t *testing.T, cfg config.Cfg, logger log.Logger) *grpc.Server {
 	t.Helper()
 
-	logrusEntry := logger.WithField("test", t.Name())
+	logger = logger.WithField("test", t.Name())
 
 	opts := []grpc.ServerOption{
+		grpc.StatsHandler(log.PerRPCLogHandler{
+			Underlying:     &grpcstats.PayloadBytes{},
+			FieldProducers: []log.FieldsProducer{grpcstats.FieldsProducer},
+		}),
 		grpc.ChainStreamInterceptor(
 			StreamInterceptor,
-			logrusEntry.StreamServerInterceptor(
-				grpcmwlogrus.WithTimestampFormat(log.LogTimestampFormat),
-				grpcmwlogrus.WithMessageProducer(log.MessageProducer(grpcmwlogrus.DefaultMessageProducer, FieldsProducer))),
+			logger.StreamServerInterceptor(FieldsProducer),
 		),
 		grpc.ChainUnaryInterceptor(
 			UnaryInterceptor,
-			logrusEntry.UnaryServerInterceptor(
-				grpcmwlogrus.WithTimestampFormat(log.LogTimestampFormat),
-				grpcmwlogrus.WithMessageProducer(log.MessageProducer(grpcmwlogrus.DefaultMessageProducer, FieldsProducer))),
+			logger.UnaryServerInterceptor(FieldsProducer),
 		),
 	}
 
diff --git a/internal/grpc/middleware/featureflag/featureflag_handler_test.go b/internal/grpc/middleware/featureflag/featureflag_handler_test.go
index 45eb31d80..e398cd541 100644
--- a/internal/grpc/middleware/featureflag/featureflag_handler_test.go
+++ b/internal/grpc/middleware/featureflag/featureflag_handler_test.go
@@ -5,9 +5,9 @@ import (
 	"net"
 	"testing"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/featureflag"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/grpcstats"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/structerr"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
@@ -37,17 +37,11 @@ func TestFeatureFlagLogs(t *testing.T) {
 
 	service := &mockService{}
 	server := grpc.NewServer(
-		grpc.ChainUnaryInterceptor(
-			grpcmwlogrus.UnaryServerInterceptor(
-				logger.LogrusEntry(), //nolint:staticcheck
-				grpcmwlogrus.WithMessageProducer(
-					log.MessageProducer(
-						grpcmwlogrus.DefaultMessageProducer,
-						FieldsProducer,
-					),
-				),
-			),
-		),
+		grpc.StatsHandler(log.PerRPCLogHandler{
+			Underlying:     &grpcstats.PayloadBytes{},
+			FieldProducers: []log.FieldsProducer{grpcstats.FieldsProducer},
+		}),
+		grpc.ChainUnaryInterceptor(logger.UnaryServerInterceptor(FieldsProducer)),
 	)
 	grpc_testing.RegisterTestServiceServer(server, service)
 
diff --git a/internal/log/logger.go b/internal/log/logger.go
index 753ac3c30..af7579f30 100644
--- a/internal/log/logger.go
+++ b/internal/log/logger.go
@@ -23,8 +23,8 @@ type Logger interface {
 	Warn(msg string)
 	Error(msg string)
 
-	StreamServerInterceptor(...grpcmwlogrus.Option) grpc.StreamServerInterceptor
-	UnaryServerInterceptor(...grpcmwlogrus.Option) grpc.UnaryServerInterceptor
+	StreamServerInterceptor(...FieldsProducer) grpc.StreamServerInterceptor
+	UnaryServerInterceptor(...FieldsProducer) grpc.UnaryServerInterceptor
 }
 
 // LogrusLogger is an implementation of the Logger interface that is implemented via a `logrus.FieldLogger`.
@@ -87,13 +87,27 @@ func (l LogrusLogger) ToContext(ctx context.Context) context.Context {
 }
 
 // StreamServerInterceptor creates a gRPC interceptor that generates log messages for streaming RPC calls.
-func (l LogrusLogger) StreamServerInterceptor(opts ...grpcmwlogrus.Option) grpc.StreamServerInterceptor {
-	return grpcmwlogrus.StreamServerInterceptor(l.entry, opts...)
+func (l LogrusLogger) StreamServerInterceptor(fieldsProducers ...FieldsProducer) grpc.StreamServerInterceptor {
+	return grpcmwlogrus.StreamServerInterceptor(l.entry,
+		grpcmwlogrus.WithTimestampFormat(LogTimestampFormat),
+		grpcmwlogrus.WithMessageProducer(MessageProducer(
+			PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
+			fieldsProducers...,
+		)),
+		DeciderOption(),
+	)
 }
 
 // UnaryServerInterceptor creates a gRPC interceptor that generates log messages for unary RPC calls.
-func (l LogrusLogger) UnaryServerInterceptor(opts ...grpcmwlogrus.Option) grpc.UnaryServerInterceptor {
-	return grpcmwlogrus.UnaryServerInterceptor(l.entry, opts...)
+func (l LogrusLogger) UnaryServerInterceptor(fieldsProducers ...FieldsProducer) grpc.UnaryServerInterceptor {
+	return grpcmwlogrus.UnaryServerInterceptor(l.entry,
+		grpcmwlogrus.WithTimestampFormat(LogTimestampFormat),
+		grpcmwlogrus.WithMessageProducer(MessageProducer(
+			PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
+			fieldsProducers...,
+		)),
+		DeciderOption(),
+	)
 }
 
 // FromContext extracts the logger from the context. If no logger has been injected then this will return a discarding
diff --git a/internal/praefect/delete_object_pool_test.go b/internal/praefect/delete_object_pool_test.go
index 573bbb3b7..bc77a26aa 100644
--- a/internal/praefect/delete_object_pool_test.go
+++ b/internal/praefect/delete_object_pool_test.go
@@ -4,9 +4,9 @@ import (
 	"context"
 	"testing"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/grpcstats"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/praefect/datastore"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
@@ -71,9 +71,13 @@ func TestDeleteObjectPoolHandler(t *testing.T) {
 	praefectLn, praefectAddr := testhelper.GetLocalhostListener(t)
 	logger := testhelper.NewLogger(t)
 	hook := testhelper.AddLoggerHook(logger)
-	praefectSrv := grpc.NewServer(grpc.ChainStreamInterceptor(
-		logger.StreamServerInterceptor(grpcmwlogrus.WithTimestampFormat(log.LogTimestampFormat)),
-	))
+	praefectSrv := grpc.NewServer(
+		grpc.StatsHandler(log.PerRPCLogHandler{
+			Underlying:     &grpcstats.PayloadBytes{},
+			FieldProducers: []log.FieldsProducer{grpcstats.FieldsProducer},
+		}),
+		grpc.ChainStreamInterceptor(logger.StreamServerInterceptor()),
+	)
 	praefectSrv.RegisterService(&grpc.ServiceDesc{
 		ServiceName: "gitaly.ObjectPoolService",
 		HandlerType: (*interface{})(nil),
diff --git a/internal/praefect/server.go b/internal/praefect/server.go
index 823ed02ec..0ebee1420 100644
--- a/internal/praefect/server.go
+++ b/internal/praefect/server.go
@@ -7,7 +7,6 @@ package praefect
 import (
 	"time"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	grpcmwtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
 	grpcprometheus "github.com/grpc-ecosystem/go-grpc-prometheus"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/server/auth"
@@ -42,20 +41,19 @@ import (
 	"google.golang.org/grpc/keepalive"
 )
 
+var logFieldsProducers = []log.FieldsProducer{
+	structerr.FieldsProducer,
+}
+
 // NewBackchannelServerFactory returns a ServerFactory that serves the RefTransactionServer on the backchannel
 // connection.
 func NewBackchannelServerFactory(logger log.Logger, refSvc gitalypb.RefTransactionServer, registry *sidechannel.Registry) backchannel.ServerFactory {
-	logMsgProducer := log.MessageProducer(
-		log.PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
-		structerr.FieldsProducer,
-	)
-
 	return func() backchannel.Server {
 		lm := listenmux.New(insecure.NewCredentials())
 		lm.Register(sidechannel.NewServerHandshaker(registry))
 		srv := grpc.NewServer(
 			grpc.ChainUnaryInterceptor(
-				commonUnaryServerInterceptors(logger.WithField("component", "backchannel.PraefectServer"), logMsgProducer)...,
+				commonUnaryServerInterceptors(logger.WithField("component", "backchannel.PraefectServer"))...,
 			),
 			grpc.Creds(lm),
 		)
@@ -65,17 +63,13 @@ func NewBackchannelServerFactory(logger log.Logger, refSvc gitalypb.RefTransacti
 	}
 }
 
-func commonUnaryServerInterceptors(logger log.Logger, messageProducer grpcmwlogrus.MessageProducer) []grpc.UnaryServerInterceptor {
+func commonUnaryServerInterceptors(logger log.Logger) []grpc.UnaryServerInterceptor {
 	return []grpc.UnaryServerInterceptor{
 		grpcmwtags.UnaryServerInterceptor(ctxtagsInterceptorOption()),
 		grpccorrelation.UnaryServerCorrelationInterceptor(), // Must be above the metadata handler
 		metadatahandler.UnaryInterceptor,
 		grpcprometheus.UnaryServerInterceptor,
-		logger.UnaryServerInterceptor(
-			grpcmwlogrus.WithTimestampFormat(log.LogTimestampFormat),
-			grpcmwlogrus.WithMessageProducer(messageProducer),
-			log.DeciderOption(),
-		),
+		logger.UnaryServerInterceptor(logFieldsProducers...),
 		sentryhandler.UnaryLogHandler,
 		statushandler.Unary, // Should be below LogHandler
 		grpctracing.UnaryServerTracingInterceptor(),
@@ -123,13 +117,8 @@ func NewGRPCServer(
 		opt(&serverCfg)
 	}
 
-	logMsgProducer := log.MessageProducer(
-		log.PropagationMessageProducer(grpcmwlogrus.DefaultMessageProducer),
-		structerr.FieldsProducer,
-	)
-
 	unaryInterceptors := append(
-		commonUnaryServerInterceptors(deps.Logger.WithField("component", "praefect.UnaryServerInterceptor"), logMsgProducer),
+		commonUnaryServerInterceptors(deps.Logger.WithField("component", "praefect.UnaryServerInterceptor")),
 		middleware.MethodTypeUnaryInterceptor(deps.Registry, deps.Logger),
 		auth.UnaryServerInterceptor(deps.Config.Auth),
 	)
@@ -141,11 +130,7 @@ func NewGRPCServer(
 		middleware.MethodTypeStreamInterceptor(deps.Registry, deps.Logger),
 		metadatahandler.StreamInterceptor,
 		grpcprometheus.StreamServerInterceptor,
-		deps.Logger.WithField("component", "praefect.StreamServerInterceptor").StreamServerInterceptor(
-			grpcmwlogrus.WithTimestampFormat(log.LogTimestampFormat),
-			grpcmwlogrus.WithMessageProducer(logMsgProducer),
-			log.DeciderOption(),
-		),
+		deps.Logger.WithField("component", "praefect.StreamServerInterceptor").StreamServerInterceptor(logFieldsProducers...),
 		sentryhandler.StreamLogHandler,
 		statushandler.Stream, // Should be below LogHandler
 		grpctracing.StreamServerTracingInterceptor(),
diff --git a/internal/testhelper/testserver/structerr_interceptors_test.go b/internal/testhelper/testserver/structerr_interceptors_test.go
index a0453e7ed..7a057fe39 100644
--- a/internal/testhelper/testserver/structerr_interceptors_test.go
+++ b/internal/testhelper/testserver/structerr_interceptors_test.go
@@ -7,8 +7,8 @@ import (
 	"net"
 	"testing"
 
-	grpcmwlogrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
 	"github.com/stretchr/testify/require"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/grpc/grpcstats"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/structerr"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
@@ -94,15 +94,12 @@ func TestFieldsProducer(t *testing.T) {
 
 	service := &mockService{}
 	server := grpc.NewServer(
+		grpc.StatsHandler(log.PerRPCLogHandler{
+			Underlying:     &grpcstats.PayloadBytes{},
+			FieldProducers: []log.FieldsProducer{grpcstats.FieldsProducer},
+		}),
 		grpc.ChainUnaryInterceptor(
-			logger.UnaryServerInterceptor(
-				grpcmwlogrus.WithMessageProducer(
-					log.MessageProducer(
-						grpcmwlogrus.DefaultMessageProducer,
-						structerr.FieldsProducer,
-					),
-				),
-			),
+			logger.UnaryServerInterceptor(structerr.FieldsProducer),
 		),
 	)
 	grpc_testing.RegisterTestServiceServer(server, service)