Richer await timeout diagnostics

common/testing/await/report.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"strings"
 	"testing"
+	"text/tabwriter"
 	"time"
 )
 
@@ -21,10 +22,16 @@ type attemptFailure struct {
 }
 
 type timeoutReport struct {
-	effectiveTimeout time.Duration
-	attempts         int
-	attemptTimeouts  int
-	failures         []attemptFailure
+	effectiveTimeout    time.Duration
+	configuredTimeout   time.Duration
+	attemptTimeout      time.Duration
+	testExtensionReport string
+	deadlineCause       string
+	attempts            int
+	attemptTimeouts     int
+	attemptDurationSum  time.Duration
+	attemptDurationMax  time.Duration
+	failures            []attemptFailure
 }
 
 func (r *timeoutReport) nextPoll() {
@@ -41,18 +48,98 @@ func (r *timeoutReport) recordAttemptTimeout() {
 	r.attemptTimeouts++
 }
 
+func (r *timeoutReport) recordAttemptDuration(d time.Duration) {
+	r.attemptDurationSum += d
+	r.attemptDurationMax = max(r.attemptDurationMax, d)
+}
+
 func (r timeoutReport) reportAttemptErrors(tb testing.TB) {
 	reportAttemptErrors(tb, r.failures)
 }
 
 func (r timeoutReport) reportTimeout(tb testing.TB, funcName, timeoutMsg string) {
 	r.reportAttemptErrors(tb)
-	message := fmt.Sprintf("condition not satisfied after %v", r.effectiveTimeout)
+	message := fmt.Sprintf("condition not satisfied after %v", reportDuration(r.effectiveTimeout))
 	if timeoutMsg != "" {
-		message = fmt.Sprintf("%s (not satisfied after %v)", timeoutMsg, r.effectiveTimeout)
+		message = fmt.Sprintf("%s (not satisfied after %v)", timeoutMsg, reportDuration(r.effectiveTimeout))
+	}
+	var details strings.Builder
+	detailWriter := tabwriter.NewWriter(&details, 0, 0, 1, ' ', 0)
+	var detailErr error
+	writeDetail := func(label, value string) {
+		if detailErr != nil {
+			return
+		}
+		_, detailErr = fmt.Fprintf(detailWriter, "  %s\t= %s\n", label, value)
+	}
+
+	hasAttemptFailures := len(r.failures) > 0 || r.attemptTimeouts > 0
+	shortenedTimeout := r.configuredTimeout-r.effectiveTimeout > time.Millisecond
+	if r.configuredTimeout > 0 && (!hasAttemptFailures || shortenedTimeout) {
+		value := reportDuration(r.effectiveTimeout)
+		if shortenedTimeout {
+			value += fmt.Sprintf(" (configured %v", reportDuration(r.configuredTimeout))
+			if r.deadlineCause != "" {
+				value += "; limited by " + r.deadlineCause
+			}
+			value += ")"
+		}
+		writeDetail("await timeout", value)
+	}
+	writeDetail("attempts", fmt.Sprintf("%d", r.attempts))
+	if r.attemptTimeouts > 0 {
+		writeDetail("attempt timeout", fmt.Sprintf("%d (configured as %v)", r.attemptTimeouts, reportDuration(r.attemptTimeout)))
+	}
+	if r.attempts > 0 {
+		writeDetail(
+			"attempt duration",
+			fmt.Sprintf(
+				"avg %v, max %v",
+				reportDuration(r.attemptDurationSum/time.Duration(r.attempts)),
+				reportDuration(r.attemptDurationMax),
+			),
+		)
+	}
+	if r.attemptTimeouts == 0 && r.deadlineCause != "" {
+		writeDetail("last failure", r.deadlineCause)
+	}
+	if r.testExtensionReport != "" {
+		if detailErr == nil {
+			_, detailErr = fmt.Fprintln(detailWriter, indentDetail(r.testExtensionReport))
+		}
+	}
+	if detailErr != nil {
+		tb.Fatalf("%s: failed to render timeout report: %v", funcName, detailErr)
+		return
+	}
+	if err := detailWriter.Flush(); err != nil {
+		tb.Fatalf("%s: failed to render timeout report: %v", funcName, err)
+		return
+	}
+	tb.Fatalf("%s: %s\ndetails:\n%s", funcName, message, strings.TrimSuffix(details.String(), "\n"))
+}
+
+func reportDuration(d time.Duration) string {
+	if d > -time.Millisecond && d < time.Millisecond {
+		rounded := d.Round(time.Microsecond)
+		if rounded == 0 {
+			return "0µs"
+		}
+		return rounded.String()
+	}
+	return d.Round(time.Millisecond).String()
+}
+
+func indentDetail(s string) string {
+	var b strings.Builder
+	for line := range strings.SplitSeq(s, "\n") {
+		if b.Len() > 0 {
+			b.WriteByte('\n')
+		}
+		b.WriteString("  ")
+		b.WriteString(line)
 	}
-	tb.Fatalf("%s: %s\ndetails:\n  attempts         = %d\n  attempt timeouts = %d",
-		funcName, message, r.attempts, r.attemptTimeouts)
+	return b.String()
 }
 
 func reportAttemptErrors(tb testing.TB, failures []attemptFailure) {

common/testing/await/require_ctx.go

@@ -100,26 +100,34 @@ func run(
 		parentCtx = extension.Context()
 	}
 	deadline := start.Add(cfg.totalTimeout)
+	deadlineCause := ""
 	if !extension.Deadline.IsZero() && extension.Deadline.Before(deadline) {
 		deadline = extension.Deadline
+		deadlineCause = testcontextDeadlineCause(extension.Limit, parentIsTestContext)
 	}
 
 	// Cap at the parent context's deadline if it's earlier than our timeout.
 	if parentDeadline, hasDeadline := parentCtx.Deadline(); hasDeadline && parentDeadline.Before(deadline) {
 		deadline = parentDeadline
+		deadlineCause = testcontextDeadlineCause(extension.Limit, parentIsTestContext)
 	}
 
 	effectiveTimeout := max(0, time.Until(deadline))
 	awaitCtx, awaitCancel := context.WithDeadline(parentCtx, deadline)
 	defer awaitCancel()
 
-	report := timeoutReport{effectiveTimeout: effectiveTimeout}
+	report := timeoutReport{
+		effectiveTimeout:    effectiveTimeout,
+		configuredTimeout:   cfg.totalTimeout,
+		attemptTimeout:      cfg.attemptTimeout,
+		testExtensionReport: extension.Report,
+		deadlineCause:       deadlineCause,
+	}
 
 	for {
 		// Parent context was canceled while we were sleeping (not our deadline).
 		if err := awaitCtx.Err(); err != nil && !deadlineReached(deadline) {
-			report.reportAttemptErrors(tb)
-			tb.Fatalf("%s: context canceled before condition was satisfied: %v", funcName, err)
+			failContextCanceled(tb, report, funcName, err)
 			return
 		}
 
@@ -131,7 +139,9 @@ func run(
 		t := &T{tb: tb, ctx: attemptCtx}
 
 		// Run attempt.
+		attemptStart := time.Now()
 		res := runAttempt(t, condition, attemptCancel, funcName, cancellable)
+		report.recordAttemptDuration(time.Since(attemptStart))
 		attemptCancel()
 		if res.panicVal != nil {
 			panic(res.panicVal) // propagate to caller
@@ -165,13 +175,15 @@ func run(
 
 		// Parent context was canceled during the attempt (not our deadline).
 		if err := awaitCtx.Err(); err != nil && !deadlineReached(deadline) {
-			report.reportAttemptErrors(tb)
-			tb.Fatalf("%s: context canceled before condition was satisfied: %v", funcName, err)
+			failContextCanceled(tb, report, funcName, err)
 			return
 		}
 
 		// Our deadline expired.
 		if deadlineReached(deadline) {
+			if deadlineCause != "" {
+				extension.SuppressCleanupReport()
+			}
 			report.reportTimeout(tb, funcName, cfg.timeoutMsg)
 			return
 		}
@@ -186,6 +198,22 @@ func run(
 	}
 }
 
+func failContextCanceled(tb testing.TB, report timeoutReport, funcName string, err error) {
+	tb.Helper()
+	report.reportAttemptErrors(tb)
+	tb.Fatalf("%v", fmt.Errorf("%s: context canceled before condition was satisfied: %w", funcName, err))
+}
+
+func testcontextDeadlineCause(limit string, parentIsTestContext bool) string {
+	if limit != "" {
+		return limit
+	}
+	if parentIsTestContext {
+		return "test context deadline"
+	}
+	return "parent context deadline"
+}
+
 // attemptResult describes how an attempt terminated. Exactly one of the
 // following fields is set:
 //   - panicVal != nil: condition panicked with a non-attemptFailed value;