refactor mlog and merr to handle and format error messages better

mctx/annotate.go

@@ -178,3 +178,17 @@ func MergeAnnotations(ctx context.Context, ctxs ...context.Context) context.Cont
 	}
 	return context.WithValue(ctx, ctxKeyAnnotation(0), &el{annotator: aa})
 }
+
+type ctxAnnotator struct {
+	ctx context.Context
+}
+
+func (ca ctxAnnotator) Annotate(aa Annotations) {
+	EvaluateAnnotations(ca.ctx, aa)
+}
+
+// ContextAsAnnotator will return an Annotator which, when evaluated, will
+// call EvaluateAnnotations on the given Context.
+func ContextAsAnnotator(ctx context.Context) Annotator {
+	return ctxAnnotator{ctx}
+}

merr/merr.go

@@ -41,9 +41,14 @@ type Error struct {
 
 // Error implements the method for the error interface.
 func (e Error) Error() string {
-	sb := strBuilderPool.Get().(*strings.Builder)
+	return e.Err.Error()
-	defer putStrBuilder(sb)
+}
-	sb.WriteString(strings.TrimSpace(e.Err.Error()))
+
+// FullError returns an error string which includes contextual annotations and
+// stacktrace information.
+func (e Error) FullError() string {
+	sb := new(strings.Builder)
+	sb.WriteString(strings.TrimSpace(e.Error()))
 
 	annotations := make(mctx.Annotations)
 	mctx.EvaluateAnnotations(e.Ctx, annotations)

merr/merr_test.go

@@ -10,7 +10,7 @@ import (
 	"github.com/mediocregopher/mediocre-go-lib/v2/mtest/massert"
 )
 
-func TestError(t *testing.T) {
+func TestFullError(t *testing.T) {
 	massert.Require(t, massert.Nil(Wrap(context.Background(), nil)))
 
 	ctx := mctx.Annotate(context.Background(),
@@ -27,7 +27,7 @@ func TestError(t *testing.T) {
 		ccc
 	* d: weird key but ok
 	* line: merr/merr_test.go:22`
-		massert.Require(t, massert.Equal(exp, e.Error()))
+		massert.Require(t, massert.Equal(exp, e.(Error).FullError()))
 	}
 
 	{
@@ -39,90 +39,95 @@ func TestError(t *testing.T) {
 		ccc
 	* d: weird key but ok
 	* line: merr/merr_test.go:34`
-		massert.Require(t, massert.Equal(exp, e.Error()))
+		massert.Require(t, massert.Equal(exp, e.(Error).FullError()))
 	}
 }
 
-func TestAs(t *testing.T) {
+func TestAsIsError(t *testing.T) {
+	testST := newStacktrace(0)
+
 	ctxA := mctx.Annotate(context.Background(), "a", "1")
 	ctxB := mctx.Annotate(context.Background(), "b", "2")
 	errFoo := errors.New("foo")
 
 	type test struct {
-		in    error
+		in     error
-		expAs error
+		expAs  error
-		expIs error
+		expIs  error
+		expStr string
 	}
 
 	tests := []test{
 		{
-			in:    nil,
+			in: nil,
-			expAs: nil,
-			expIs: nil,
 		},
 		{
-			in:    errors.New("bar"),
+			in:     errors.New("bar"),
-			expAs: nil,
+			expStr: "bar",
 		},
 		{
 			in: Error{
 				Err:        errFoo,
 				Ctx:        ctxA,
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			},
 			expAs: Error{
 				Err:        errFoo,
 				Ctx:        ctxA,
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			},
-			expIs: errFoo,
+			expIs:  errFoo,
+			expStr: "foo",
 		},
 		{
 			in: fmt.Errorf("bar: %w", Error{
 				Err:        errFoo,
 				Ctx:        ctxA,
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			}),
 			expAs: Error{
 				Err:        errFoo,
 				Ctx:        ctxA,
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			},
-			expIs: errFoo,
+			expIs:  errFoo,
+			expStr: "bar: foo",
 		},
 		{
 			in: Wrap(ctxB, Error{
 				Err:        errFoo,
 				Ctx:        ctxA,
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			}),
 			expAs: Error{
 				Err: Error{
 					Err:        errFoo,
 					Ctx:        ctxA,
-					Stacktrace: Stacktrace{frames: []uintptr{666}},
+					Stacktrace: testST,
 				},
 				Ctx:        mctx.MergeAnnotations(ctxA, ctxB),
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			},
-			expIs: errFoo,
+			expIs:  errFoo,
+			expStr: "foo",
 		},
 		{
-			in: Wrap(ctxB, fmt.Errorf("%w", Error{
+			in: Wrap(ctxB, fmt.Errorf("bar: %w", Error{
 				Err:        errFoo,
 				Ctx:        ctxA,
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			})),
 			expAs: Error{
-				Err: fmt.Errorf("%w", Error{
+				Err: fmt.Errorf("bar: %w", Error{
 					Err:        errFoo,
 					Ctx:        ctxA,
-					Stacktrace: Stacktrace{frames: []uintptr{666}},
+					Stacktrace: testST,
 				}),
 				Ctx:        mctx.MergeAnnotations(ctxA, ctxB),
-				Stacktrace: Stacktrace{frames: []uintptr{666}},
+				Stacktrace: testST,
 			},
-			expIs: errFoo,
+			expIs:  errFoo,
+			expStr: "bar: foo",
 		},
 	}
 
@@ -154,6 +159,7 @@ func TestAs(t *testing.T) {
 					massert.Equal(true, errors.Is(test.in, test.expIs)),
 					"errors.Is(\ntest.in:%#v,\ntest.expIs:%#v,\n)", test.in, test.expIs,
 				),
+				massert.Equal(test.expStr, test.in.Error()),
 			)
 		})
 	}

mlog/mlog.go

@@ -10,7 +10,7 @@ package mlog
 import (
 	"context"
 	"encoding/json"
-	"fmt"
+	"errors"
 	"io"
 	"io/ioutil"
 	"os"
@@ -19,8 +19,11 @@ import (
 	"time"
 
 	"github.com/mediocregopher/mediocre-go-lib/v2/mctx"
+	"github.com/mediocregopher/mediocre-go-lib/v2/merr"
 )
 
+type mlogAnnotation string
+
 // Null is an instance of Logger which will write all Messages to /dev/null.
 var Null = NewLogger(&LoggerOpts{
 	MessageHandler: NewMessageHandler(ioutil.Discard),
@@ -299,7 +302,7 @@ func (l *Logger) Log(msg Message) {
 	}
 }
 
-func mkMsg(ctx context.Context, lvl Level, descr string, annotators ...mctx.Annotator) Message {
+func mkMsg(ctx context.Context, lvl Level, descr string) Message {
 	return Message{
 		Context:     ctx,
 		Level:       lvl,
@@ -307,6 +310,22 @@ func mkMsg(ctx context.Context, lvl Level, descr string, annotators ...mctx.Anno
 	}
 }
 
+func mkErrMsg(ctx context.Context, lvl Level, descr string, err error) Message {
+	var e merr.Error
+	if !errors.As(err, &e) {
+		ctx = mctx.Annotate(ctx, mlogAnnotation("errMsg"), err.Error())
+		return mkMsg(ctx, lvl, descr)
+	}
+
+	ctx = mctx.Annotate(ctx,
+		mlogAnnotation("errMsg"), err.Error(),
+		mlogAnnotation("errCtx"), mctx.ContextAsAnnotator(e.Ctx),
+		mlogAnnotation("errLine"), e.Stacktrace.String(),
+	)
+
+	return mkMsg(ctx, lvl, descr)
+}
+
 // Debug logs a LevelDebug message.
 func (l *Logger) Debug(ctx context.Context, descr string) {
 	l.Log(mkMsg(ctx, LevelDebug, descr))
@@ -324,7 +343,7 @@ func (l *Logger) WarnString(ctx context.Context, descr string) {
 
 // Warn logs a LevelWarn message, including information from the given error.
 func (l *Logger) Warn(ctx context.Context, descr string, err error) {
-	l.Log(mkMsg(ctx, LevelWarn, fmt.Sprintf("%s: %s", descr, err)))
+	l.Log(mkErrMsg(ctx, LevelWarn, descr, err))
 }
 
 // ErrorString logs a LevelError message which is only a string.
@@ -334,7 +353,7 @@ func (l *Logger) ErrorString(ctx context.Context, descr string) {
 
 // Error logs a LevelError message, including information from the given error.
 func (l *Logger) Error(ctx context.Context, descr string, err error) {
-	l.Log(mkMsg(ctx, LevelError, fmt.Sprintf("%s: %s", descr, err)))
+	l.Log(mkErrMsg(ctx, LevelError, descr, err))
 }
 
 // Fatal logs a LevelFatal message. A Fatal message automatically stops the

mlog/mlog_test.go

@@ -50,8 +50,8 @@ func TestLogger(t *T) {
 	l.Error(ctx, "buz", errors.New("ERR"))
 	massert.Require(t,
 		assertOut(`{"td":"<TD>","ts":<TS>,"level":"INFO","descr":"bar","level_int":30}`),
-		assertOut(`{"td":"<TD>","ts":<TS>,"level":"WARN","descr":"baz: ERR","level_int":20}`),
+		assertOut(`{"td":"<TD>","ts":<TS>,"level":"WARN","descr":"baz","level_int":20,"annotations":{"errMsg":"ERR"}}`),
-		assertOut(`{"td":"<TD>","ts":<TS>,"level":"ERROR","descr":"buz: ERR","level_int":10}`),
+		assertOut(`{"td":"<TD>","ts":<TS>,"level":"ERROR","descr":"buz","level_int":10,"annotations":{"errMsg":"ERR"}}`),
 	)
 
 	// annotate context