add logrus hook to log error file/line/function from stack traces

Signed-off-by: Steve Kriss <steve@heptio.com>

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())

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
+		}
+	}
+}

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())
+		})
+	}
+}