Improve await timeout diagnostics

common/testing/await/report.go

@@ -1,10 +1,13 @@
 package await
 
 import (
+	"context"
 	"fmt"
 	"strings"
 	"testing"
 	"time"
+
+	"go.temporal.io/server/common/testing/testcontext"
 )
 
 // reportAttemptErrors emits the collected attempt failures. When there are
@@ -21,10 +24,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
+	testContext        context.Context
+	deadlineCause      string
+	attempts           int
+	attemptTimeouts    int
+	attemptDurationSum time.Duration
+	attemptDurationMax time.Duration
+	failures           []attemptFailure
 }
 
 func (r *timeoutReport) nextPoll() {
@@ -41,18 +50,64 @@ 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))
 	}
-	tb.Fatalf("%s: %s\ndetails:\n  attempts         = %d\n  attempt timeouts = %d",
-		funcName, message, r.attempts, r.attemptTimeouts)
+	var details strings.Builder
+	// Keep the 16-character label column aligned with the testcontext audit appended below.
+	writeDetail := func(label, value string) {
+		fmt.Fprintf(&details, "  %-16s = %s\n", label, value)
+	}
+
+	if r.deadlineCause != "" && r.configuredTimeout > 0 {
+		writeDetail("await timeout", fmt.Sprintf(
+			"%v (configured %v; limited by %s)",
+			reportDuration(r.effectiveTimeout), reportDuration(r.configuredTimeout), r.deadlineCause,
+		))
+	}
+	writeDetail("attempts", fmt.Sprintf("%d", r.attempts))
+	if r.attemptTimeouts > 0 {
+		writeDetail("attempt timeouts", fmt.Sprintf("%d (attempt timeout %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 audit := testcontext.ExtensionAudit(r.testContext); audit != "" {
+		details.WriteString("  ")
+		details.WriteString(strings.ReplaceAll(audit, "\n", "\n  "))
+		details.WriteByte('\n')
+	}
+	tb.Fatalf("%s: %s\ndetails:\n%s", funcName, message, strings.TrimSuffix(details.String(), "\n"))
+}
+
+// Keep this formatting consistent with testcontext reports embedded above.
+func reportDuration(d time.Duration) string {
+	if d > -time.Millisecond && d < time.Millisecond {
+		rounded := d.Round(time.Microsecond)
+		if rounded != 0 {
+			return rounded.String()
+		}
+	}
+	return d.Round(time.Millisecond).String()
 }
 
 func reportAttemptErrors(tb testing.TB, failures []attemptFailure) {

common/testing/await/report_test.go

@@ -5,9 +5,11 @@ import (
 	"strings"
 	"sync"
 	"testing"
+	"testing/synctest"
 	"time"
 
 	"github.com/stretchr/testify/require"
+	"go.temporal.io/server/common/testing/testcontext"
 )
 
 func TestReportTimeout(t *testing.T) {
@@ -15,16 +17,17 @@ func TestReportTimeout(t *testing.T) {
 		tb := newReportRecordingTB()
 
 		timeoutReport{
-			effectiveTimeout: time.Second,
-			attempts:         3,
-			attemptTimeouts:  2,
+			effectiveTimeout:   time.Second,
+			attempts:           3,
+			attemptDurationSum: 60 * time.Millisecond,
+			attemptDurationMax: 30 * time.Millisecond,
 		}.reportTimeout(tb, "Require", "")
 
 		require.Equal(t, strings.Join([]string{
 			"Require: condition not satisfied after 1s",
 			"details:",
 			"  attempts         = 3",
-			"  attempt timeouts = 2",
+			"  attempt duration = avg 20ms, max 30ms",
 		}, "\n"), tb.fatals())
 	})
 
@@ -32,18 +35,44 @@ func TestReportTimeout(t *testing.T) {
 		tb := newReportRecordingTB()
 
 		timeoutReport{
-			effectiveTimeout: 2 * time.Second,
-			attempts:         4,
-			attemptTimeouts:  1,
+			effectiveTimeout:  time.Second,
+			configuredTimeout: 2 * time.Second,
+			attemptTimeout:    50 * time.Millisecond,
+			deadlineCause:     "parent context deadline",
+			attempts:          4,
+			attemptTimeouts:   1,
 		}.reportTimeout(tb, "Require", "workflow wf-123 not ready")
 
 		require.Equal(t, strings.Join([]string{
-			"Require: workflow wf-123 not ready (not satisfied after 2s)",
+			"Require: workflow wf-123 not ready (not satisfied after 1s)",
 			"details:",
+			"  await timeout    = 1s (configured 2s; limited by parent context deadline)",
 			"  attempts         = 4",
-			"  attempt timeouts = 1",
+			"  attempt timeouts = 1 (attempt timeout 50ms)",
+			"  attempt duration = avg 0s, max 0s",
 		}, "\n"), tb.fatals())
 	})
+
+	t.Run("with test context extension audit", func(t *testing.T) {
+		synctest.Test(t, func(t *testing.T) {
+			ctx := testcontext.For(t)
+			testcontext.EnsureRemaining(ctx, t, testcontext.DefaultTimeout()+10*time.Second)
+			tb := newReportRecordingTB()
+
+			timeoutReport{
+				effectiveTimeout: time.Second,
+				testContext:      ctx,
+			}.reportTimeout(tb, "Require", "")
+
+			require.Equal(t, strings.Join([]string{
+				"Require: condition not satisfied after 1s",
+				"details:",
+				"  attempts         = 0",
+				"  ctx extensions   = 1 (+10s total)",
+				"    1. +10s after 0s",
+			}, "\n"), tb.fatals())
+		})
+	})
 }
 
 type reportRecordingTB struct {

common/testing/await/require_ctx.go

@@ -7,7 +7,6 @@ import (
 	"time"
 
 	"go.temporal.io/server/common/testing/testcontext"
-	"go.temporal.io/server/common/util"
 )
 
 const requireMisuseHint = "use the *await.T passed to the callback, not s.T() or suite assertion methods"
@@ -82,32 +81,47 @@ func run(
 		return
 	}
 
+	start := time.Now()
 	// Ensure enough context time for the await itself plus post-await reserve.
 	// This only works for [testcontext]s; other contexts will be left unchanged.
 	testcontext.EnsureRemaining(parentCtx, tb, cfg.totalTimeout+postAwaitTimeoutReserve)
 
-	deadline := time.Now().Add(cfg.totalTimeout)
-	if parentDeadline, hasDeadline := parentCtx.Deadline(); hasDeadline {
+	deadline := start.Add(cfg.totalTimeout)
+	deadlineCause := ""
+	if parentDeadline, hasDeadline := parentCtx.Deadline(); hasDeadline && parentDeadline.Before(deadline) {
 		// Cap at the parent context's deadline if it's earlier than our timeout.
-		deadline = util.MinTime(deadline, parentDeadline)
+		deadline = parentDeadline
+		deadlineCause = "parent context deadline"
 	}
 
 	// Cap at the test's deadline if it's earlier than our deadline.
 	// Ideally, the parent context already accounts for the test's deadline - but we are being defensive.
-	if testDeadline, hasDeadline := testcontext.GoTestDeadline(tb); hasDeadline {
-		deadline = util.MinTime(deadline, testDeadline)
+	if testDeadline, hasDeadline := testcontext.GoTestDeadline(tb); hasDeadline && testDeadline.Before(deadline) {
+		deadline = testDeadline
+		deadlineCause = "go test timeout"
 	}
 
+	effectiveTimeout := max(0, time.Until(deadline))
 	awaitCtx, awaitCancel := context.WithDeadline(parentCtx, deadline)
 	defer awaitCancel()
 
-	report := timeoutReport{effectiveTimeout: max(0, time.Until(deadline))}
+	report := timeoutReport{
+		effectiveTimeout:  effectiveTimeout,
+		configuredTimeout: cfg.totalTimeout,
+		attemptTimeout:    cfg.attemptTimeout,
+		testContext:       parentCtx,
+		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
+		}
+		// Sleep can return at the deadline; do not start another attempt then.
+		if deadlineReached(deadline) {
+			report.reportTimeout(tb, funcName, cfg.timeoutMsg)
 			return
 		}
 
@@ -119,7 +133,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
@@ -153,8 +169,7 @@ 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
 		}
 
@@ -174,6 +189,12 @@ func run(
 	}
 }
 
+func failContextCanceled(tb testing.TB, report timeoutReport, funcName string, err error) {
+	tb.Helper()
+	report.reportAttemptErrors(tb)
+	tb.Fatalf("%s: context canceled before condition was satisfied: %v", funcName, err)
+}
+
 // attemptResult describes how an attempt terminated. Exactly one of the
 // following fields is set:
 //   - panicVal != nil: condition panicked with a non-attemptFailed value;