From 7952b2af4d185c16bbea8e362e1594fb14a3d5f1 Mon Sep 17 00:00:00 2001 From: Lyu Date: Fri, 18 Sep 2026 02:21:03 -0700 Subject: [PATCH 1/2] fix: finish archive build log reads after polling expires --- src/build-logs.ts | 19 +++++-- test/build-logs.test.ts | 123 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 136 insertions(+), 6 deletions(-) diff --git a/src/build-logs.ts b/src/build-logs.ts index e69c09e..9158b92 100644 --- a/src/build-logs.ts +++ b/src/build-logs.ts @@ -136,14 +136,18 @@ export function archiveLogWatcher(api: Api, projectId: string, write: (message: let unavailable = false return async (buildId: string, finished: boolean, remainingMs = 30_000): Promise => { if (unavailable) return - const deadline = Date.now() + Math.min(remainingMs, finished ? 18_000 : 3000) + const started = Date.now() + const deadline = started + remainingMs + const refreshDeadline = started + Math.min(remainingMs, finished ? 18_000 : 3000) for (let attempt = 0; attempt < (finished ? 6 : 1); attempt++) { - if (attempt > 0) await wait(Math.min(3000, Math.max(0, deadline - Date.now()))) - const remaining = deadline - Date.now() + if (attempt > 0) await wait(Math.min(3000, Math.max(0, refreshDeadline - Date.now()))) + const finalRead = finished && (attempt === 5 || Date.now() >= refreshDeadline) + const remaining = Math.min(deadline - Date.now(), finalRead ? 30_000 : refreshDeadline - Date.now()) if (remaining <= 0) return - if (finished && (attempt === 0 || attempt === 5)) follow.tails.clear() + if (finished && (attempt === 0 || finalRead)) follow.tails.clear() + const signal = AbortSignal.timeout(remaining) try { - const snapshot = await readBuildLogs(api, projectId, 'archive', buildId, AbortSignal.timeout(remaining), follow) + const snapshot = await readBuildLogs(api, projectId, 'archive', buildId, signal, follow) if (snapshot.state === 'unsupported') { printer.finishLine(write) write('Build logs are not supported for this build provider.\n') @@ -153,12 +157,15 @@ export function archiveLogWatcher(api: Api, projectId: string, write: (message: if (snapshot.state === 'unavailable') throw new Error('build logs unavailable') warned = '' } catch (error) { + if (signal.aborted && !finalRead && Date.now() < deadline) continue if (error instanceof ApiError && error.status === 400) follow.tails.clear() printer.finishLine(write) - const message = `Could not read build logs. Retry with: insta build-logs ${buildId}\n` + const reason = signal.aborted ? ' (timed out)' : error instanceof ApiError ? ` (HTTP ${error.status})` : '' + const message = `Could not read build logs${reason}. Retry with: insta build-logs ${buildId}\n` if (warned !== message) write(message) warned = message } + if (finalRead) return } } } diff --git a/test/build-logs.test.ts b/test/build-logs.test.ts index f1dbd6c..e73e5b8 100644 --- a/test/build-logs.test.ts +++ b/test/build-logs.test.ts @@ -200,3 +200,126 @@ it('prints an unavailable build failure through the one-shot command', async () load.mockRestore(); project.mockRestore(); output.mockRestore() } }) + +it.each([250, 350])('finishes the final full read after %s ms page reads consume the polling budget', async (latency) => { + vi.useFakeTimers() + const timeout = vi.spyOn(AbortSignal, 'timeout').mockImplementation(ms => { + const controller = new AbortController() + setTimeout(() => controller.abort(new DOMException('timed out', 'TimeoutError')), ms) + return controller.signal + }) + let reads = 0 + const api: Pick = { rawRequest: vi.fn(async (_method, path, _body, opts) => { + await new Promise(resolve => setTimeout(resolve, latency)) + opts?.signal?.throwIfAborted() + const q = new URL('http://local' + path).searchParams + if (!q.has('step')) { reads++; return { status: 200, body: { ...base, buildState: 'succeeded' } } } + return { status: 200, body: { ...base, entries: [entry(q.has('cursor') ? 'tail\n' : reads >= 6 ? 'LATE\n' : 'first\n')], ...(q.has('cursor') ? {} : { nextCursor: 'tail' }) } } + }) } + const write = vi.fn() + try { + const watching = archiveLogWatcher(api, 'p', write)('b', true) + await vi.runAllTimersAsync() + await watching + expect(write).toHaveBeenCalledWith('LATE\n') + expect(write.mock.calls.some(([s]) => s.includes('Could not read'))).toBe(false) + expect(write.mock.calls.filter(([s]) => s === 'tail\n')).toHaveLength(1) + } finally { timeout.mockRestore(); vi.useRealTimers() } +}) + +it('yields an unfinished live refresh without warning and resumes its completed pages', async () => { + vi.useFakeTimers() + const timeout = vi.spyOn(AbortSignal, 'timeout').mockImplementation(ms => { + const controller = new AbortController() + setTimeout(() => controller.abort(new DOMException('timed out', 'TimeoutError')), ms) + return controller.signal + }) + let slow = true + const api: Pick = { rawRequest: vi.fn(async (_method, path, _body, opts) => { + await new Promise(resolve => setTimeout(resolve, slow ? 1100 : 10)) + opts?.signal?.throwIfAborted() + const q = new URL('http://local' + path).searchParams + if (!q.has('step')) return { status: 200, body: base } + return { status: 200, body: { ...base, entries: [entry(q.has('cursor') ? 'tail\n' : 'first\n')], ...(q.has('cursor') ? {} : { nextCursor: 'tail' }) } } + }) } + const write = vi.fn() + try { + const watch = archiveLogWatcher(api, 'p', write) + let watching = watch('b', false) + await vi.runAllTimersAsync(); await watching + expect(write).toHaveBeenCalledWith('first\n') + slow = false + watching = watch('b', false) + await vi.runAllTimersAsync(); await watching + expect(write.mock.calls.some(([s]) => s.includes('Could not read'))).toBe(false) + expect(write.mock.calls.filter(([s]) => s === 'first\n')).toHaveLength(1) + expect(write.mock.calls.filter(([s]) => s === 'tail\n')).toHaveLength(1) + } finally { timeout.mockRestore(); vi.useRealTimers() } +}) + +it('reports a final read timeout while respecting the remaining deployment deadline', async () => { + vi.useFakeTimers() + const timeout = vi.spyOn(AbortSignal, 'timeout').mockImplementation(ms => { + const controller = new AbortController() + setTimeout(() => controller.abort(new DOMException('timed out', 'TimeoutError')), ms) + return controller.signal + }) + const api: Pick = { rawRequest: vi.fn(async (_method, _path, _body, opts) => { + await new Promise((_resolve, reject) => opts!.signal!.addEventListener('abort', () => reject(opts!.signal!.reason), { once: true })) + return { status: 200, body: base } + }) } + const write = vi.fn() + try { + const watching = archiveLogWatcher(api, 'p', write)('b', true, 500) + await vi.runAllTimersAsync() + await watching + expect(api.rawRequest).toHaveBeenCalledTimes(1) + expect(timeout).toHaveBeenCalledWith(500) + expect(write).toHaveBeenCalledWith('Could not read build logs (timed out). Retry with: insta build-logs b\n') + } finally { timeout.mockRestore(); vi.useRealTimers() } +}) + +it('keeps real HTTP failures visible in the archive watcher', async () => { + const api = apiWith(() => { throw new ApiError(403, 'forbidden') }) + const write = vi.fn() + await archiveLogWatcher(api, 'p', write)('b', false) + expect(write).toHaveBeenCalledWith('Could not read build logs (HTTP 403). Retry with: insta build-logs b\n') +}) + + +it('keeps polling delayed terminal output when less than 18 seconds remain', async () => { + vi.useFakeTimers() + let reads = 0 + const api = apiWith(path => { + if (!path.includes('step=')) { reads++; return { ...base, buildState: 'succeeded' } } + return { ...base, entries: reads >= 4 ? [entry('late\n')] : [] } + }) + const write = vi.fn() + try { + await archiveLogWatcher(api, 'p', write, async ms => { vi.advanceTimersByTime(ms) })('b', true, 12_000) + expect(write).toHaveBeenCalledWith('late\n') + } finally { vi.useRealTimers() } +}) + + +it('performs a bounded final scan after an early terminal refresh uses the whole polling window', async () => { + vi.useFakeTimers() + const timeout = vi.spyOn(AbortSignal, 'timeout').mockImplementation(ms => { + const controller = new AbortController() + setTimeout(() => controller.abort(new DOMException('timed out', 'TimeoutError')), ms) + return controller.signal + }) + let calls = 0 + const api: Pick = { rawRequest: vi.fn(async (_method, path, _body, opts) => { + if (++calls === 1) await new Promise((_resolve, reject) => opts!.signal!.addEventListener('abort', () => reject(opts!.signal!.reason), { once: true })) + return { status: 200, body: { ...base, buildState: 'succeeded', entries: path.includes('step=') ? [entry('recovered\n')] : [] } } + }) } + const write = vi.fn() + try { + const watching = archiveLogWatcher(api, 'p', write)('b', true, 60_000) + await vi.runAllTimersAsync(); await watching + expect(write).toHaveBeenCalledWith('recovered\n') + expect(write.mock.calls.some(([s]) => s.includes('Could not read'))).toBe(false) + expect(timeout.mock.calls).toEqual([[18_000], [30_000]]) + } finally { timeout.mockRestore(); vi.useRealTimers() } +}) From d0e63e7c0db3d4a21691a98905cf0d1048160a58 Mon Sep 17 00:00:00 2001 From: Lyu Date: Fri, 18 Sep 2026 10:27:50 -0700 Subject: [PATCH 2/2] fix: poll deploy status independently of build logs --- src/build-logs.ts | 25 ++++++-- src/deploy-archive.ts | 101 +++++++++++++++++-------------- test/build-logs.test.ts | 55 +++++++++++++---- test/deploy-archive-logs.test.ts | 99 ++++++++++++++++++++++++++++++ 4 files changed, 216 insertions(+), 64 deletions(-) create mode 100644 test/deploy-archive-logs.test.ts diff --git a/src/build-logs.ts b/src/build-logs.ts index 9158b92..db00f3c 100644 --- a/src/build-logs.ts +++ b/src/build-logs.ts @@ -39,7 +39,19 @@ export async function readBuildLogs(api: Api, projectId: string, source: BuildSo do { if (++requests > 200) throw new Error('build logs exceed the per-read page limit') const params = new URLSearchParams({ ...(step ? { step } : {}), ...(cursor ? { cursor } : {}) }) - const { body } = await api.rawRequest('GET', `/projects/${projectId}/builds/${source}/${encodeURIComponent(buildId)}/logs?${params}`, undefined, { signal }) + signal.throwIfAborted() + const request = new AbortController() + const abort = () => request.abort(signal.reason) + signal.addEventListener('abort', abort, { once: true }) + const timeout = setTimeout(() => request.abort(new DOMException('build log request timed out', 'TimeoutError')), 20_000) + let body + try { + const response = await api.rawRequest('GET', `/projects/${projectId}/builds/${source}/${encodeURIComponent(buildId)}/logs?${params}`, undefined, { signal: request.signal }) + body = response.body + } finally { + clearTimeout(timeout) + signal.removeEventListener('abort', abort) + } if (!body || !['ready', 'pending', 'unsupported', 'unavailable'].includes(body.state) || !Array.isArray(body.steps) || !Array.isArray(body.entries)) throw new Error('invalid build log response') bytes += Buffer.byteLength(JSON.stringify(body)) if (bytes > 16 * 1024 * 1024) throw new Error('build logs exceed the 16 MiB per-read limit') @@ -134,18 +146,18 @@ export function archiveLogWatcher(api: Api, projectId: string, write: (message: const follow: FollowState = { tails: new Map(), emit: snapshot => printer.print(snapshot, write) } let warned = '' let unavailable = false - return async (buildId: string, finished: boolean, remainingMs = 30_000): Promise => { + return async (buildId: string, finished: boolean, remainingMs = 30_000, cancelSignal?: AbortSignal): Promise => { if (unavailable) return const started = Date.now() const deadline = started + remainingMs - const refreshDeadline = started + Math.min(remainingMs, finished ? 18_000 : 3000) + const refreshDeadline = started + Math.min(remainingMs, finished ? 18_000 : remainingMs) for (let attempt = 0; attempt < (finished ? 6 : 1); attempt++) { if (attempt > 0) await wait(Math.min(3000, Math.max(0, refreshDeadline - Date.now()))) const finalRead = finished && (attempt === 5 || Date.now() >= refreshDeadline) const remaining = Math.min(deadline - Date.now(), finalRead ? 30_000 : refreshDeadline - Date.now()) if (remaining <= 0) return if (finished && (attempt === 0 || finalRead)) follow.tails.clear() - const signal = AbortSignal.timeout(remaining) + const signal = cancelSignal ?? AbortSignal.timeout(remaining) try { const snapshot = await readBuildLogs(api, projectId, 'archive', buildId, signal, follow) if (snapshot.state === 'unsupported') { @@ -157,10 +169,11 @@ export function archiveLogWatcher(api: Api, projectId: string, write: (message: if (snapshot.state === 'unavailable') throw new Error('build logs unavailable') warned = '' } catch (error) { - if (signal.aborted && !finalRead && Date.now() < deadline) continue + if (cancelSignal?.aborted) return + if (finished && signal.aborted && !finalRead && Date.now() < deadline) continue if (error instanceof ApiError && error.status === 400) follow.tails.clear() printer.finishLine(write) - const reason = signal.aborted ? ' (timed out)' : error instanceof ApiError ? ` (HTTP ${error.status})` : '' + const reason = signal.aborted || (error instanceof Error && error.name === 'TimeoutError') ? ' (timed out)' : error instanceof ApiError ? ` (HTTP ${error.status})` : '' const message = `Could not read build logs${reason}. Retry with: insta build-logs ${buildId}\n` if (warned !== message) write(message) warned = message diff --git a/src/deploy-archive.ts b/src/deploy-archive.ts index 4c867c5..097236a 100644 --- a/src/deploy-archive.ts +++ b/src/deploy-archive.ts @@ -1,3 +1,4 @@ +import { setTimeout as delay } from 'node:timers/promises' import type { ApiClient } from './api.js' import { handleApproval } from './util.js' import type { PackResult } from './pack.js' @@ -110,7 +111,7 @@ export async function deployArchive( now: () => number = Date.now, wait: (ms: number) => Promise = sleep, log: (m: string) => void = () => {}, - watchLogs?: (operationId: string, finished: boolean, remainingMs: number) => Promise, + watchLogs?: (operationId: string, finished: boolean, remainingMs: number, signal?: AbortSignal) => Promise, ): Promise { const started = await api.rawRequest('POST', `/projects/${projectId}/archive-deploys`, { branch, @@ -129,56 +130,62 @@ export async function deployArchive( const deadline = now() + DEPLOY_DEADLINE_MS const overdue = () => new Error(`the deploy did not finish within ${Math.round(DEPLOY_DEADLINE_MS / 60000)} minutes — check \`insta status\` or re-run`) - let last = '' - for (;;) { - // The deadline bounds the wall clock, not the number of answers: it is checked before each poll, - // and each poll is itself bounded by what remains, so a stalled endpoint cannot hold the CLI - // past it, and an answer that would arrive after it is not waited for. - const remaining = deadline - now() - if (remaining <= 0) throw overdue() - const res = await api.rawRequest('GET', `/projects/${projectId}/archive-deploys/${encodeURIComponent(operationId)}`, undefined, { - signal: AbortSignal.timeout(Math.min(remaining, POLL_REQUEST_TIMEOUT_MS)), - }).catch((e) => { - if (!isAbort(e)) throw e - throw remaining <= POLL_REQUEST_TIMEOUT_MS ? overdue() : new Error(`the platform did not answer a status poll within ${POLL_REQUEST_TIMEOUT_MS / 1000}s — check \`insta status\` or re-run`) - }) - const state = res.body?.state - await watchLogs?.(operationId, state === 'failed' || state === 'live', Math.max(0, deadline - now())) - // A failed operation is an ANSWER, not a transport error: the poll worked, and the sentence - // it carries (usually the gateway's own, e.g. "no Dockerfile at ./api") is the one to show. - if (state === 'failed') { - // `||` would let a non-string through and the CLI would print "[object Object]" for the one - // sentence that explains the failure. Only a non-empty string is a message. - const error = res.body?.error - return { failed: typeof error === 'string' && error ? error : 'the deploy failed' } + const logController = new AbortController() + const logTask = watchLogs ? (async () => { + while (!logController.signal.aborted && now() < deadline) { + await watchLogs(operationId, false, Math.max(0, deadline - now()), logController.signal) + await delay(Math.min(POLL_MS, Math.max(0, deadline - now())), undefined, { signal: logController.signal }) } - if (state === 'live') { - const image = res.body?.imageRef - const url = res.body?.url - if (typeof image !== 'string' || !image || typeof url !== 'string' || !url) { - throw new Error('the deploy finished but the platform returned no image or URL for it — check `insta status`') + })().catch(() => { + if (!logController.signal.aborted) log(`Could not follow build logs. Retry with: insta build-logs ${operationId}`) + }) : undefined + let last = '' + try { + for (;;) { + const remaining = deadline - now() + if (remaining <= 0) throw overdue() + const res = await api.rawRequest('GET', `/projects/${projectId}/archive-deploys/${encodeURIComponent(operationId)}`, undefined, { + signal: AbortSignal.timeout(Math.min(remaining, POLL_REQUEST_TIMEOUT_MS)), + }).catch((e) => { + if (!isAbort(e)) throw e + throw remaining <= POLL_REQUEST_TIMEOUT_MS ? overdue() : new Error(`the platform did not answer a status poll within ${POLL_REQUEST_TIMEOUT_MS / 1000}s — check \`insta status\` or re-run`) + }) + const state = res.body?.state + if (state === 'failed' || state === 'live') { + logController.abort() + await logTask + await watchLogs?.(operationId, true, Math.max(0, deadline - now())) } - // Optional strings, validated as such. String() would have coerced a protocol error into a - // plausible-looking branch or group and reported a target the deploy never named. An omitted - // field falls back to what was requested; a field of the wrong type is a broken contract. - const optionalString = (field: string, v: unknown): string | undefined => { - if (v === undefined || v === null) return undefined - if (typeof v !== 'string') throw new Error(`the platform returned a non-string ${field} for the deploy — upgrade with \`insta upgrade\``) - return v + if (state === 'failed') { + const error = res.body?.error + return { failed: typeof error === 'string' && error ? error : 'the deploy failed' } } - return { - image, url, - branch: optionalString('branch', res.body.branch) ?? branch, - group: optionalString('group', res.body.group) ?? opts.group ?? '', - machineId: optionalString('machineId', res.body.machineId), + if (state === 'live') { + const image = res.body?.imageRef + const url = res.body?.url + if (typeof image !== 'string' || !image || typeof url !== 'string' || !url) { + throw new Error('the deploy finished but the platform returned no image or URL for it — check `insta status`') + } + const optionalString = (field: string, v: unknown): string | undefined => { + if (v === undefined || v === null) return undefined + if (typeof v !== 'string') throw new Error(`the platform returned a non-string ${field} for the deploy — upgrade with \`insta upgrade\``) + return v + } + return { + image, url, + branch: optionalString('branch', res.body.branch) ?? branch, + group: optionalString('group', res.body.group) ?? opts.group ?? '', + machineId: optionalString('machineId', res.body.machineId), + } } + if (state !== 'queued' && state !== 'building' && state !== 'deploying') { + throw new Error(`the platform reported an unknown deploy state (${JSON.stringify(state)}) — upgrade with \`insta upgrade\``) + } + if (state !== last) { log(state === 'deploying' ? 'image built, deploying it' : `${state}…`); last = state } + await wait(POLL_MS) } - // Only the platform's own in-flight states keep the loop going. An absent or unknown state - // would otherwise spend the whole deadline looking like a slow build. - if (state !== 'queued' && state !== 'building' && state !== 'deploying') { - throw new Error(`the platform reported an unknown deploy state (${JSON.stringify(state)}) — upgrade with \`insta upgrade\``) - } - if (state !== last) { log(state === 'deploying' ? 'image built, deploying it' : `${state}…`); last = state } - await wait(POLL_MS) + } finally { + logController.abort() + await logTask } } diff --git a/test/build-logs.test.ts b/test/build-logs.test.ts index e73e5b8..c826590 100644 --- a/test/build-logs.test.ts +++ b/test/build-logs.test.ts @@ -227,36 +227,69 @@ it.each([250, 350])('finishes the final full read after %s ms page reads consume } finally { timeout.mockRestore(); vi.useRealTimers() } }) -it('yields an unfinished live refresh without warning and resumes its completed pages', async () => { +it('reads slow live pages for longer than 30 seconds without truncating or repeating output', async () => { vi.useFakeTimers() const timeout = vi.spyOn(AbortSignal, 'timeout').mockImplementation(ms => { const controller = new AbortController() setTimeout(() => controller.abort(new DOMException('timed out', 'TimeoutError')), ms) return controller.signal }) - let slow = true + let latency = 4000 const api: Pick = { rawRequest: vi.fn(async (_method, path, _body, opts) => { - await new Promise(resolve => setTimeout(resolve, slow ? 1100 : 10)) + await new Promise(resolve => setTimeout(resolve, latency)) opts?.signal?.throwIfAborted() const q = new URL('http://local' + path).searchParams if (!q.has('step')) return { status: 200, body: base } - return { status: 200, body: { ...base, entries: [entry(q.has('cursor') ? 'tail\n' : 'first\n')], ...(q.has('cursor') ? {} : { nextCursor: 'tail' }) } } + const page = Number(q.get('cursor') ?? 0) + return { status: 200, body: { ...base, entries: [entry(`page ${page}\n`)], ...(page < 7 ? { nextCursor: String(page + 1) } : {}) } } }) } const write = vi.fn() try { const watch = archiveLogWatcher(api, 'p', write) - let watching = watch('b', false) - await vi.runAllTimersAsync(); await watching - expect(write).toHaveBeenCalledWith('first\n') - slow = false + let watching = watch('b', false, 60_000) + await vi.advanceTimersByTimeAsync(36_000) + await watching + expect(write).toHaveBeenCalledWith('page 7\n') + latency = 10 watching = watch('b', false) - await vi.runAllTimersAsync(); await watching + await vi.advanceTimersByTimeAsync(20) + await watching expect(write.mock.calls.some(([s]) => s.includes('Could not read'))).toBe(false) - expect(write.mock.calls.filter(([s]) => s === 'first\n')).toHaveLength(1) - expect(write.mock.calls.filter(([s]) => s === 'tail\n')).toHaveLength(1) + expect(write.mock.calls.filter(([s]) => s.startsWith('page '))).toHaveLength(8) } finally { timeout.mockRestore(); vi.useRealTimers() } }) +it('times out a stalled page after 20 seconds and retries from its saved cursor', async () => { + vi.useFakeTimers() + let stalled = true + const cursors: string[] = [] + const api: Pick = { rawRequest: vi.fn(async (_method, path, _body, opts) => { + const q = new URL('http://local' + path).searchParams + if (!q.has('step')) return { status: 200, body: base } + const cursor = q.get('cursor') ?? '' + cursors.push(cursor) + if (cursor && stalled) await new Promise((_resolve, reject) => opts!.signal!.addEventListener('abort', () => reject(opts!.signal!.reason), { once: true })) + return { status: 200, body: { ...base, entries: [entry(cursor ? 'tail\n' : 'first\n')], ...(cursor ? {} : { nextCursor: 'tail' }) } } + }) } + const write = vi.fn() + try { + const watch = archiveLogWatcher(api, 'p', write) + const watching = watch('b', false, 60_000) + await vi.advanceTimersByTimeAsync(19_999) + expect(write).toHaveBeenCalledWith('first\n') + expect(write.mock.calls.some(([s]) => s.includes('Could not read'))).toBe(false) + await vi.advanceTimersByTimeAsync(1) + await watching + expect(write).toHaveBeenCalledWith('Could not read build logs (timed out). Retry with: insta build-logs b\n') + stalled = false + await watch('b', false) + expect(cursors).toEqual(['', 'tail', 'tail']) + expect(write.mock.calls.filter(([s]) => s === 'first\n')).toHaveLength(1) + expect(write).toHaveBeenCalledWith('tail\n') + expect(vi.getTimerCount()).toBe(0) + } finally { vi.useRealTimers() } +}) + it('reports a final read timeout while respecting the remaining deployment deadline', async () => { vi.useFakeTimers() const timeout = vi.spyOn(AbortSignal, 'timeout').mockImplementation(ms => { diff --git a/test/deploy-archive-logs.test.ts b/test/deploy-archive-logs.test.ts new file mode 100644 index 0000000..477c676 --- /dev/null +++ b/test/deploy-archive-logs.test.ts @@ -0,0 +1,99 @@ +import { describe, expect, it, vi } from 'vitest' +import { archiveLogWatcher } from '../src/build-logs.js' +import { deployArchive } from '../src/deploy-archive.js' +import type { ApiClient } from '../src/api.js' + +const ref = { archiveSha256: 'a'.repeat(64), build: { type: 'dockerfile' as const } } +const accepted = { status: 202, body: { operationId: 'build' } } +const live = { state: 'live', imageRef: 'ecr/app@sha256:aa', url: 'https://app.example' } +const step = { digest: 'step', name: 'RUN build', hasLogs: true } +const page = { state: 'ready', buildState: 'running', steps: [step], entries: [] } +const entry = (message: string) => ({ timestamp: '2026-09-18T00:00:00Z', message }) + +describe('archive deployment log polling', () => { + it('polls status every 3 seconds during slow log reads, then cancels and drains before the final scan', async () => { + vi.useFakeTimers() + const started = Date.now() + const polls: number[] = [] + let finished = false + let active = 0 + let maxActive = 0 + let canceled = 0 + const api: Pick = { rawRequest: vi.fn(async (method, path, _body, opts) => { + if (method === 'POST') return accepted + if (path.includes('/archive-deploys/')) { + polls.push(Date.now() - started) + finished = polls.length === 4 + return { status: 200, body: finished ? live : { state: 'building' } } + } + active++ + maxActive = Math.max(maxActive, active) + try { + if (!finished) await new Promise((resolve, reject) => { + const abort = () => { clearTimeout(timer); canceled++; reject(opts!.signal!.reason) } + const timer = setTimeout(() => { opts!.signal!.removeEventListener('abort', abort); resolve() }, 4000) + opts!.signal!.addEventListener('abort', abort, { once: true }) + }) + const q = new URL('http://local' + path).searchParams + return { status: 200, body: !q.has('step') ? page : { + ...page, entries: [entry(q.has('cursor') ? 'FINAL\n' : 'FIRST\n')], ...(q.has('cursor') ? {} : { nextCursor: 'tail' }), + } } + } finally { active-- } + }) } + const write = vi.fn() + const status = vi.fn() + try { + const deploying = deployArchive(api, 'p', ref, 'main', {}, Date.now, undefined, status, archiveLogWatcher(api, 'p', write)) + await vi.advanceTimersByTimeAsync(8000) + expect(polls).toEqual([0, 3000, 6000]) + expect(write).toHaveBeenCalledWith('FIRST\n') + await vi.advanceTimersByTimeAsync(16_000) + expect(await deploying).toMatchObject({ url: live.url }) + expect(polls).toEqual([0, 3000, 6000, 9000]) + expect(maxActive).toBe(1) + expect(active).toBe(0) + expect(canceled).toBe(1) + expect(write.mock.calls.filter(([s]) => s === 'FIRST\n')).toHaveLength(1) + expect(write.mock.calls.filter(([s]) => s === 'FINAL\n')).toHaveLength(1) + expect(write.mock.calls.some(([s]) => s.includes('Could not read'))).toBe(false) + const requests = vi.mocked(api.rawRequest).mock.calls.length + await vi.advanceTimersByTimeAsync(60_000) + expect(vi.mocked(api.rawRequest).mock.calls).toHaveLength(requests) + } finally { vi.useRealTimers() } + }) + + it.each(['error', 'unknown', 'deadline'])('cancels pending logs when status polling exits through %s', async reason => { + let now = 0 + let canceled = false + const api: Pick = { rawRequest: vi.fn(async (method, path, _body, opts) => { + if (method === 'POST') return accepted + if (path.includes('/archive-deploys/')) { + if (reason === 'error') throw new Error('status unavailable') + return { status: 200, body: { state: reason === 'unknown' ? 'unexpected' : 'building' } } + } + await new Promise((_resolve, reject) => opts!.signal!.addEventListener('abort', () => { canceled = true; reject(opts!.signal!.reason) }, { once: true })) + return { status: 200, body: page } + }) } + const write = vi.fn() + const deploying = deployArchive(api, 'p', ref, 'main', {}, () => now, async () => { now = 30 * 60_000 }, () => {}, archiveLogWatcher(api, 'p', write)) + await expect(deploying).rejects.toThrow(reason === 'error' ? 'status unavailable' : reason === 'unknown' ? 'unknown deploy state' : 'did not finish within 30 minutes') + expect(canceled).toBe(true) + expect(write).not.toHaveBeenCalled() + }) + + it('refreshes logs while a status request is waiting and cancels idle polling when the build fails', async () => { + let finishStatus!: (value: { status: number; body: { state: string; error: string } }) => void + const status = new Promise<{ status: number; body: { state: string; error: string } }>(resolve => { finishStatus = resolve }) + const api = { rawRequest: async (method: string) => method === 'POST' ? accepted : status } + let finishReads!: () => void + const refreshed = new Promise(resolve => { finishReads = resolve }) + const watch = vi.fn(async (_id: string, finished: boolean) => { + if (!finished && watch.mock.calls.length === 2) finishReads() + }) + const deploying = deployArchive(api, 'p', ref, 'main', {}, Date.now, undefined, undefined, watch) + await refreshed + finishStatus({ status: 200, body: { state: 'failed', error: 'exit 17' } }) + expect(await deploying).toEqual({ failed: 'exit 17' }) + expect(watch.mock.calls.map(([, finished]) => finished)).toEqual([false, false, true]) + }) +})