log: Auto wrap baseplate.Error in logs

internal/thriftint/baseplate_error.go

@@ -0,0 +1,93 @@
+// Package thriftint provides internal thrift related helpers to avoid circular
+// dependencies.
+package thriftint
+
+import (
+	"errors"
+	"fmt"
+	"strings"
+
+	"github.com/apache/thrift/lib/go/thrift"
+
+	"github.com/reddit/baseplate.go/internal/gen-go/reddit/baseplate"
+)
+
+// baseplateError defines the interface of thrift compiled baseplate.Error
+// that will be satisfied as long as services are using the same version of
+// thrift compiler.
+type baseplateError interface {
+	thrift.TException
+
+	IsSetMessage() bool
+	GetMessage() string
+
+	IsSetCode() bool
+	GetCode() int32
+
+	IsSetRetryable() bool
+	GetRetryable() bool
+
+	IsSetDetails() bool
+	GetDetails() map[string]string
+}
+
+var (
+	_ baseplateError = (*baseplate.Error)(nil)
+)
+
+type wrappedBaseplateError struct {
+	cause error
+	bpErr baseplateError
+}
+
+func (e wrappedBaseplateError) Error() string {
+	var sb strings.Builder
+	sb.WriteString(fmt.Sprintf("baseplate.Error: %q", e.bpErr.GetMessage()))
+	var details []string
+	if e.bpErr.IsSetCode() {
+		details = append(details, fmt.Sprintf("code=%d", e.bpErr.GetCode()))
+	}
+	if e.bpErr.IsSetRetryable() {
+		details = append(details, fmt.Sprintf("retryable=%v", e.bpErr.GetRetryable()))
+	}
+	if e.bpErr.IsSetDetails() {
+		details = append(details, fmt.Sprintf("details=%#v", e.bpErr.GetDetails()))
+	}
+	if len(details) > 0 {
+		sb.WriteString(" (")
+		sb.WriteString(strings.Join(details, ", "))
+		sb.WriteString(")")
+	}
+	return sb.String()
+}
+
+func (e wrappedBaseplateError) Unwrap() error {
+	return e.cause
+}
+
+// WrapBaseplateError wraps e to an error with more meaningful error message if
+// e is baseplate.Error. Otherwise it returns e as-is.
+//
+// NOTE: This in general should only be used in clients.
+// If you wrap baseplate.Error returned in server code,
+// it could cause the error no longer being recognized as an error defined in
+// thrift IDL by the thrift server, and the client would get a generic
+// TApplicationException instead.
+// If you only need this for logging, it's auto applied on zapcore initialized
+// from log package automatically, and you don't need to do anything special
+// about it.
+func WrapBaseplateError(e error) error {
+	if errors.As(e, new(wrappedBaseplateError)) {
+		// Already wrapped, return e as-is to avoid double wrapping
+		return e
+	}
+
+	var bpErr baseplateError
+	if errors.As(e, &bpErr) {
+		return wrappedBaseplateError{
+			cause: e,
+			bpErr: bpErr,
+		}
+	}
+	return e
+}

internal/thriftint/baseplate_error_test.go

@@ -0,0 +1,140 @@
+package thriftint_test
+
+import (
+	"errors"
+	"fmt"
+	"testing"
+
+	"github.com/apache/thrift/lib/go/thrift"
+
+	baseplatethrift "github.com/reddit/baseplate.go/internal/gen-go/reddit/baseplate"
+	"github.com/reddit/baseplate.go/internal/thriftint"
+)
+
+func TestWrapBaseplateError(t *testing.T) {
+	for _, _c := range []struct {
+		label    string
+		orig     error
+		expected string
+	}{
+		{
+			label:    "nil",
+			orig:     nil,
+			expected: "<nil>",
+		},
+		{
+			label:    "not-bp",
+			orig:     errors.New("foo"),
+			expected: "foo",
+		},
+		{
+			label:    "empty",
+			orig:     &baseplatethrift.Error{},
+			expected: `baseplate.Error: ""`,
+		},
+		{
+			label: "full",
+			orig: &baseplatethrift.Error{
+				Message:   thrift.StringPtr("message"),
+				Code:      thrift.Int32Ptr(1),
+				Retryable: thrift.BoolPtr(true),
+				Details: map[string]string{
+					"foo": "bar",
+				},
+			},
+			expected: `baseplate.Error: "message" (code=1, retryable=true, details=map[string]string{"foo":"bar"})`,
+		},
+		{
+			label: "message-only",
+			orig: &baseplatethrift.Error{
+				Message: thrift.StringPtr("message"),
+			},
+			expected: `baseplate.Error: "message"`,
+		},
+		{
+			label: "no-message",
+			orig: &baseplatethrift.Error{
+				Code:      thrift.Int32Ptr(1),
+				Retryable: thrift.BoolPtr(true),
+				Details: map[string]string{
+					"foo": "bar",
+				},
+			},
+			expected: `baseplate.Error: "" (code=1, retryable=true, details=map[string]string{"foo":"bar"})`,
+		},
+		{
+			label: "no-code",
+			orig: &baseplatethrift.Error{
+				Message:   thrift.StringPtr("message"),
+				Retryable: thrift.BoolPtr(true),
+				Details: map[string]string{
+					"foo": "bar",
+				},
+			},
+			expected: `baseplate.Error: "message" (retryable=true, details=map[string]string{"foo":"bar"})`,
+		},
+		{
+			label: "no-retryable",
+			orig: &baseplatethrift.Error{
+				Message: thrift.StringPtr("message"),
+				Code:    thrift.Int32Ptr(1),
+				Details: map[string]string{
+					"foo": "bar",
+				},
+			},
+			expected: `baseplate.Error: "message" (code=1, details=map[string]string{"foo":"bar"})`,
+		},
+		{
+			label: "no-details",
+			orig: &baseplatethrift.Error{
+				Message:   thrift.StringPtr("message"),
+				Code:      thrift.Int32Ptr(1),
+				Retryable: thrift.BoolPtr(true),
+			},
+			expected: `baseplate.Error: "message" (code=1, retryable=true)`,
+		},
+		{
+			label: "already-wrapped",
+			orig: fmt.Errorf("already wrapped: %w", thriftint.WrapBaseplateError(&baseplatethrift.Error{
+				Message:   thrift.StringPtr("message"),
+				Code:      thrift.Int32Ptr(1),
+				Retryable: thrift.BoolPtr(true),
+			})),
+			expected: `already wrapped: baseplate.Error: "message" (code=1, retryable=true)`,
+		},
+	} {
+		c := _c
+		t.Run(c.label, func(t *testing.T) {
+			err := thriftint.WrapBaseplateError(c.orig)
+			actual := fmt.Sprintf("%v", err)
+			if c.expected != actual {
+				t.Errorf("Error message expected %q, got %q", c.expected, actual)
+			}
+		})
+	}
+
+	t.Run("errorsAs", func(t *testing.T) {
+		// Copied from retrybp package
+		type thriftRetryableError interface {
+			error
+
+			IsSetRetryable() bool
+			GetRetryable() bool
+		}
+
+		err := thriftint.WrapBaseplateError(&baseplatethrift.Error{
+			Message:   thrift.StringPtr("message"),
+			Code:      thrift.Int32Ptr(1),
+			Retryable: thrift.BoolPtr(true),
+			Details: map[string]string{
+				"foo": "bar",
+			},
+		})
+		if !errors.As(err, new(*baseplatethrift.Error)) {
+			t.Errorf("%v cannot be casted into *baseplate.Error", err)
+		}
+		if !errors.As(err, new(thriftRetryableError)) {
+			t.Errorf("%v cannot be casted into thriftRetryableError", err)
+		}
+	})
+}

log/core_wrapper.go

@@ -4,18 +4,20 @@ import (
 	"strconv"
 
 	"go.uber.org/zap/zapcore"
+
+	"github.com/reddit/baseplate.go/internal/thriftint"
 )
 
 type wrappedCore struct {
 	zapcore.Core
 }
 
 func (w wrappedCore) With(fields []zapcore.Field) zapcore.Core {
-	return wrappedCore{Core: w.Core.With(fieldsInt64ToString(fields))}
+	return wrappedCore{Core: w.Core.With(wrapFields(fields))}
 }
 
 func (w wrappedCore) Write(entry zapcore.Entry, fields []zapcore.Field) error {
-	return w.Core.Write(entry, fieldsInt64ToString(fields))
+	return w.Core.Write(entry, wrapFields(fields))
 }
 
 func (w wrappedCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
@@ -25,15 +27,21 @@ func (w wrappedCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore
 	return ce
 }
 
-func fieldsInt64ToString(fields []zapcore.Field) []zapcore.Field {
+func wrapFields(fields []zapcore.Field) []zapcore.Field {
 	for i, f := range fields {
 		switch f.Type {
+		// To make sure larger int64/uint64 logged will not be treated as float64
+		// and lose precision.
 		case zapcore.Int64Type:
 			f.Type = zapcore.StringType
 			f.String = strconv.FormatInt(f.Integer, 10)
 		case zapcore.Uint64Type:
 			f.Type = zapcore.StringType
 			f.String = strconv.FormatUint(uint64(f.Integer), 10)
+
+		// To make *baseplate.Errors more human readable in the logs.
+		case zapcore.ErrorType:
+			f.Interface = thriftint.WrapBaseplateError(f.Interface.(error))
 		}
 		fields[i] = f
 	}

log/core_wrapper_test.go

@@ -5,16 +5,25 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/apache/thrift/lib/go/thrift"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+
+	"github.com/reddit/baseplate.go/internal/gen-go/reddit/baseplate"
 )
 
+var bpErr = &baseplate.Error{
+	Message: thrift.StringPtr("foo"),
+	Code:    thrift.Int32Ptr(1),
+}
+
 func log(l *zap.SugaredLogger) {
 	l.Debugw(
 		"This is a log",
 		"int", int(123),
 		"int64", int64(1234),
 		"uint64", uint64(1234),
+		"bpErr", bpErr,
 	)
 }
 
@@ -33,17 +42,20 @@ func initCore(buf *bytes.Buffer) zapcore.Core {
 
 func TestWrappedCore(t *testing.T) {
 	const (
-		expectedOrigin  = `{"level":"debug","msg":"This is a log","int":123,"int64":1234,"uint64":1234}`
-		expectedWrapped = `{"level":"debug","msg":"This is a log","int":"123","int64":"1234","uint64":"1234"}`
+		// Example:
+		// {"level":"debug","msg":"This is a log","int":123,"int64":1234,"uint64":1234,"bpErr":"Error({Code:0xc0000268bc Message:0xc000072390 Details:map[] Retryable:<nil>})"}
+		expectedOriginPrefix = `{"level":"debug","msg":"This is a log","int":123,"int64":1234,"uint64":1234,"bpErr":"Error({Code:0x`
+
+		expectedWrapped = `{"level":"debug","msg":"This is a log","int":"123","int64":"1234","uint64":"1234","bpErr":"baseplate.Error: \"foo\" (code=1)"}`
 	)
 	t.Run("origin", func(t *testing.T) {
 		buf := new(bytes.Buffer)
 		core := initCore(buf)
 		logger := zap.New(core).Sugar()
 		log(logger)
 		actual := strings.TrimSpace(buf.String())
-		if actual != expectedOrigin {
-			t.Errorf("Expected log line %s, got %s", expectedOrigin, actual)
+		if !strings.HasPrefix(actual, expectedOriginPrefix) {
+			t.Errorf("Expected log line to start with %#q, got %#q", expectedOriginPrefix, actual)
 		}
 	})
 	t.Run("wrapped", func(t *testing.T) {
@@ -53,7 +65,7 @@ func TestWrappedCore(t *testing.T) {
 		log(logger)
 		actual := strings.TrimSpace(buf.String())
 		if actual != expectedWrapped {
-			t.Errorf("Expected log line %s, got %s", expectedWrapped, actual)
+			t.Errorf("Expected log line %#q, got %#q", expectedWrapped, actual)
 		}
 	})
 	t.Run("wrapped-with", func(t *testing.T) {
@@ -65,10 +77,11 @@ func TestWrappedCore(t *testing.T) {
 			"This is a log",
 			"int64", int64(1234),
 			"uint64", uint64(1234),
+			"bpErr", bpErr,
 		)
 		actual := strings.TrimSpace(buf.String())
 		if actual != expectedWrapped {
-			t.Errorf("Expected log line %s, got %s", expectedWrapped, actual)
+			t.Errorf("Expected log line %#q, got %#q", expectedWrapped, actual)
 		}
 	})
 }

thriftbp/client_middlewares.go

@@ -15,6 +15,7 @@ import (
 	"github.com/reddit/baseplate.go/ecinterface"
 	"github.com/reddit/baseplate.go/errorsbp"
 	"github.com/reddit/baseplate.go/internal/gen-go/reddit/baseplate"
+	"github.com/reddit/baseplate.go/internal/thriftint"
 	"github.com/reddit/baseplate.go/prometheusbp"
 	"github.com/reddit/baseplate.go/retrybp"
 	"github.com/reddit/baseplate.go/tracing"
@@ -299,7 +300,7 @@ func BaseplateErrorWrapper(next thrift.TClient) thrift.TClient {
 	return thrift.WrappedTClient{
 		Wrapped: func(ctx context.Context, method string, args, result thrift.TStruct) (thrift.ResponseMeta, error) {
 			meta, err := next.Call(ctx, method, args, result)
-			return meta, WrapBaseplateError(getClientError(result, err))
+			return meta, thriftint.WrapBaseplateError(getClientError(result, err))
 		},
 	}
 }