RSDK-9150 - Client log interceptor should not use zap.Logger

logger.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/edaniels/golog"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 )
 
 // Logger is used various parts of the package for informational/debugging purposes.
@@ -24,6 +25,7 @@ type ILogger interface {
 // ZapCompatibleLogger is a basic logging interface for golog.Logger (alias for *zap.SugaredLogger) and RDK loggers.
 type ZapCompatibleLogger interface {
 	Desugar() *zap.Logger
+	Level() zapcore.Level
 
 	Debug(args ...interface{})
 	Debugf(template string, args ...interface{})

logger_test.go

@@ -6,6 +6,7 @@
 
 	"github.com/edaniels/golog"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"go.viam.com/test"
 )
 
@@ -64,6 +65,10 @@
 func (m *InvalidLogger) Fatalw(msg string, keysAndValues ...interface{}) {
 }
 
+func (m *InvalidLogger) Level() zapcore.Level {
+	return zapcore.Level(zap.DebugLevel)
+}
+
 // MockLogger fulfills the ZapCompatibleLogger interface by extending InvalidLogger with a Sublogger() method. This type
 // is used to simulate calling utils.Sublogger() on an RDK logger.
 type MockLogger struct {
@@ -79,6 +84,10 @@
 	m.Name = "WithFields called"
 }
 
+func (m *MockLogger) Level() zapcore.Level {
+	return zapcore.Level(zap.DebugLevel)
+}
+
 func TestSubloggerWithZapLogger(t *testing.T) {
 	logger := golog.NewTestLogger(t)
 	sublogger := Sublogger(logger, "sub")

rpc/wrtc_client_channel.go

@@ -10,10 +10,9 @@
 
 	grpc_logging "github.com/grpc-ecosystem/go-grpc-middleware/logging"
 	grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
-	"github.com/grpc-ecosystem/go-grpc-middleware/logging/zap/ctxzap"
 	"github.com/pion/webrtc/v4"
+
 	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/metadata"
 	"google.golang.org/protobuf/proto"
@@ -101,11 +100,10 @@
 	reply interface{},
 	opts ...grpc.CallOption,
 ) error {
-	fields := newClientLoggerFields(method)
 	startTime := time.Now()
 	err := ch.invokeWithInterceptor(ctx, method, args, reply, opts...)
-	newCtx := ctxzap.ToContext(ctx, ch.webrtcBaseChannel.logger.Desugar().With(fields...))
-	logFinalClientLine(newCtx, startTime, err, "finished client unary call")
+	loggerWithFields := utils.AddFieldsToLogger(ch.webrtcBaseChannel.logger, newClientLoggerFields(method)...)
+	logFinalClientLine(loggerWithFields, startTime, err, "finished client unary call")
 	return err
 }
 
@@ -189,11 +187,10 @@
 	method string,
 	opts ...grpc.CallOption,
 ) (grpc.ClientStream, error) {
-	fields := newClientLoggerFields(method)
 	startTime := time.Now()
 	clientStream, err := ch.streamWithInterceptor(ctx, method)
-	newCtx := ctxzap.ToContext(ctx, ch.webrtcBaseChannel.logger.Desugar().With(fields...))
-	logFinalClientLine(newCtx, startTime, err, "finished client streaming call")
+	loggerWithFields := utils.AddFieldsToLogger(ch.webrtcBaseChannel.logger, newClientLoggerFields(method)...)
+	logFinalClientLine(loggerWithFields, startTime, err, "finished client streaming call")
 	return clientStream, err
 }
 
@@ -336,29 +333,44 @@
 
 // taken from
 // https://github.com/grpc-ecosystem/go-grpc-middleware/blob/560829fc74fcf9a69b7ab01d484f8b8961dc734b/logging/zap/client_interceptors.go
-
-func logFinalClientLine(ctx context.Context, startTime time.Time, err error, msg string) {
+func logFinalClientLine(logger utils.ZapCompatibleLogger, startTime time.Time, err error, msg string) {
 	code := grpc_logging.DefaultErrorToCode(err)
 	level := grpc_zap.DefaultCodeToLevel(code)
+
+	// this calculation is done because duration.Milliseconds() will return an integer, which is not precise enough.
+	duration := float32(time.Since(startTime).Nanoseconds()/1000) / 1000
+	fields := []any{}
 	if err == nil {
 		level = zap.DebugLevel
+	} else {
+		fields = append(fields, "error", err)
+	}
+	fields = append(fields, "grpc.code", code.String(), "grpc.time_ms", duration)
+
+	if logger.Level().Enabled(level) {
+		// cases for all outputs of grpc_zap.DefaultCodeToLevel
+		switch level {
+		case zap.DebugLevel:
+			logger.Debugw(msg, fields...)
+		case zap.InfoLevel:
+			logger.Infow(msg, fields...)
+		case zap.ErrorLevel:
+			logger.Errorw(msg, fields...)
+		case zap.WarnLevel:
+			fallthrough
+		default:
+			logger.Warnw(msg, fields...)
+		}
 	}
-	duration := grpc_zap.DefaultDurationToField(time.Since(startTime))
-	grpc_zap.DefaultMessageProducer(ctx, msg, level, code, err, duration)
 }
 
-var (
-	clientField = zap.String("span.kind", "client")
-	systemField = zap.String("system", "grpc")
-)
-
-func newClientLoggerFields(fullMethodString string) []zapcore.Field {
+func newClientLoggerFields(fullMethodString string) []any {
 	service := path.Dir(fullMethodString)[1:]
 	method := path.Base(fullMethodString)
-	return []zapcore.Field{
-		systemField,
-		clientField,
-		zap.String("grpc.service", service),
-		zap.String("grpc.method", method),
+	return []any{
+		"span.kind", "client",
+		"system", "grpc",
+		"grpc.service", service,
+		"grpc.method", method,
 	}
 }