Skip to content

test: add logging to TestWorkspaceActivityBump/Dial #15089

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Oct 16, 2024
Merged

test: add logging to TestWorkspaceActivityBump/Dial #15089

Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
b0bc897
chore: add log statements to detect a slow test check
Emyrk Oct 15, 2024
81b08ab
chore: include avg check time in eventually loop
Emyrk Oct 15, 2024
2bf1898
always log timing information
Emyrk Oct 15, 2024
eb1602b
linting
Emyrk Oct 15, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
51 changes: 43 additions & 8 deletions coderd/activitybump_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -124,23 +124,58 @@ func TestWorkspaceActivityBump(t *testing.T) {
return
}

var updatedAfter time.Time
// 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

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
// 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.Time{}
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Made to time.Time so the first loop is always logged.

// 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()
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
},
testutil.WaitLong, testutil.IntervalFast,
//nolint: gocritic // maxTimeDrift is a testutil time
maxTimeDrift, 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
Expand All @@ -156,7 +191,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, maxTimeDrift)
}
}

Expand Down
Loading