@@ -124,23 +124,58 @@ func TestWorkspaceActivityBump(t *testing.T) {
124124return
125125}
126126
127- var updatedAfter time.Time
127+ // maxTimeDrift is how long we are willing wait for a deadline to
128+ // be increased. Since it could have been bumped at the intial
129+ maxTimeDrift := testutil .WaitMedium
130+
131+ updatedAfter := dbtime .Now ()
132+ // waitedFor is purely for debugging failed tests. If a test fails,
133+ // it helps to know how long it took for the deadline bump to be
134+ // detected. The longer this takes, the more likely time drift will
135+ // affect the results.
136+ waitedFor := time .Now ()
137+ // lastChecked is for logging within the Eventually loop.
138+ // Debouncing log lines to every second to prevent spam.
139+ lastChecked := time.Time {}
140+ // checks is for keeping track of the average check time.
141+ // If CI is running slow, this could be useful to know checks
142+ // are taking longer than expected.
143+ checks := 0
144+
128145// The Deadline bump occurs asynchronously.
129146require .Eventuallyf (t ,
130147func ()bool {
148+ checks ++
131149workspace ,err = client .Workspace (ctx ,workspace .ID )
132150require .NoError (t ,err )
133- updatedAfter = dbtime .Now ()
134- if workspace .LatestBuild .Deadline .Time .Equal (firstDeadline ) {
135- updatedAfter = time .Now ()
136- return false
151+
152+ hasBumped := ! workspace .LatestBuild .Deadline .Time .Equal (firstDeadline )
153+
154+ // Always make sure to log this information, even on the last check.
155+ // The last check is the most important, as if this loop is acting
156+ // slow, the last check could be the cause of the failure.
157+ if time .Since (lastChecked )> time .Second || hasBumped {
158+ avgCheckTime := time .Since (waitedFor )/ time .Duration (checks )
159+ t .Logf ("deadline detect: bumped=%t since_last_check=%s avg_check_dur=%s checks=%d deadline=%v" ,
160+ hasBumped ,time .Since (updatedAfter ),avgCheckTime ,checks ,workspace .LatestBuild .Deadline .Time )
161+ lastChecked = time .Now ()
137162}
138- return true
163+
164+ updatedAfter = dbtime .Now ()
165+ return hasBumped
139166},
140- testutil .WaitLong ,testutil .IntervalFast ,
167+ //nolint: gocritic // maxTimeDrift is a testutil time
168+ maxTimeDrift ,testutil .IntervalFast ,
141169"deadline %v never updated" ,firstDeadline ,
142170)
143171
172+ // This log line helps establish how long it took for the deadline
173+ // to be detected as bumped.
174+ t .Logf ("deadline bump detected: %v, waited for %s" ,
175+ workspace .LatestBuild .Deadline .Time ,
176+ time .Since (waitedFor ),
177+ )
178+
144179require .Greater (t ,workspace .LatestBuild .Deadline .Time ,updatedAfter )
145180
146181// If the workspace has a max deadline, the deadline must not exceed
@@ -156,7 +191,7 @@ func TestWorkspaceActivityBump(t *testing.T) {
156191firstDeadline ,workspace .LatestBuild .Deadline .Time ,now ,
157192now .Sub (workspace .LatestBuild .Deadline .Time ),
158193)
159- require .WithinDuration (t ,dbtime . Now (). Add (ttl ),workspace .LatestBuild .Deadline .Time ,testutil . WaitShort )
194+ require .WithinDuration (t ,now . Add (ttl ),workspace .LatestBuild .Deadline .Time ,maxTimeDrift )
160195}
161196}
162197