Skip to content

Commit 9b4ac8e

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 9b4ac8e

4 files changed

Lines changed: 135 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: 69 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,20 @@ 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: checkly/monorepo enforces it in
59+
// fitBatchSizeToMaxDelay (public-api/test-sessions/helper.js) and clamps at
60+
// the send site (common/helpers/send-check-run-to-sqs.js,
61+
// MAX_SQS_DELAY_SECONDS). If the stagger ceiling ever changes there, this
62+
// constant must follow.
63+
const MAX_SCHEDULING_DELAY_SECONDS = 900
64+
5165
function schedulingFailedError (operation: TestSessionSchedulingOperation): TestSessionSchedulingFailedError {
5266
return new TestSessionSchedulingFailedError(
5367
operation.error?.message ?? 'The test session could not be scheduled.',
@@ -277,6 +291,13 @@ export default abstract class AbstractCheckRunner extends EventEmitter {
277291

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

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

371419
private disableAllTimeouts () {

0 commit comments

Comments
 (0)