Make stacktrace logging handle nested errors (#4573)

We now iterate through the error layers until we find the stacktrace
 - Previously any level of nesting prevented the stacktrace being shown

Also added stacktrace logging to idealised share error logging

Signed-off-by: JamesMurkin <jamesmurkin@hotmail.com>

Author: JamesMurkin

internal/common/logging/logger.go

@@ -93,12 +93,39 @@ func (l *Logger) WithError(err error) *Logger {
 // WithStacktrace returns a new Logger with the error and (if available) the stacktrace added as fields
 func (l *Logger) WithStacktrace(err error) *Logger {
 	logger := l.WithError(err)
-	if stackErr, ok := err.(stackTracer); ok {
-		return logger.WithField("stacktrace", fmt.Sprintf("%v", stackErr.StackTrace()))
+
+	stackTrace := getStackTrace(err)
+	if stackTrace != nil && len(stackTrace) > 0 {
+		return logger.WithField("stacktrace", fmt.Sprintf("%v", stackTrace))
 	}
 	return logger
 }
 
+// Will look through the Cause chain until it finds a stacktrace
+// Will not nest deeper than 10 layers, will return nil if the stacktrace isn't reached after that many iterations
+func getStackTrace(err error) errors.StackTrace {
+	var stackErr error
+	count := 0
+	for {
+		count++
+		if count > 10 {
+			break
+		}
+		if _, ok := err.(stackTracer); ok {
+			stackErr = err
+		}
+		if causerErr, ok := err.(causer); ok {
+			err = causerErr.Cause()
+		} else {
+			break
+		}
+	}
+	if stackErr != nil {
+		return stackErr.(stackTracer).StackTrace()
+	}
+	return nil
+}
+
 // WithField returns a new Logger with the key-value pair added as a new field
 func (l *Logger) WithField(key string, value any) *Logger {
 	return &Logger{
@@ -134,3 +161,7 @@ func (l *Logger) WithCallerSkip(skip int) *Logger {
 type stackTracer interface {
 	StackTrace() errors.StackTrace
 }
+
+type causer interface {
+	Cause() error
+}

internal/common/logging/logger_test.go

@@ -77,22 +77,75 @@ func TestWithError(t *testing.T) {
 }
 
 func TestWithStacktrace(t *testing.T) {
-	logger, buf := testLogger()
-	err := errors.New("test error")
-	logger = logger.WithStacktrace(err)
-
-	logger.Info("test message")
-
-	assertLogLineExpected(
-		t,
-		&testLogEntry{
-			Level:      "info",
-			Message:    "test message",
-			Error:      "test error",
-			Stacktrace: fmt.Sprintf("%v", err.(stackTracer).StackTrace()),
+	errorsNew := errors.New("test error")
+	errorsErrorf := errors.Errorf("test error")
+	errorsWithStack := errors.WithStack(fmt.Errorf("inner error"))
+	innerErrorWithStackTrace := errors.Errorf("inner error")
+	errorsWithMessageNested := errors.WithMessage(innerErrorWithStackTrace, "outer message")
+	errorsWithMessageNested2 := errors.WithMessage(errorsWithMessageNested, "even outer message")
+	tests := map[string]struct {
+		err         error
+		expectedLog *testLogEntry
+	}{
+		"errors.New": {
+			err: errorsNew,
+			expectedLog: &testLogEntry{
+				Level:      "info",
+				Message:    "test message",
+				Error:      "test error",
+				Stacktrace: fmt.Sprintf("%v", errorsNew.(stackTracer).StackTrace()),
+			},
 		},
-		buf,
-	)
+		"errors.ErrorF": {
+			err: errorsErrorf,
+			expectedLog: &testLogEntry{
+				Level:      "info",
+				Message:    "test message",
+				Error:      "test error",
+				Stacktrace: fmt.Sprintf("%v", errorsErrorf.(stackTracer).StackTrace()),
+			},
+		},
+		"errors.WithStack": {
+			err: errorsWithStack,
+			expectedLog: &testLogEntry{
+				Level:      "info",
+				Message:    "test message",
+				Error:      "inner error",
+				Stacktrace: fmt.Sprintf("%v", errorsWithStack.(stackTracer).StackTrace()),
+			},
+		},
+		"errors.WithMessage - nested": {
+			err: errorsWithMessageNested,
+			expectedLog: &testLogEntry{
+				Level:      "info",
+				Message:    "test message",
+				Error:      "outer message: inner error",
+				Stacktrace: fmt.Sprintf("%v", innerErrorWithStackTrace.(stackTracer).StackTrace()),
+			},
+		},
+		"errors.WithMessage - nested 2": {
+			err: errorsWithMessageNested2,
+			expectedLog: &testLogEntry{
+				Level:      "info",
+				Message:    "test message",
+				Error:      "even outer message: outer message: inner error",
+				Stacktrace: fmt.Sprintf("%v", innerErrorWithStackTrace.(stackTracer).StackTrace()),
+			},
+		},
+	}
+	for name, tc := range tests {
+		t.Run(name, func(t *testing.T) {
+			logger, buf := testLogger()
+			logger = logger.WithStacktrace(tc.err)
+			logger.Info("test message")
+
+			assertLogLineExpected(
+				t,
+				tc.expectedLog,
+				buf,
+			)
+		})
+	}
 }
 
 func TestLogAtLevel(t *testing.T) {

internal/scheduler/scheduling/scheduling_algo.go

@@ -577,7 +577,7 @@ func (l *FairSchedulingAlgo) SchedulePool(
 		resourceUnit,
 	)
 	if idealisedShareErr != nil {
-		log.Warnf("failed to calculated idealised share for pool %s - %s", fsctx.pool, idealisedShareErr)
+		log.WithStacktrace(idealisedShareErr).Warnf("failed to calculated idealised share for pool %s - %s", fsctx.pool, idealisedShareErr)
 	}
 
 	scheduler := NewPreemptingQueueScheduler(