From a43c3cf3b54a89ebd34fc2e54f7e2cfe7b670dae Mon Sep 17 00:00:00 2001 From: Yuxuan 'fishy' Wang Date: Fri, 3 Mar 2023 13:56:23 -0800 Subject: [PATCH] log: Auto wrap baseplate.Error in logs A pain point currently is that thrift generated baseplate.Error doesn't provide human readable message automatically since we are using optional fields, logging it will not produce human readable/meaningful info. Although we provided WrapBaseplateError helper function, it has its own limitations, for example it's usually only safe to be used unconditionally on the client side, which limited its usefulness on the server side. Add a wrapper to zapcore to auto wrap baseplate.Errors, so whenever they are logged via kv pairs they are always auto wrapped. --- internal/thriftint/baseplate_error.go | 93 ++++++++++++ internal/thriftint/baseplate_error_test.go | 140 +++++++++++++++++++ log/core_wrapper.go | 14 +- log/core_wrapper_test.go | 25 +++- thriftbp/client_middlewares.go | 3 +- thriftbp/errors.go | 90 ++---------- thriftbp/errors_test.go | 129 ----------------- thriftbp/prometheus_test.go | 2 +- thriftbp/server_middlewares.go | 3 +- thriftbp/server_middlewares_internal_test.go | 3 - 10 files changed, 277 insertions(+), 225 deletions(-) create mode 100644 internal/thriftint/baseplate_error.go create mode 100644 internal/thriftint/baseplate_error_test.go diff --git a/internal/thriftint/baseplate_error.go b/internal/thriftint/baseplate_error.go new file mode 100644 index 000000000..ab5d57ce8 --- /dev/null +++ b/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 +} diff --git a/internal/thriftint/baseplate_error_test.go b/internal/thriftint/baseplate_error_test.go new file mode 100644 index 000000000..a48f38ea0 --- /dev/null +++ b/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: "", + }, + { + 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) + } + }) +} diff --git a/log/core_wrapper.go b/log/core_wrapper.go index 487386096..414a79394 100644 --- a/log/core_wrapper.go +++ b/log/core_wrapper.go @@ -4,6 +4,8 @@ import ( "strconv" "go.uber.org/zap/zapcore" + + "github.com/reddit/baseplate.go/internal/thriftint" ) type wrappedCore struct { @@ -11,11 +13,11 @@ type wrappedCore struct { } 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 } diff --git a/log/core_wrapper_test.go b/log/core_wrapper_test.go index 59a35e5fb..1b004c4d9 100644 --- a/log/core_wrapper_test.go +++ b/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,8 +42,11 @@ 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:})"} + 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) @@ -42,8 +54,8 @@ func TestWrappedCore(t *testing.T) { 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) } }) } diff --git a/thriftbp/client_middlewares.go b/thriftbp/client_middlewares.go index 96240a685..8370cc003 100644 --- a/thriftbp/client_middlewares.go +++ b/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)) }, } } diff --git a/thriftbp/errors.go b/thriftbp/errors.go index b9e04544a..c0057d7df 100644 --- a/thriftbp/errors.go +++ b/thriftbp/errors.go @@ -2,36 +2,16 @@ package thriftbp import ( "errors" - "fmt" - "strings" "github.com/apache/thrift/lib/go/thrift" "github.com/avast/retry-go" "github.com/reddit/baseplate.go/errorsbp" baseplatethrift "github.com/reddit/baseplate.go/internal/gen-go/reddit/baseplate" + "github.com/reddit/baseplate.go/internal/thriftint" "github.com/reddit/baseplate.go/retrybp" ) -// 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 -} - // We create this interface instead of using baseplateError because we want it to always match // regardless of the version of the thrift file the user has put in their repository. type baseplateErrorCoder interface { @@ -42,7 +22,7 @@ type baseplateErrorCoder interface { } var ( - _ baseplateError = (*baseplatethrift.Error)(nil) + _ baseplateErrorCoder = (*baseplatethrift.Error)(nil) ) // ClientPoolConfig errors are returned if the configuration validation fails. @@ -108,65 +88,13 @@ func IDLExceptionSuppressor(err error) bool { var _ errorsbp.Suppressor = IDLExceptionSuppressor -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())) - first := true - writeSeparator := func() { - if first { - first = false - sb.WriteString(" (") - } else { - sb.WriteString(", ") - } - } - if e.bpErr.IsSetCode() { - writeSeparator() - sb.WriteString(fmt.Sprintf("code=%d", e.bpErr.GetCode())) - } - if e.bpErr.IsSetRetryable() { - writeSeparator() - sb.WriteString(fmt.Sprintf("retryable=%v", e.bpErr.GetRetryable())) - } - if e.bpErr.IsSetDetails() { - writeSeparator() - sb.WriteString(fmt.Sprintf("details=%#v", e.bpErr.GetDetails())) - } - if !first { - 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. +// WrapBaseplateError wraps *baseplate.Error into errors with better error +// message, and can be unwrapped to the original *baseplate.Error. +// +// If e is not *baseplate.Error it will be returned 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. +// For logging this wrapping is auto applied as long as you initialize zap +// logger from log package so this is not needed. 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 + return thriftint.WrapBaseplateError(e) } diff --git a/thriftbp/errors_test.go b/thriftbp/errors_test.go index 7c639a860..3fd46f184 100644 --- a/thriftbp/errors_test.go +++ b/thriftbp/errors_test.go @@ -2,7 +2,6 @@ package thriftbp_test import ( "errors" - "fmt" "reflect" "testing" @@ -193,131 +192,3 @@ func TestIDLExceptionSuppressor(t *testing.T) { }) } } - -func TestWrapBaseplateError(t *testing.T) { - for _, _c := range []struct { - label string - orig error - expected string - }{ - { - label: "nil", - orig: nil, - expected: "", - }, - { - 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", thriftbp.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 := thriftbp.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 := thriftbp.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) - } - }) -} diff --git a/thriftbp/prometheus_test.go b/thriftbp/prometheus_test.go index d906f9aad..c46c73ca5 100644 --- a/thriftbp/prometheus_test.go +++ b/thriftbp/prometheus_test.go @@ -28,7 +28,7 @@ func TestPrometheusServerMiddleware(t *testing.T) { }{ { name: "bp error", - wantErr: thrift.NewTProtocolExceptionWithType(thrift.PROTOCOL_ERROR, WrapBaseplateError(errors.New("test"))), + wantErr: thrift.NewTProtocolExceptionWithType(thrift.PROTOCOL_ERROR, errors.New("test")), wantOK: false, baseplateStatusCode: "", }, diff --git a/thriftbp/server_middlewares.go b/thriftbp/server_middlewares.go index ceaa38243..de50616a9 100644 --- a/thriftbp/server_middlewares.go +++ b/thriftbp/server_middlewares.go @@ -13,6 +13,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/iobp" "github.com/reddit/baseplate.go/log" "github.com/reddit/baseplate.go/prometheusbp" @@ -120,7 +121,7 @@ func wrapErrorForServerSpan(err error, suppressor errorsbp.Suppressor) error { if suppressor == nil { suppressor = IDLExceptionSuppressor } - return WrapBaseplateError(suppressor.Wrap(err)) + return thriftint.WrapBaseplateError(suppressor.Wrap(err)) } // InjectServerSpan implements thrift.ProcessorMiddleware and injects a server diff --git a/thriftbp/server_middlewares_internal_test.go b/thriftbp/server_middlewares_internal_test.go index 1c88b5209..a8c298381 100644 --- a/thriftbp/server_middlewares_internal_test.go +++ b/thriftbp/server_middlewares_internal_test.go @@ -36,9 +36,6 @@ func TestWrapErrorForServerSpan(t *testing.T) { if err == nil { t.Fatal("Expected non-nil error, got nil") } - if !errors.As(err, new(wrappedBaseplateError)) { - t.Errorf("Expect baseplate.Error to be wrapped, got %#v", err) - } }, }, {