RSDK-13559: Support receiving LogRequest.Caller information.

logging/net_appender.go

@@ -192,14 +192,24 @@
 	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 @@
 		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
 	}

logging/proto_conversions.go

@@ -40,6 +40,27 @@
 	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)

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
 }
 

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)

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