Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 5 commits into from
Oct 28, 2024
Merged

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

Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
380000c
fix
cheukt Oct 25, 2024
df59cdf
lint
cheukt Oct 25, 2024
5c58e22
lint
cheukt Oct 25, 2024
735945f
Merge branch 'main' into fix-client-logs
cheukt Oct 28, 2024
48190b0
some pr feedback
cheukt Oct 28, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
51 changes: 29 additions & 22 deletions rpc/wrtc_client_channel.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,6 @@ import (

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/viamrobotics/webrtc/v3"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
Expand Down Expand Up @@ -101,11 +100,10 @@ func (ch *webrtcClientChannel) Invoke(
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
}

Expand Down Expand Up @@ -189,11 +187,10 @@ func (ch *webrtcClientChannel) NewStream(
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
}

Expand Down Expand Up @@ -336,29 +333,39 @@ func (ch *webrtcClientChannel) writeReset(stream *webrtcpb.Stream) error {

// 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)
// grpc_zap.DefaultCodeToLevel will only return zap.DebugLevel, zap.InfoLevel, zap.ErrorLevel, zap.WarnLevel
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, zap.DPanicLevel, zap.PanicLevel, zap.FatalLevel, zapcore.InvalidLevel:
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",
Copy link
Member Author

@cheukt cheukt Oct 25, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

note: rdk loggers' WithFields() do not play nicely with zapcore.Field at all. which probably means that zap loggers will not play nicely with AddFieldsToLogger

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for filing that ticket; sounds like zap loggers will almost certainly not play nicely with AddFieldsToLogger. But, from the sample "after changes" output you put in the PR description, the added fields do seem to be getting added. Is that right?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yep, but the way they're getting passed in now is different - no longer a list of zap.Fields

"system", "grpc",
"grpc.service", service,
"grpc.method", method,
}
}
Loading