From 9ac71b03ccd4aa8aac76cb6664236cce0cfd774e Mon Sep 17 00:00:00 2001 From: Steve Kriss Date: Tue, 3 Oct 2017 12:40:01 -0700 Subject: [PATCH] add logrus hook to log error file/line/function from stack traces Signed-off-by: Steve Kriss --- pkg/cmd/server/server.go | 10 +- pkg/util/logging/error_location_hook.go | 81 ++++++++++ pkg/util/logging/error_location_hook_test.go | 147 +++++++++++++++++++ 3 files changed, 234 insertions(+), 4 deletions(-) create mode 100644 pkg/util/logging/error_location_hook.go create mode 100644 pkg/util/logging/error_location_hook_test.go diff --git a/pkg/cmd/server/server.go b/pkg/cmd/server/server.go index d1de9b1e3..72514ba61 100644 --- a/pkg/cmd/server/server.go +++ b/pkg/cmd/server/server.go @@ -56,6 +56,7 @@ import ( "github.com/heptio/ark/pkg/restore" "github.com/heptio/ark/pkg/restore/restorers" "github.com/heptio/ark/pkg/util/kube" + "github.com/heptio/ark/pkg/util/logging" ) func NewCommand() *cobra.Command { @@ -66,10 +67,11 @@ func NewCommand() *cobra.Command { Short: "Run the ark server", Long: "Run the ark server", Run: func(c *cobra.Command, args []string) { - var ( - logger = logrus.New() - s, err = newServer(kubeconfig, fmt.Sprintf("%s-%s", c.Parent().Name(), c.Name()), logger) - ) + logger := logrus.New() + logger.Hooks.Add(&logging.ErrorLocationHook{}) + + s, err := newServer(kubeconfig, fmt.Sprintf("%s-%s", c.Parent().Name(), c.Name()), logger) + cmd.CheckError(err) cmd.CheckError(s.run()) diff --git a/pkg/util/logging/error_location_hook.go b/pkg/util/logging/error_location_hook.go new file mode 100644 index 000000000..c7bbd3d6c --- /dev/null +++ b/pkg/util/logging/error_location_hook.go @@ -0,0 +1,81 @@ +package logging + +import ( + "fmt" + + "github.com/pkg/errors" + "github.com/sirupsen/logrus" +) + +const ( + errorFileField = "error.file" + errorFunctionField = "error.function" +) + +// ErrorLocationHook is a logrus hook that attaches error location information +// to log entries if an error is being logged and it has stack-trace information +// (i.e. if it originates from or is wrapped by github.com/pkg/errors) +type ErrorLocationHook struct { +} + +func (h *ErrorLocationHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +func (h *ErrorLocationHook) Fire(entry *logrus.Entry) error { + var ( + errObj interface{} + exists bool + ) + + if errObj, exists = entry.Data[logrus.ErrorKey]; !exists { + return nil + } + + err, ok := errObj.(error) + if !ok { + return errors.New("object logged as error does not satisfy error interface") + } + + stackErr := getInnermostTrace(err) + + if stackErr != nil { + stackTrace := stackErr.StackTrace() + functionName := fmt.Sprintf("%n", stackTrace[0]) + fileAndLine := fmt.Sprintf("%s:%d", stackTrace[0], stackTrace[0]) + + entry.Data[errorFileField] = fileAndLine + entry.Data[errorFunctionField] = functionName + } + + return nil +} + +type stackTracer interface { + error + StackTrace() errors.StackTrace +} + +type causer interface { + Cause() error +} + +// getInnermostTrace returns the innermost error that +// has a stack trace attached +func getInnermostTrace(err error) stackTracer { + var tracer stackTracer + + for { + t, isTracer := err.(stackTracer) + if isTracer { + tracer = t + } + + c, isCauser := err.(causer) + if isCauser { + err = c.Cause() + } else { + return tracer + } + } +} diff --git a/pkg/util/logging/error_location_hook_test.go b/pkg/util/logging/error_location_hook_test.go new file mode 100644 index 000000000..3f99eb07a --- /dev/null +++ b/pkg/util/logging/error_location_hook_test.go @@ -0,0 +1,147 @@ +package logging + +import ( + "errors" + "testing" + + pkgerrs "github.com/pkg/errors" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestFire(t *testing.T) { + tests := []struct { + name string + preEntryFields map[string]interface{} + expectedEntryFields map[string]interface{} + expectedErr bool + }{ + { + name: "no error", + preEntryFields: map[string]interface{}{"foo": "bar"}, + expectedEntryFields: map[string]interface{}{"foo": "bar"}, + }, + { + name: "basic (non-pkg/errors) error", + preEntryFields: map[string]interface{}{logrus.ErrorKey: errors.New("a normal error")}, + expectedEntryFields: map[string]interface{}{logrus.ErrorKey: errors.New("a normal error")}, + }, + { + name: "non-error logged in error field", + preEntryFields: map[string]interface{}{logrus.ErrorKey: "not an error"}, + expectedEntryFields: map[string]interface{}{logrus.ErrorKey: "not an error"}, + expectedErr: true, + }, + { + name: "pkg/errors error", + preEntryFields: map[string]interface{}{logrus.ErrorKey: pkgerrs.New("a pkg/errors error")}, + expectedEntryFields: map[string]interface{}{ + logrus.ErrorKey: pkgerrs.New("a pkg/errors error"), + errorFileField: "", + errorFunctionField: "TestFire", + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + hook := &ErrorLocationHook{} + + entry := &logrus.Entry{ + Data: logrus.Fields(test.preEntryFields), + } + + // method under test + err := hook.Fire(entry) + + require.Equal(t, test.expectedErr, err != nil) + require.Equal(t, len(test.expectedEntryFields), len(entry.Data)) + + for key, expectedValue := range test.expectedEntryFields { + actualValue, found := entry.Data[key] + assert.True(t, found, "expected key not found: %s", key) + + switch key { + // test existence of this field only since testing the value + // is fragile + case errorFileField: + case logrus.ErrorKey: + if err, ok := expectedValue.(error); ok { + assert.Equal(t, err.Error(), actualValue.(error).Error()) + } else { + assert.Equal(t, expectedValue, actualValue) + } + default: + assert.Equal(t, expectedValue, actualValue) + } + } + }) + } +} + +func TestGetInnermostTrace(t *testing.T) { + newError := func() error { + return errors.New("a normal error") + } + + tests := []struct { + name string + err error + expectedRes error + }{ + { + name: "normal error", + err: newError(), + expectedRes: nil, + }, + { + name: "pkg/errs error", + err: pkgerrs.New("a pkg/errs error"), + expectedRes: pkgerrs.New("a pkg/errs error"), + }, + { + name: "one level of stack-ing a normal error", + err: pkgerrs.WithStack(newError()), + expectedRes: pkgerrs.WithStack(newError()), + }, + { + name: "two levels of stack-ing a normal error", + err: pkgerrs.WithStack(pkgerrs.WithStack(newError())), + expectedRes: pkgerrs.WithStack(newError()), + }, + { + name: "one level of stack-ing a pkg/errors error", + err: pkgerrs.WithStack(pkgerrs.New("a pkg/errs error")), + expectedRes: pkgerrs.New("a pkg/errs error"), + }, + { + name: "two levels of stack-ing a pkg/errors error", + err: pkgerrs.WithStack(pkgerrs.WithStack(pkgerrs.New("a pkg/errs error"))), + expectedRes: pkgerrs.New("a pkg/errs error"), + }, + { + name: "two levels of wrapping a normal error", + err: pkgerrs.Wrap(pkgerrs.Wrap(newError(), "wrap 1"), "wrap 2"), + expectedRes: pkgerrs.Wrap(newError(), "wrap 1"), + }, + { + name: "two levels of wrapping a pkg/errors error", + err: pkgerrs.Wrap(pkgerrs.Wrap(pkgerrs.New("a pkg/errs error"), "wrap 1"), "wrap 2"), + expectedRes: pkgerrs.New("a pkg/errs error"), + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + res := getInnermostTrace(test.err) + + if test.expectedRes == nil { + assert.Nil(t, res) + return + } + + assert.Equal(t, test.expectedRes.Error(), res.Error()) + }) + } +}