diff --git a/logging/proto_conversions.go b/logging/proto_conversions.go index c5dfbd5f2d8..c5f6926c663 100644 --- a/logging/proto_conversions.go +++ b/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 } diff --git a/logging/proto_conversions_test.go b/logging/proto_conversions_test.go index a7a75bc1e82..a3ade1248e5 100644 --- a/logging/proto_conversions_test.go +++ b/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) +} diff --git a/module/testmodule/main.go b/module/testmodule/main.go index b9b09a8f33d..e622b318203 100644 --- a/module/testmodule/main.go +++ b/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: