fix: keep build log reads independent of deploy status polling

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,16 +146,20 @@ 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<void> => {
+  return async (buildId: string, finished: boolean, remainingMs = 30_000, cancelSignal?: AbortSignal): Promise<void> => {
     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 : remainingMs)
     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 = cancelSignal ?? 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 +169,16 @@ export function archiveLogWatcher(api: Api, projectId: string, write: (message:
         if (snapshot.state === 'unavailable') throw new Error('build logs unavailable')
         warned = ''
       } catch (error) {
+        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 message = `Could not read build logs. Retry with: insta build-logs ${buildId}\n`
+        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
       }
+      if (finalRead) return
     }
   }
 }

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<unknown> = sleep,
   log: (m: string) => void = () => {},
-  watchLogs?: (operationId: string, finished: boolean, remainingMs: number) => Promise<void>,
+  watchLogs?: (operationId: string, finished: boolean, remainingMs: number, signal?: AbortSignal) => Promise<void>,
 ): Promise<ArchiveDeployResult | null> {
   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
   }
 }

test/build-logs.test.ts

@@ -200,3 +200,159 @@ 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<ApiClient, 'rawRequest'> = { 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('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 latency = 4000
+  const api: Pick<ApiClient, 'rawRequest'> = { 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')) return { status: 200, body: base }
+    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, 60_000)
+    await vi.advanceTimersByTimeAsync(36_000)
+    await watching
+    expect(write).toHaveBeenCalledWith('page 7\n')
+    latency = 10
+    watching = watch('b', false)
+    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.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<ApiClient, 'rawRequest'> = { 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 => {
+    const controller = new AbortController()
+    setTimeout(() => controller.abort(new DOMException('timed out', 'TimeoutError')), ms)
+    return controller.signal
+  })
+  const api: Pick<ApiClient, 'rawRequest'> = { 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<ApiClient, 'rawRequest'> = { 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() }
+})