From b0bc897773f08c6145b6295caad73edf2b3870e4 Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Tue, 15 Oct 2024 12:00:06 -0500 Subject: [PATCH 1/4] chore: add log statements to detect a slow test check If a test is running slow, the workspace deadline check can be slow. Since we use 'now' as a reference point, any time drift will affect the results. --- coderd/activitybump_test.go | 24 ++++++++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/coderd/activitybump_test.go b/coderd/activitybump_test.go index 90b0e7345862b..aaebd19b1b3b0 100644 --- a/coderd/activitybump_test.go +++ b/coderd/activitybump_test.go @@ -125,6 +125,15 @@ func TestWorkspaceActivityBump(t *testing.T) { } var updatedAfter time.Time + // waitedFor is purely for debugging failed tests. If a test fails, + // it helps to know how long it took for the deadline bump to be + // detected. The longer this takes, the more likely time drift will + // affect the results. + waitedFor := time.Now() + // lastChecked is for logging within the Eventually loop. + // Debouncing log lines to every second to prevent spam. + lastChecked := time.Now() + // The Deadline bump occurs asynchronously. require.Eventuallyf(t, func() bool { @@ -133,14 +142,25 @@ func TestWorkspaceActivityBump(t *testing.T) { updatedAfter = dbtime.Now() if workspace.LatestBuild.Deadline.Time.Equal(firstDeadline) { updatedAfter = time.Now() + if time.Since(lastChecked) > time.Second { + t.Logf("deadline still not updated, will continue to check: deadline=%v", workspace.LatestBuild.Deadline.Time) + lastChecked = time.Now() + } return false } return true }, - testutil.WaitLong, testutil.IntervalFast, + testutil.WaitMedium, testutil.IntervalFast, "deadline %v never updated", firstDeadline, ) + // This log line helps establish how long it took for the deadline + // to be detected as bumped. + t.Logf("deadline bump detected: %v, waited for %s", + workspace.LatestBuild.Deadline.Time, + time.Since(waitedFor), + ) + require.Greater(t, workspace.LatestBuild.Deadline.Time, updatedAfter) // If the workspace has a max deadline, the deadline must not exceed @@ -156,7 +176,7 @@ func TestWorkspaceActivityBump(t *testing.T) { firstDeadline, workspace.LatestBuild.Deadline.Time, now, now.Sub(workspace.LatestBuild.Deadline.Time), ) - require.WithinDuration(t, dbtime.Now().Add(ttl), workspace.LatestBuild.Deadline.Time, testutil.WaitShort) + require.WithinDuration(t, now.Add(ttl), workspace.LatestBuild.Deadline.Time, testutil.WaitShort) } } From 81b08ab5e7bf85badb92830c00d6b70cefd6ec8f Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Tue, 15 Oct 2024 12:12:49 -0500 Subject: [PATCH 2/4] chore: include avg check time in eventually loop If the hypothesis of a 10s time drift is true, this loop might be acting slow. --- coderd/activitybump_test.go | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/coderd/activitybump_test.go b/coderd/activitybump_test.go index aaebd19b1b3b0..86a59f06534fa 100644 --- a/coderd/activitybump_test.go +++ b/coderd/activitybump_test.go @@ -124,6 +124,10 @@ func TestWorkspaceActivityBump(t *testing.T) { return } + // maxTimeDrift is how long we are willing wait for a deadline to + // be increased. Since it could have been bumped at the intial + maxTimeDrift := testutil.WaitMedium + var updatedAfter time.Time // waitedFor is purely for debugging failed tests. If a test fails, // it helps to know how long it took for the deadline bump to be @@ -132,25 +136,32 @@ func TestWorkspaceActivityBump(t *testing.T) { waitedFor := time.Now() // lastChecked is for logging within the Eventually loop. // Debouncing log lines to every second to prevent spam. - lastChecked := time.Now() + lastChecked := time.Time{} + // checks is for keeping track of the average check time. + // If CI is running slow, this could be useful to know checks + // are taking longer than expected. + checks := 0 // The Deadline bump occurs asynchronously. require.Eventuallyf(t, func() bool { + checks++ workspace, err = client.Workspace(ctx, workspace.ID) require.NoError(t, err) updatedAfter = dbtime.Now() + if workspace.LatestBuild.Deadline.Time.Equal(firstDeadline) { updatedAfter = time.Now() if time.Since(lastChecked) > time.Second { - t.Logf("deadline still not updated, will continue to check: deadline=%v", workspace.LatestBuild.Deadline.Time) + avgCheckTime := time.Since(waitedFor) / time.Duration(checks) + t.Logf("deadline still not updated, will continue to check: avg_check_dur=%s checks=%d deadline=%v", avgCheckTime, checks, workspace.LatestBuild.Deadline.Time) lastChecked = time.Now() } return false } return true }, - testutil.WaitMedium, testutil.IntervalFast, + maxTimeDrift, testutil.IntervalFast, "deadline %v never updated", firstDeadline, ) @@ -176,7 +187,7 @@ func TestWorkspaceActivityBump(t *testing.T) { firstDeadline, workspace.LatestBuild.Deadline.Time, now, now.Sub(workspace.LatestBuild.Deadline.Time), ) - require.WithinDuration(t, now.Add(ttl), workspace.LatestBuild.Deadline.Time, testutil.WaitShort) + require.WithinDuration(t, now.Add(ttl), workspace.LatestBuild.Deadline.Time, maxTimeDrift) } } From 2bf1898c0713be787ab0cf3bd3cee47674dc7033 Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Tue, 15 Oct 2024 12:21:11 -0500 Subject: [PATCH 3/4] always log timing information --- coderd/activitybump_test.go | 25 ++++++++++++++----------- 1 file changed, 14 insertions(+), 11 deletions(-) diff --git a/coderd/activitybump_test.go b/coderd/activitybump_test.go index 86a59f06534fa..e8953df0a05f1 100644 --- a/coderd/activitybump_test.go +++ b/coderd/activitybump_test.go @@ -128,7 +128,7 @@ func TestWorkspaceActivityBump(t *testing.T) { // be increased. Since it could have been bumped at the intial maxTimeDrift := testutil.WaitMedium - var updatedAfter time.Time + updatedAfter := dbtime.Now() // waitedFor is purely for debugging failed tests. If a test fails, // it helps to know how long it took for the deadline bump to be // detected. The longer this takes, the more likely time drift will @@ -148,18 +148,21 @@ func TestWorkspaceActivityBump(t *testing.T) { checks++ workspace, err = client.Workspace(ctx, workspace.ID) require.NoError(t, err) - updatedAfter = dbtime.Now() - if workspace.LatestBuild.Deadline.Time.Equal(firstDeadline) { - updatedAfter = time.Now() - if time.Since(lastChecked) > time.Second { - avgCheckTime := time.Since(waitedFor) / time.Duration(checks) - t.Logf("deadline still not updated, will continue to check: avg_check_dur=%s checks=%d deadline=%v", avgCheckTime, checks, workspace.LatestBuild.Deadline.Time) - lastChecked = time.Now() - } - return false + hasBumped := !workspace.LatestBuild.Deadline.Time.Equal(firstDeadline) + + // Always make sure to log this information, even on the last check. + // The last check is the most important, as if this loop is acting + // slow, the last check could be the cause of the failure. + if time.Since(lastChecked) > time.Second || hasBumped { + avgCheckTime := time.Since(waitedFor) / time.Duration(checks) + t.Logf("deadline detect: bumped=%t since_last_check=%s avg_check_dur=%s checks=%d deadline=%v", + hasBumped, time.Since(updatedAfter), avgCheckTime, checks, workspace.LatestBuild.Deadline.Time) + lastChecked = time.Now() } - return true + + updatedAfter = dbtime.Now() + return hasBumped }, maxTimeDrift, testutil.IntervalFast, "deadline %v never updated", firstDeadline, From eb1602bba472f2cb4eff9c8cac58c5b69356052c Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Tue, 15 Oct 2024 12:26:08 -0500 Subject: [PATCH 4/4] linting --- coderd/activitybump_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/coderd/activitybump_test.go b/coderd/activitybump_test.go index e8953df0a05f1..2f4413dff9fee 100644 --- a/coderd/activitybump_test.go +++ b/coderd/activitybump_test.go @@ -164,6 +164,7 @@ func TestWorkspaceActivityBump(t *testing.T) { updatedAfter = dbtime.Now() return hasBumped }, + //nolint: gocritic // maxTimeDrift is a testutil time maxTimeDrift, testutil.IntervalFast, "deadline %v never updated", firstDeadline, )