Skip to content

Commit 614641e

Browse files
sorccuclaude
andcommitted
fix(cli): exclude server-side scheduling delay from the per-check timeout [RED-814]
Per-check timers (default 600s) all started at run start, so on large staggered sessions — where the backend spreads non-priority checks across up to 900s of SQS delay — the tail was reported as timed out before those checks ever started. Timers now carry scheduling-delay headroom (timeout + 900s, with a distinct did-not-start message) until the check's run-start message arrives, then re-arm to the plain timeout: --timeout measures execution, not queue delay. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01HFcrNm7uzzkD1p87Nf9AhP
1 parent cebe501 commit 614641e

4 files changed

Lines changed: 134 additions & 23 deletions

File tree

packages/cli/src/commands/test.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,7 @@ export default class Test extends AuthCommand {
7575
}),
7676
'timeout': Flags.integer({
7777
default: DEFAULT_CHECK_RUN_TIMEOUT_SECONDS,
78-
description: 'A timeout (in seconds) to wait for checks to complete.',
78+
description: 'A timeout (in seconds) to wait for each check result once the check starts running. Checks awaiting scheduling get additional headroom for the server-side dispatch stagger.',
7979
}),
8080
'verbose': Flags.boolean({
8181
char: 'v',

packages/cli/src/commands/trigger.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ export default class Trigger extends AuthCommand {
6262
}),
6363
'timeout': Flags.integer({
6464
default: DEFAULT_CHECK_RUN_TIMEOUT_SECONDS,
65-
description: 'A timeout (in seconds) to wait for checks to complete.',
65+
description: 'A timeout (in seconds) to wait for each check result once the check starts running. Checks awaiting scheduling get additional headroom for the server-side dispatch stagger.',
6666
}),
6767
'verbose': Flags.boolean({
6868
char: 'v',

packages/cli/src/services/__tests__/abstract-check-runner.spec.ts

Lines changed: 64 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -375,3 +375,67 @@ describe('AbstractCheckRunner — scheduling watch', () => {
375375
expect(errors[0].code).toEqual('ABANDONED')
376376
})
377377
})
378+
379+
describe('AbstractCheckRunner — per-check timeouts vs scheduling delay', () => {
380+
const TIMEOUT_SECONDS = 60
381+
const MAX_SCHEDULING_DELAY_SECONDS = 900
382+
383+
beforeEach(() => {
384+
vi.useFakeTimers()
385+
})
386+
387+
afterEach(() => {
388+
vi.useRealTimers()
389+
})
390+
391+
function makeArmedRunner () {
392+
const runner = new StubCheckRunner('acc-1', TIMEOUT_SECONDS, false)
393+
runner.checks = new Map([['seq-1', { check: {} }]])
394+
const failures: string[] = []
395+
runner.on(Events.CHECK_FAILED, (_sequenceId, _check, message) => failures.push(message))
396+
;(runner as any).setAllTimeouts()
397+
return { runner, failures }
398+
}
399+
400+
it('does not time out a not-yet-started check before the scheduling-delay headroom elapses', async () => {
401+
const { runner, failures } = makeArmedRunner()
402+
403+
// The backend may hold a check in an SQS delay slot for up to 900s on
404+
// large staggered sessions: the plain execution timeout alone must not
405+
// fail a check that has not started yet.
406+
await vi.advanceTimersByTimeAsync((TIMEOUT_SECONDS + MAX_SCHEDULING_DELAY_SECONDS) * 1000 - 1000)
407+
expect(failures).toHaveLength(0)
408+
409+
await vi.advanceTimersByTimeAsync(2000)
410+
expect(failures).toHaveLength(1)
411+
expect(failures[0]).toContain('did not start')
412+
;(runner as any).disableAllTimeouts()
413+
})
414+
415+
it('re-arms to the plain execution timeout once the check starts', async () => {
416+
const { runner, failures } = makeArmedRunner()
417+
418+
await (runner as any).processMessage('seq-1', 'run-start', {})
419+
420+
await vi.advanceTimersByTimeAsync(TIMEOUT_SECONDS * 1000 - 1000)
421+
expect(failures).toHaveLength(0)
422+
423+
await vi.advanceTimersByTimeAsync(2000)
424+
expect(failures).toHaveLength(1)
425+
expect(failures[0]).toContain(`Reached timeout of ${TIMEOUT_SECONDS} seconds`)
426+
;(runner as any).disableAllTimeouts()
427+
})
428+
429+
it('a final result before the timeout produces no failure', async () => {
430+
const { runner, failures } = makeArmedRunner()
431+
const successes: string[] = []
432+
runner.on(Events.CHECK_SUCCESSFUL, sequenceId => successes.push(sequenceId))
433+
434+
await (runner as any).processMessage('seq-1', 'run-start', {})
435+
await (runner as any).processMessage('seq-1', 'result', { result: {}, resultType: 'FINAL' })
436+
437+
await vi.advanceTimersByTimeAsync((TIMEOUT_SECONDS + MAX_SCHEDULING_DELAY_SECONDS) * 1000)
438+
expect(failures).toHaveLength(0)
439+
expect(successes).toEqual(['seq-1'])
440+
})
441+
})

packages/cli/src/services/abstract-check-runner.ts

Lines changed: 68 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,19 @@ export const DEFAULT_PLAYWRIGHT_CHECK_RUN_TIMEOUT_SECONDS = 1200
4848

4949
const DEFAULT_SCHEDULING_DELAY_EXCEEDED_MS = 20000
5050

51+
// The backend staggers large sessions with SQS DelaySeconds and widens its
52+
// batches so no check is ever delayed beyond SQS's 15-minute ceiling. Until a
53+
// check's run-start message arrives, its timer must allow for that worst-case
54+
// queue delay on top of the execution timeout — otherwise the timer expires
55+
// for checks the server has not started yet. Once the check starts, the timer
56+
// is re-armed to the plain execution timeout.
57+
//
58+
// The 900s ceiling is a backend contract (the dispatch stagger is capped at
59+
// SQS's DelaySeconds maximum; RED-814 records where the backend enforces
60+
// it). If the backend's stagger ceiling ever changes, this constant must
61+
// follow.
62+
const MAX_SCHEDULING_DELAY_SECONDS = 900
63+
5164
function schedulingFailedError (operation: TestSessionSchedulingOperation): TestSessionSchedulingFailedError {
5265
return new TestSessionSchedulingFailedError(
5366
operation.error?.message ?? 'The test session could not be scheduled.',
@@ -277,6 +290,13 @@ export default abstract class AbstractCheckRunner extends EventEmitter {
277290

278291
const { check } = this.checks.get(sequenceId)!
279292
if (subtopic === 'run-start') {
293+
// The check is running: drop the scheduling-delay headroom so --timeout
294+
// measures execution from here on. A retry attempt re-arms the timer
295+
// again, giving each attempt a fresh execution window; the retry's
296+
// backoff delay runs against the previous attempt's window, without
297+
// extra headroom — no worse than the pre-existing behavior where all
298+
// attempts and backoffs shared a single window from run start.
299+
this.restartTimeoutForExecution(sequenceId, check)
280300
this.emit(Events.CHECK_INPROGRESS, check, sequenceId)
281301
} else if (subtopic === 'result') {
282302
const { result, testResultId, resultType } = message
@@ -344,28 +364,55 @@ export default abstract class AbstractCheckRunner extends EventEmitter {
344364
})
345365
}
346366

367+
private executionTimeoutSeconds (check: any): number {
368+
// Playwright checks can take longer; bump the default (only) accordingly.
369+
return (check instanceof PlaywrightCheck && this.timeout === DEFAULT_CHECK_RUN_TIMEOUT_SECONDS)
370+
? DEFAULT_PLAYWRIGHT_CHECK_RUN_TIMEOUT_SECONDS
371+
: this.timeout
372+
}
373+
374+
private armTimeout (sequenceId: SequenceId, check: any, seconds: number, hasStarted: boolean) {
375+
this.timeouts.set(sequenceId, setTimeout(() => {
376+
this.timeouts.delete(sequenceId)
377+
let errorMessage = hasStarted
378+
? `Reached timeout of ${seconds} seconds waiting for check result.`
379+
: `Check did not start within ${seconds} seconds (execution timeout plus the maximum scheduling delay).`
380+
// Playwright checks can take longer.
381+
// We should point the user to the --timeout flag in that case.
382+
if (check instanceof PlaywrightCheck) {
383+
errorMessage += ' Use a custom timeout with --timeout'
384+
} else if (this.timeout === DEFAULT_CHECK_RUN_TIMEOUT_SECONDS) {
385+
// Checkly should always report a result within 240s of a check
386+
// starting, and a check that never started at all is even more likely
387+
// a Checkly-side problem. If the default timeout was used, point the
388+
// user to the status page and support email.
389+
errorMessage += ' Checkly may be experiencing problems. Please check https://is.checkly.online or reach out to support@checklyhq.com.'
390+
}
391+
this.emit(Events.CHECK_FAILED, sequenceId, check, errorMessage)
392+
this.emit(Events.CHECK_FINISHED, check)
393+
}, seconds * 1000),
394+
)
395+
}
396+
347397
private setAllTimeouts () {
348-
Array.from(this.checks.entries()).forEach(([sequenceId, { check }]) => {
349-
const checkTimeout = (check instanceof PlaywrightCheck && this.timeout === DEFAULT_CHECK_RUN_TIMEOUT_SECONDS)
350-
? DEFAULT_PLAYWRIGHT_CHECK_RUN_TIMEOUT_SECONDS
351-
: this.timeout
352-
this.timeouts.set(sequenceId, setTimeout(() => {
353-
this.timeouts.delete(sequenceId)
354-
let errorMessage = `Reached timeout of ${checkTimeout} seconds waiting for check result.`
355-
// Playwright checks can take longer.
356-
// We should point the user to the --timeout flag in that case.
357-
if (check instanceof PlaywrightCheck) {
358-
errorMessage += ' Use a custom timeout with --timeout'
359-
} else if (this.timeout === DEFAULT_CHECK_RUN_TIMEOUT_SECONDS) {
360-
// Checkly should always report a result within 240s.
361-
// If the default timeout was used, we should point the user to the status page and support email.
362-
errorMessage += ' Checkly may be experiencing problems. Please check https://is.checkly.online or reach out to support@checklyhq.com.'
363-
}
364-
this.emit(Events.CHECK_FAILED, sequenceId, check, errorMessage)
365-
this.emit(Events.CHECK_FINISHED, check)
366-
}, checkTimeout * 1000),
367-
)
368-
})
398+
// Pre-start timers carry scheduling-delay headroom: a check at the tail
399+
// of a large staggered session may legitimately sit in a delay slot for
400+
// up to MAX_SCHEDULING_DELAY_SECONDS before it runs. The timer is
401+
// re-armed to the plain execution timeout when run-start arrives (see
402+
// processMessage). Every check must keep a `timeouts` entry from run
403+
// start — processMessage treats a missing entry as "already timed out"
404+
// and drops the check's messages.
405+
Array.from(this.checks.entries()).forEach(([sequenceId, { check }]) =>
406+
this.armTimeout(sequenceId, check, this.executionTimeoutSeconds(check) + MAX_SCHEDULING_DELAY_SECONDS, false))
407+
}
408+
409+
private restartTimeoutForExecution (sequenceId: SequenceId, check: any) {
410+
if (!this.timeouts.has(sequenceId)) {
411+
// Already timed out; do not resurrect the check.
412+
return
413+
}
414+
this.disableTimeout(sequenceId)
415+
this.armTimeout(sequenceId, check, this.executionTimeoutSeconds(check), true)
369416
}
370417

371418
private disableAllTimeouts () {

0 commit comments

Comments
 (0)