From e8765cef396a147800fd0b346d7179b61e009fb9 Mon Sep 17 00:00:00 2001 From: Dan Gottlieb Date: Mon, 20 Apr 2026 13:25:33 -0400 Subject: [PATCH] RSDK-13559: Support receiving `LogRequest.Caller` information. --- logging/net_appender.go | 23 +++++++++++++---------- logging/proto_conversions.go | 21 +++++++++++++++++++++ robot/client/client.go | 10 +++++++--- robot/server/server.go | 8 +++++++- robot/server/server_test.go | 24 ++++++++++++++++++++++-- 5 files changed, 70 insertions(+), 16 deletions(-) diff --git a/logging/net_appender.go b/logging/net_appender.go index c3e5a77049d..9995921a624 100644 --- a/logging/net_appender.go +++ b/logging/net_appender.go @@ -192,14 +192,24 @@ func (nl *NetAppender) close(exitIfNoProgressIters, totalIters int, sleepFn func nl.remoteWriter.close() } -// Mirrors zapcore.EntryCaller but leaves out the pointer address. -type wrappedEntryCaller struct { +// Mirrors zapcore.EntryCaller but leaves out the PC member. This is because the zapcore.EntryCaller +// uses a `uintptr` for the program counter/instruction pointer which is not a valid proto type. +type WrappedEntryCaller struct { Defined bool File string Line int Function string } +func WrapEntryCaller(ec zapcore.EntryCaller) WrappedEntryCaller { + return WrappedEntryCaller{ + Defined: ec.Defined, + File: ec.File, + Line: ec.Line, + Function: ec.Function, + } +} + // newInternalLogEntry creates a minimal zapcore.Entry that can be used with NetAppender.Write. func newInternalLogEntry(level zapcore.Level, message string) zapcore.Entry { return zapcore.Entry{ @@ -222,14 +232,7 @@ func (nl *NetAppender) Write(e zapcore.Entry, f []zapcore.Field) error { Stack: e.Stack, } - wc := wrappedEntryCaller{ - Defined: e.Caller.Defined, - File: e.Caller.File, - Line: e.Caller.Line, - Function: e.Caller.Function, - } - - caller, err := protoutils.StructToStructPb(wc) + caller, err := protoutils.StructToStructPb(WrapEntryCaller(e.Caller)) if err != nil { return err } diff --git a/logging/proto_conversions.go b/logging/proto_conversions.go index 6f1c6192e42..d181d726cc6 100644 --- a/logging/proto_conversions.go +++ b/logging/proto_conversions.go @@ -40,6 +40,27 @@ func FieldToProto(field zap.Field) (*structpb.Struct, error) { return protoutils.StructToStructPb(field) } +func CallerFromProto(caller *structpb.Struct) zapcore.EntryCaller { + ret := zapcore.EntryCaller{} + if defined, ok := caller.Fields["Defined"]; ok { + ret.Defined = defined.GetBoolValue() + } + + if file, ok := caller.Fields["File"]; ok { + ret.File = file.GetStringValue() + } + + if fn, ok := caller.Fields["Function"]; ok { + ret.Function = fn.GetStringValue() + } + + if ln, ok := caller.Fields["Line"]; ok { + ret.Line = int(ln.GetNumberValue()) + } + + return ret +} + // FieldFromProto unmarshals a proto-encoded zap.Field. func FieldFromProto(field *structpb.Struct) (zap.Field, error) { fieldJSON, err := json.Marshal(field) diff --git a/robot/client/client.go b/robot/client/client.go index 9a28cf84f6d..a022d26ad7d 100644 --- a/robot/client/client.go +++ b/robot/client/client.go @@ -1149,7 +1149,10 @@ func (rc *RobotClient) StopAll(ctx context.Context, extra map[resource.Name]map[ // Log sends a log entry to the server. To be used by Golang modules wanting to // log over gRPC and not by normal Golang SDK clients. func (rc *RobotClient) Log(ctx context.Context, log zapcore.Entry, fields []zap.Field) error { - message := fmt.Sprintf("%v\t%v", log.Caller.TrimmedPath(), log.Message) + caller, err := protoutils.StructToStructPb(logging.WrapEntryCaller(log.Caller)) + if err != nil { + caller = nil + } fieldsP := make([]*structpb.Struct, 0, len(fields)) for _, field := range fields { @@ -1167,7 +1170,8 @@ func (rc *RobotClient) Log(ctx context.Context, log zapcore.Entry, fields []zap. Level: log.Level.String(), Time: timestamppb.New(log.Time), LoggerName: log.LoggerName, - Message: message, + Message: log.Message, + Caller: caller, // Leave out Caller; Caller is already in Message field above. We put // the Caller in Message as other languages may also do this in the // future. We do not want other languages to have to force their caller @@ -1177,7 +1181,7 @@ func (rc *RobotClient) Log(ctx context.Context, log zapcore.Entry, fields []zap. }}, } - _, err := rc.client.Log(ctx, logRequest) + _, err = rc.client.Log(ctx, logRequest) return err } diff --git a/robot/server/server.go b/robot/server/server.go index 16b9d36f989..3a16a16087c 100644 --- a/robot/server/server.go +++ b/robot/server/server.go @@ -446,9 +446,15 @@ func (s *Server) Log(ctx context.Context, req *pb.LogRequest) (*pb.LogResponse, Time: time.Now(), LoggerName: log.LoggerName, Message: log.Message, - // `Caller` is already encoded in `Message` above // `Stack` is not included } + + // Initially, `Caller` was encoded in the `log.Message`. We have since started preserving the + // structure. + if log.Caller != nil { + zEntry.Caller = logging.CallerFromProto(log.Caller) + } + fields := make([]zapcore.Field, 0, len(log.Fields)*2) for _, fieldP := range log.Fields { field, err := logging.FieldFromProto(fieldP) diff --git a/robot/server/server_test.go b/robot/server/server_test.go index 93d99ac86b5..97883380e90 100644 --- a/robot/server/server_test.go +++ b/robot/server/server_test.go @@ -35,6 +35,7 @@ import ( "go.viam.com/rdk/session" "go.viam.com/rdk/spatialmath" "go.viam.com/rdk/testutils/inject" + utilsproto "go.viam.com/utils/protoutils" ) var emptyResources = &pb.ResourceNamesResponse{ @@ -647,17 +648,36 @@ func TestModuleLogTimestamp(t *testing.T) { injectRobot.LoggerFunc = func() logging.Logger { return logger } srv := server.New(injectRobot) - _, err := srv.Log(context.Background(), &pb.LogRequest{ + // Piggy back this test for roundtripping of the `Caller` field. + caller, err := utilsproto.StructToStructPb(logging.WrapEntryCaller(zapcore.EntryCaller{ + Defined: true, + PC: 0, + File: "some_filename.go", + Line: 67, + Function: "TestModuleLogTimestamp", + })) + test.That(t, err, test.ShouldBeNil) + + _, err = srv.Log(context.Background(), &pb.LogRequest{ Logs: []*commonpb.LogEntry{{ Level: "info", Time: timestamppb.New(time.Now().Add(-2 * time.Hour)), Message: "old log contains `log_ts`", + Caller: caller, }}, }) test.That(t, err, test.ShouldBeNil) // Dan: This half of the test works "in the favor" of a race. If this fails, there's a real // bug/change in expected behavior. - test.That(t, logs.FilterFieldKey("log_ts").Len(), test.ShouldEqual, 1) + logsWithTS := logs.FilterFieldKey("log_ts") + test.That(t, logsWithTS.Len(), test.ShouldEqual, 1) + + // Assert that the caller roundtripped. + deserializedCaller := logsWithTS.All()[0].Caller + test.That(t, deserializedCaller.Defined, test.ShouldBeTrue) + test.That(t, deserializedCaller.File, test.ShouldEqual, "some_filename.go") + test.That(t, deserializedCaller.Line, test.ShouldEqual, 67) + test.That(t, deserializedCaller.Function, test.ShouldEqual, "TestModuleLogTimestamp") logs.TakeAll() // clear logs