From 1d84047b244a439847bbacf25753901eda115695 Mon Sep 17 00:00:00 2001 From: Marc Coury Date: Thu, 21 Mar 2019 18:45:15 +0000 Subject: [PATCH 1/3] added multistack logging -- wip --- go.mod | 10 +++++ pkgerrors/stacktrace.go | 71 +++++++++++++++++++++++++++++++-- pkgerrors/stacktrace_test.go | 76 ++++++++++++++++++++++++++++++++++++ 3 files changed, 154 insertions(+), 3 deletions(-) diff --git a/go.mod b/go.mod index ed794278..99ad033c 100644 --- a/go.mod +++ b/go.mod @@ -1 +1,11 @@ module github.com/rs/zerolog + +go 1.12 + +require ( + github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e + github.com/pkg/errors v0.8.1 + github.com/rs/xid v1.2.1 + github.com/zenazn/goji v0.9.0 + golang.org/x/tools v0.0.0-20190321154406-ae772f11d294 +) diff --git a/pkgerrors/stacktrace.go b/pkgerrors/stacktrace.go index 01420e64..3d3a3a4e 100644 --- a/pkgerrors/stacktrace.go +++ b/pkgerrors/stacktrace.go @@ -1,6 +1,8 @@ package pkgerrors import ( + "encoding/json" + "github.com/pkg/errors" ) @@ -40,13 +42,14 @@ func frameField(f errors.Frame, s *state, c rune) string { return string(s.b) } +type stackTracer interface { + StackTrace() errors.StackTrace +} + // MarshalStack implements pkg/errors stack trace marshaling. // // zerolog.ErrorStackMarshaler = MarshalStack func MarshalStack(err error) interface{} { - type stackTracer interface { - StackTrace() errors.StackTrace - } sterr, ok := err.(stackTracer) if !ok { return nil @@ -63,3 +66,65 @@ func MarshalStack(err error) interface{} { } return out } + +type multiStack struct { + StackTraces []stackTrace +} + +type stackTrace struct { + Frames []frame `json:"stacktrace"` +} + +type frame struct { + StackSourceFileName string `json:"source"` + StackSourceLineName string `json:"line"` + StackSourceFuncName string `json:"func"` +} + +// MarshalMultiStack properly implements pkg/errors stack trace marshaling by unwrapping the error stack. +// +// zerolog.ErrorStackMarshaler = MarshalMultiStack +func MarshalMultiStack(err error) interface{} { + multiStack := multiStack{} + currentErr := err + for currentErr != nil { + stack, ok := currentErr.(stackTracer) + if !ok { + // Unwrap again because errors.Wrap actually adds two + // layers of wrapping. + currentErr = unwrapErr(currentErr) + continue + } + st := stack.StackTrace() + s := &state{} + stackTrace := stackTrace{} + for _, f := range st { + frame := frame{ + StackSourceFileName: frameField(f, s, 's'), + StackSourceLineName: frameField(f, s, 'd'), + StackSourceFuncName: frameField(f, s, 'n'), + } + stackTrace.Frames = append(stackTrace.Frames, frame) + } + multiStack.StackTraces = append(multiStack.StackTraces, stackTrace) + + currentErr = unwrapErr(currentErr) + } + marshalled, err := json.Marshal(multiStack.StackTraces) + if err != nil { + return "" + } + return string(marshalled) +} + +type causer interface { + Cause() error +} + +func unwrapErr(err error) error { + cause, ok := err.(causer) + if !ok { + return nil + } + return cause.Cause() +} diff --git a/pkgerrors/stacktrace_test.go b/pkgerrors/stacktrace_test.go index e771317d..e01944a1 100644 --- a/pkgerrors/stacktrace_test.go +++ b/pkgerrors/stacktrace_test.go @@ -27,6 +27,82 @@ func TestLogStack(t *testing.T) { } } +func TestLogMultiStack(t *testing.T) { + zerolog.ErrorStackMarshaler = MarshalMultiStack + + out := &bytes.Buffer{} + log := zerolog.New(out) + + err := errors.Wrap(errors.New("error message"), "from error") + log.Log().Stack().Err(err).Msg("") + + got := out.String() + want := `\{"stack":"\[\{\"stacktrace\":\[\{\"source\":\"stacktrace_test.go\",\"line\":\"36\",\"func\":\"TestLogMultiStack\"\},.*\{\"stacktrace\".*\],"error":"from error: error message"\}` + if ok, _ := regexp.MatchString(want, got); !ok { + t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) + } + +} + +// Some methods of wrapping cause more layers of wrapping than other layers, +// e.g. errors.New doesn't cause any wrapping, errors.WithStack and +// errors.WithMessage add one layer of wrapping, whereas errors.Wrap adds +// two layers of wrapping. +func TestUnwrapErr(t *testing.T) { + table := []struct { + name string + err error + numberOfWrapLevels int + }{ + { + name: "pass in nil error", + err: nil, + numberOfWrapLevels: 0, + }, + { + name: "fundamental error", + err: errors.New("error message"), + numberOfWrapLevels: 0, + }, + { + name: "singly wrapped error", + err: errors.Wrap(errors.New("error message"), "from error"), + numberOfWrapLevels: 2, + }, + { + name: "doubly wrapped error", + err: errors.Wrap(errors.Wrap(errors.New("error message"), "first wrapper"), "second wrapper"), + numberOfWrapLevels: 4, + }, + { + name: "wrap with WithStack", + err: errors.WithStack(errors.New("error message")), + numberOfWrapLevels: 1, + }, + { + name: "wrap with WithMessage", + err: errors.WithMessage(errors.New("error message"), "first wrapper"), + numberOfWrapLevels: 1, + }, + { + name: "wrap with WithMessage and Wrap", + err: errors.Wrap(errors.WithMessage(errors.New("error message"), "first wrapper"), "second wrapper"), + numberOfWrapLevels: 3, + }, + } + for _, test := range table { + t.Run(test.name, func(t *testing.T) { + currentErr := test.err + for i := 0; i <= test.numberOfWrapLevels; i++ { + currentErr = unwrapErr(currentErr) + } + if currentErr != nil { + t.Fatal("Expected to have finished unwrapping by this point") + } + }) + } +} + func BenchmarkLogStack(b *testing.B) { zerolog.ErrorStackMarshaler = MarshalStack out := &bytes.Buffer{} From 1ad1b778a3fde2dd3f862280abb54ae603bb7093 Mon Sep 17 00:00:00 2001 From: Marc Coury Date: Thu, 21 Mar 2019 19:16:28 +0000 Subject: [PATCH 2/3] fixed my silliness over encoding and testing unwrapErr --- go.sum | 14 ++++++++++++++ pkgerrors/stacktrace.go | 16 +++------------- pkgerrors/stacktrace_test.go | 26 ++++++++++---------------- 3 files changed, 27 insertions(+), 29 deletions(-) create mode 100644 go.sum diff --git a/go.sum b/go.sum new file mode 100644 index 00000000..8ee518ad --- /dev/null +++ b/go.sum @@ -0,0 +1,14 @@ +github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e h1:Wf6HqHfScWJN9/ZjdUKyjop4mf3Qdd+1TvvltAvM3m8= +github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e/go.mod h1:F5haX7vjVVG0kc13fIWeqUViNPyEJxv/OmvnBo0Yme4= +github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I= +github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= +github.com/rs/xid v1.2.1 h1:mhH9Nq+C1fY2l1XIpgxIiUOfNpRBYH1kKcr+qfKgjRc= +github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ= +github.com/zenazn/goji v0.9.0 h1:RSQQAbXGArQ0dIDEq+PI6WqN6if+5KHu6x2Cx/GXLTQ= +github.com/zenazn/goji v0.9.0/go.mod h1:7S9M489iMyHBNxwZnk9/EHS098H4/F6TATF2mIxtB1Q= +golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= +golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= +golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= +golang.org/x/tools v0.0.0-20190321154406-ae772f11d294 h1:gMPF/7U3xs3RNmp7bh9BoJnRg81e5uKSYpyaGoAmadw= +golang.org/x/tools v0.0.0-20190321154406-ae772f11d294/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= diff --git a/pkgerrors/stacktrace.go b/pkgerrors/stacktrace.go index 3d3a3a4e..20514c73 100644 --- a/pkgerrors/stacktrace.go +++ b/pkgerrors/stacktrace.go @@ -1,8 +1,6 @@ package pkgerrors import ( - "encoding/json" - "github.com/pkg/errors" ) @@ -67,10 +65,6 @@ func MarshalStack(err error) interface{} { return out } -type multiStack struct { - StackTraces []stackTrace -} - type stackTrace struct { Frames []frame `json:"stacktrace"` } @@ -85,7 +79,7 @@ type frame struct { // // zerolog.ErrorStackMarshaler = MarshalMultiStack func MarshalMultiStack(err error) interface{} { - multiStack := multiStack{} + stackTraces := []stackTrace{} currentErr := err for currentErr != nil { stack, ok := currentErr.(stackTracer) @@ -106,15 +100,11 @@ func MarshalMultiStack(err error) interface{} { } stackTrace.Frames = append(stackTrace.Frames, frame) } - multiStack.StackTraces = append(multiStack.StackTraces, stackTrace) + stackTraces = append(stackTraces, stackTrace) currentErr = unwrapErr(currentErr) } - marshalled, err := json.Marshal(multiStack.StackTraces) - if err != nil { - return "" - } - return string(marshalled) + return stackTraces } type causer interface { diff --git a/pkgerrors/stacktrace_test.go b/pkgerrors/stacktrace_test.go index e01944a1..cc2201b8 100644 --- a/pkgerrors/stacktrace_test.go +++ b/pkgerrors/stacktrace_test.go @@ -37,7 +37,7 @@ func TestLogMultiStack(t *testing.T) { log.Log().Stack().Err(err).Msg("") got := out.String() - want := `\{"stack":"\[\{\"stacktrace\":\[\{\"source\":\"stacktrace_test.go\",\"line\":\"36\",\"func\":\"TestLogMultiStack\"\},.*\{\"stacktrace\".*\],"error":"from error: error message"\}` + want := `\{"stack":\[\{"stacktrace":\[\{"source":"stacktrace_test.go","line":"36","func":"TestLogMultiStack"\},.*\{"stacktrace".*\],"error":"from error: error message"\}` if ok, _ := regexp.MatchString(want, got); !ok { t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) } @@ -45,55 +45,49 @@ func TestLogMultiStack(t *testing.T) { } // Some methods of wrapping cause more layers of wrapping than other layers, -// e.g. errors.New doesn't cause any wrapping, errors.WithStack and -// errors.WithMessage add one layer of wrapping, whereas errors.Wrap adds -// two layers of wrapping. +// e.g. errors.New, errors.WithStack and errors.WithMessage add one layer of +// wrapping, whereas errors.Wrap adds two layers of wrapping. func TestUnwrapErr(t *testing.T) { table := []struct { name string err error numberOfWrapLevels int }{ - { - name: "pass in nil error", - err: nil, - numberOfWrapLevels: 0, - }, { name: "fundamental error", err: errors.New("error message"), - numberOfWrapLevels: 0, + numberOfWrapLevels: 1, }, { name: "singly wrapped error", err: errors.Wrap(errors.New("error message"), "from error"), - numberOfWrapLevels: 2, + numberOfWrapLevels: 3, }, { name: "doubly wrapped error", err: errors.Wrap(errors.Wrap(errors.New("error message"), "first wrapper"), "second wrapper"), - numberOfWrapLevels: 4, + numberOfWrapLevels: 5, }, { name: "wrap with WithStack", err: errors.WithStack(errors.New("error message")), - numberOfWrapLevels: 1, + numberOfWrapLevels: 2, }, { name: "wrap with WithMessage", err: errors.WithMessage(errors.New("error message"), "first wrapper"), - numberOfWrapLevels: 1, + numberOfWrapLevels: 2, }, { name: "wrap with WithMessage and Wrap", err: errors.Wrap(errors.WithMessage(errors.New("error message"), "first wrapper"), "second wrapper"), - numberOfWrapLevels: 3, + numberOfWrapLevels: 4, }, } for _, test := range table { t.Run(test.name, func(t *testing.T) { currentErr := test.err - for i := 0; i <= test.numberOfWrapLevels; i++ { + for i := 0; i < test.numberOfWrapLevels; i++ { currentErr = unwrapErr(currentErr) } if currentErr != nil { From 06d10e7fcc13a50545885171e2c8707ade5b3624 Mon Sep 17 00:00:00 2001 From: Marc Coury Date: Sat, 23 Mar 2019 15:00:31 +0000 Subject: [PATCH 3/3] Tidied up test code --- pkgerrors/stacktrace.go | 3 ++ pkgerrors/stacktrace_test.go | 58 ++---------------------------------- 2 files changed, 6 insertions(+), 55 deletions(-) diff --git a/pkgerrors/stacktrace.go b/pkgerrors/stacktrace.go index 20514c73..fe40eb50 100644 --- a/pkgerrors/stacktrace.go +++ b/pkgerrors/stacktrace.go @@ -111,6 +111,9 @@ type causer interface { Cause() error } +// Some methods of wrapping cause more layers of wrapping than other layers, +// e.g. errors.New, errors.WithStack and errors.WithMessage add one layer of +// wrapping, whereas errors.Wrap adds two layers of wrapping. func unwrapErr(err error) error { cause, ok := err.(causer) if !ok { diff --git a/pkgerrors/stacktrace_test.go b/pkgerrors/stacktrace_test.go index cc2201b8..f6421208 100644 --- a/pkgerrors/stacktrace_test.go +++ b/pkgerrors/stacktrace_test.go @@ -33,70 +33,18 @@ func TestLogMultiStack(t *testing.T) { out := &bytes.Buffer{} log := zerolog.New(out) - err := errors.Wrap(errors.New("error message"), "from error") + err := errors.New("error message") + err = errors.Wrap(err, "from error") log.Log().Stack().Err(err).Msg("") got := out.String() - want := `\{"stack":\[\{"stacktrace":\[\{"source":"stacktrace_test.go","line":"36","func":"TestLogMultiStack"\},.*\{"stacktrace".*\],"error":"from error: error message"\}` + want := `\{"stack":\[\{"stacktrace":\[\{"source":"stacktrace_test.go","line":"37","func":"TestLogMultiStack"\},.*\{"stacktrace":\[\{"source":"stacktrace_test.go","line":"36","func":"TestLogMultiStack"\}.*\],"error":"from error: error message"\}` if ok, _ := regexp.MatchString(want, got); !ok { t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) } } -// Some methods of wrapping cause more layers of wrapping than other layers, -// e.g. errors.New, errors.WithStack and errors.WithMessage add one layer of -// wrapping, whereas errors.Wrap adds two layers of wrapping. -func TestUnwrapErr(t *testing.T) { - table := []struct { - name string - err error - numberOfWrapLevels int - }{ - { - name: "fundamental error", - err: errors.New("error message"), - numberOfWrapLevels: 1, - }, - { - name: "singly wrapped error", - err: errors.Wrap(errors.New("error message"), "from error"), - numberOfWrapLevels: 3, - }, - { - name: "doubly wrapped error", - err: errors.Wrap(errors.Wrap(errors.New("error message"), "first wrapper"), "second wrapper"), - numberOfWrapLevels: 5, - }, - { - name: "wrap with WithStack", - err: errors.WithStack(errors.New("error message")), - numberOfWrapLevels: 2, - }, - { - name: "wrap with WithMessage", - err: errors.WithMessage(errors.New("error message"), "first wrapper"), - numberOfWrapLevels: 2, - }, - { - name: "wrap with WithMessage and Wrap", - err: errors.Wrap(errors.WithMessage(errors.New("error message"), "first wrapper"), "second wrapper"), - numberOfWrapLevels: 4, - }, - } - for _, test := range table { - t.Run(test.name, func(t *testing.T) { - currentErr := test.err - for i := 0; i < test.numberOfWrapLevels; i++ { - currentErr = unwrapErr(currentErr) - } - if currentErr != nil { - t.Fatal("Expected to have finished unwrapping by this point") - } - }) - } -} - func BenchmarkLogStack(b *testing.B) { zerolog.ErrorStackMarshaler = MarshalStack out := &bytes.Buffer{}