logging: add WithErrorFields (#734)

WithErrorFields allows to extract logging fields from an error.
Typically to add a stack trace field or more context around the error.

Signed-off-by: Olivier Cano <[email protected]>

interceptors/logging/interceptors.go

@@ -40,6 +40,9 @@ func (c *reporter) PostCall(err error, duration time.Duration) {
 	fields = fields.AppendUnique(Fields{"grpc.code", code.String()})
 	if err != nil {
 		fields = fields.AppendUnique(Fields{"grpc.error", fmt.Sprintf("%v", err)})
+		if c.opts.errorToFieldsFunc != nil {
+			fields = fields.AppendUnique(c.opts.errorToFieldsFunc(err))
+		}
 	}
 	if c.opts.fieldsFromCtxCallMetaFn != nil {
 		// fieldsFromCtxFn dups override the existing fields.
@@ -53,6 +56,9 @@ func (c *reporter) PostMsgSend(payload any, err error, duration time.Duration) {
 	fields := c.fields.WithUnique(ExtractFields(c.ctx))
 	if err != nil {
 		fields = fields.AppendUnique(Fields{"grpc.error", fmt.Sprintf("%v", err)})
+		if c.opts.errorToFieldsFunc != nil {
+			fields = fields.AppendUnique(c.opts.errorToFieldsFunc(err))
+		}
 	}
 	if c.opts.fieldsFromCtxCallMetaFn != nil {
 		// fieldsFromCtxFn dups override the existing fields.
@@ -104,6 +110,9 @@ func (c *reporter) PostMsgReceive(payload any, err error, duration time.Duration
 	fields := c.fields.WithUnique(ExtractFields(c.ctx))
 	if err != nil {
 		fields = fields.AppendUnique(Fields{"grpc.error", fmt.Sprintf("%v", err)})
+		if c.opts.errorToFieldsFunc != nil {
+			fields = fields.AppendUnique(c.opts.errorToFieldsFunc(err))
+		}
 	}
 	if c.opts.fieldsFromCtxCallMetaFn != nil {
 		// fieldsFromCtxFn dups override the existing fields.

interceptors/logging/interceptors_test.go

@@ -205,9 +205,12 @@ func TestSuite(t *testing.T) {
 			logging.StreamClientInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithFieldsFromContext(customFields)),
 		),
 	}
+	errorFields := func(err error) logging.Fields {
+		return testpb.ExtractErrorFields(err)
+	}
 	s.InterceptorTestSuite.ServerOpts = []grpc.ServerOption{
-		grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithFieldsFromContext(customFields))),
-		grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithFieldsFromContext(customFields))),
+		grpc.StreamInterceptor(logging.StreamServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithFieldsFromContext(customFields), logging.WithErrorFields(errorFields))),
+		grpc.UnaryInterceptor(logging.UnaryServerInterceptor(s.logger, logging.WithLevels(customClientCodeToLevel), logging.WithFieldsFromContext(customFields), logging.WithErrorFields(errorFields))),
 	}
 	suite.Run(t, s)
 }
@@ -367,6 +370,7 @@ func (s *loggingClientServerSuite) TestPingError_WithCustomLevels() {
 				AssertFieldNotEmpty(t, "grpc.request.deadline").
 				AssertField(t, "grpc.code", tcase.code.String()).
 				AssertField(t, "grpc.error", fmt.Sprintf("rpc error: code = %s desc = Userspace error", tcase.code.String())).
+				AssertField(t, "error-field", "plop").
 				AssertFieldNotEmpty(s.T(), "grpc.time_ms").AssertNoMoreTags(s.T())
 
 			clientFinishCallLogLine := lines[0]

interceptors/logging/options.go

@@ -57,6 +57,7 @@ var (
 type options struct {
 	levelFunc               CodeToLevel
 	loggableEvents          []LoggableEvent
+	errorToFieldsFunc       ErrorToFields
 	codeFunc                ErrorToCode
 	durationFieldFunc       DurationToFields
 	timestampFormat         string
@@ -89,6 +90,9 @@ func evaluateClientOpt(opts []Option) *options {
 // DurationToFields function defines how to produce duration fields for logging.
 type DurationToFields func(duration time.Duration) Fields
 
+// ErrorToFields function extract fields from error.
+type ErrorToFields func(err error) Fields
+
 // ErrorToCode function determines the error code of an error.
 // This makes using custom errors with grpc middleware easier.
 type ErrorToCode func(err error) codes.Code
@@ -169,6 +173,13 @@ func WithLogOnEvents(events ...LoggableEvent) Option {
 	}
 }
 
+// WithErrorFields allows to extract logging fields from an error.
+func WithErrorFields(f ErrorToFields) Option {
+	return func(o *options) {
+		o.errorToFieldsFunc = f
+	}
+}
+
 // WithLevels customizes the function for mapping gRPC return codes and interceptor log level statements.
 func WithLevels(f CodeToLevel) Option {
 	return func(o *options) {

testing/testpb/interceptor_suite.go

@@ -11,6 +11,7 @@ import (
 	"crypto/x509"
 	"crypto/x509/pkix"
 	"encoding/pem"
+	"errors"
 	"flag"
 	"math/big"
 	"net"
@@ -20,8 +21,10 @@ import (
 	"github.com/stretchr/testify/require"
 	"github.com/stretchr/testify/suite"
 	"google.golang.org/grpc"
+	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/credentials"
 	"google.golang.org/grpc/credentials/insecure"
+	"google.golang.org/grpc/status"
 )
 
 var (
@@ -150,6 +153,40 @@ func ExtractCtxTestNumber(ctx context.Context) *int {
 	return &zero
 }
 
+type wrappedErrFields struct {
+	wrappedErr error
+	fields     []any
+}
+
+func (err *wrappedErrFields) Unwrap() error {
+	return err.wrappedErr
+}
+
+func (err *wrappedErrFields) Error() string {
+	// Ideally we print wrapped fields as well
+	return err.wrappedErr.Error()
+}
+
+func (err *wrappedErrFields) GRPCStatus() *status.Status {
+	if s, ok := status.FromError(err.wrappedErr); ok {
+		return s
+	}
+	return status.New(codes.Unknown, err.Error())
+}
+
+func WrapFieldsInError(err error, fields []any) error {
+	return &wrappedErrFields{err, fields}
+}
+
+func ExtractErrorFields(err error) []any {
+	var e *wrappedErrFields
+	ok := errors.As(err, &e)
+	if !ok {
+		return nil
+	}
+	return e.fields
+}
+
 // UnaryServerInterceptor returns a new unary server interceptors that adds query information logging.
 func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
 	return func(ctx context.Context, req any, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {

testing/testpb/pingservice.go

@@ -45,7 +45,7 @@ func (s *TestPingService) Ping(ctx context.Context, ping *PingRequest) (*PingRes
 
 func (s *TestPingService) PingError(_ context.Context, ping *PingErrorRequest) (*PingErrorResponse, error) {
 	code := codes.Code(ping.ErrorCodeReturned)
-	return nil, status.Error(code, "Userspace error")
+	return nil, WrapFieldsInError(status.Error(code, "Userspace error"), []any{"error-field", "plop"})
 }
 
 func (s *TestPingService) PingList(ping *PingListRequest, stream TestService_PingListServer) error {