RSDK-9097: Fix zapcore.Field <-> Proto roundtrip for error types. (#4478

)

logging/proto_conversions.go

@@ -25,6 +25,18 @@ func FieldToProto(field zap.Field) (*structpb.Struct, error) {
 		field.String = fmt.Sprintf("%f", math.Float64frombits(uint64(field.Integer)))
 	}
 
+	// RSDK-9097: Calling FieldToProto goes through a marshal -> unmarshal sequence. Marshaling
+	// errors as-is will give us a zapcore type of error, but an empty `String` and an empty object
+	// for the `Interface`. Unmarshalling in `FieldFromProto` subsequently creates a zapcore.Field
+	// object with the "error" type, but no underlying `Interface`. Using the zapcore JSONEncoder
+	// fails when the underlying empty `Interface` is cast to an `error`.
+	//
+	// We work around this in the short-term by just turning errors into strings.
+	if field.Type == zapcore.ErrorType {
+		field.Type = zapcore.StringType
+		field.String = field.Interface.(error).Error()
+	}
+
 	return protoutils.StructToStructPb(field)
 }
 
@@ -39,6 +51,7 @@ func FieldFromProto(field *structpb.Struct) (zap.Field, error) {
 	if err := json.Unmarshal(fieldJSON, &zf); err != nil {
 		return zap.Field{}, err
 	}
+
 	return zf, err
 }
 

logging/proto_conversions_test.go

@@ -1,6 +1,7 @@
 package logging
 
 import (
+	"errors"
 	"math"
 	"testing"
 	"time"
@@ -100,9 +101,9 @@ func TestFieldConversion(t *testing.T) {
 		},
 		{
 			field: zap.Field{
-				Key:    "error",
-				Type:   zapcore.ErrorType,
-				String: "error message",
+				Key:       "error",
+				Type:      zapcore.ErrorType,
+				Interface: errors.New("error message"),
 			},
 			// Error types retain only their message. Stacks are contained in log.Stack.
 			expectedVal: "error message",
@@ -143,3 +144,67 @@ func TestFieldConversion(t *testing.T) {
 		})
 	}
 }
+
+type writeParams struct {
+	Entry  zapcore.Entry
+	Fields []zapcore.Field
+}
+
+type replayAppender struct {
+	logs []writeParams
+}
+
+func (app *replayAppender) Write(entry zapcore.Entry, fields []zapcore.Field) error {
+	app.logs = append(app.logs, writeParams{entry, fields})
+	return nil
+}
+
+func (app *replayAppender) Sync() error {
+	return nil
+}
+
+func TestErrorTypeRoundtrip(t *testing.T) {
+	testLogger := NewTestLogger(t)
+	_ = testLogger
+
+	// Create a logger with a special appender to capture the exact `zapcore.Field` objects being
+	// passed around.
+	replayLogger := NewBlankLogger("proto")
+
+	appender := &replayAppender{}
+	replayLogger.AddAppender(appender)
+
+	// Log a `w` line with an error value.
+	replayLogger.Infow("log message", "err", errors.New("error message"))
+	testLogger.Infof("LogEntry: %#v", appender.logs)
+
+	test.That(t, len(appender.logs), test.ShouldEqual, 1)
+	test.That(t, len(appender.logs[0].Fields), test.ShouldEqual, 1)
+
+	// Grab the `err: error` field off the replay appender.
+	field := appender.logs[0].Fields[0]
+	testLogger.Infof("Field: %#v", field)
+
+	// Demonstrate that the encoder is happy with this raw field.
+	jsonEncoder := zapcore.NewJSONEncoder(zapcore.EncoderConfig{SkipLineEnding: true})
+	_, err := jsonEncoder.EncodeEntry(zapcore.Entry{}, []zapcore.Field{field})
+	test.That(t, err, test.ShouldBeNil)
+
+	// Serialize the field to proto.
+	proto, err := FieldToProto(field)
+	test.That(t, err, test.ShouldBeNil)
+
+	// Deserialize the proto back into a zapcore.Field.
+	testLogger.Infof("Proto: %#v", proto)
+	roundTrip, err := FieldFromProto(proto)
+	test.That(t, err, test.ShouldBeNil)
+	testLogger.Infof("Roundtrip: %#v", roundTrip)
+
+	// Prior to RSDK-9097, this encoder step would fail. As we've created a zapcore.Field.Type ==
+	// error. But with an empty zapcore.Field.Interface.
+	_, err = jsonEncoder.EncodeEntry(zapcore.Entry{}, []zapcore.Field{roundTrip})
+	test.That(t, err, test.ShouldBeNil)
+
+	// TODO: Do better by preserving the error type
+	// test.That(t, roundTrip.Type, test.ShouldEqual, zapcore.ErrorType)
+}

module/testmodule/main.go

@@ -179,7 +179,7 @@ func (h *helper) DoCommand(ctx context.Context, req map[string]interface{}) (map
 		msg := req["msg"].(string)
 		switch level {
 		case logging.DEBUG:
-			h.logger.CDebugw(ctx, msg, "foo", "bar")
+			h.logger.CDebugw(ctx, msg, "foo", "bar", "err", errors.New("crash me"))
 		case logging.INFO:
 			h.logger.CInfow(ctx, msg, "foo", "bar")
 		case logging.WARN: