From 4ee71bf3137a4b05453fa10aeaf2a8e8daad6e20 Mon Sep 17 00:00:00 2001 From: Ryan Ling Date: Sun, 10 Apr 2022 00:41:06 +1000 Subject: [PATCH 1/3] Time out lint and test integrations --- .changeset/cuddly-seahorses-help.md | 7 ++ src/cli/lint/annotate/buildkite/index.ts | 2 +- src/cli/lint/autofix.ts | 24 +++--- src/cli/lint/external.ts | 6 +- src/cli/test/reporters/github/index.ts | 18 +++-- src/utils/error.test.ts | 19 +++++ src/utils/error.ts | 14 ++++ src/utils/version.ts | 9 +-- src/utils/wait.test.ts | 98 ++++++++++++++++++++++++ src/utils/wait.ts | 29 +++++++ 10 files changed, 201 insertions(+), 25 deletions(-) create mode 100644 .changeset/cuddly-seahorses-help.md create mode 100644 src/utils/error.test.ts create mode 100644 src/utils/wait.test.ts create mode 100644 src/utils/wait.ts diff --git a/.changeset/cuddly-seahorses-help.md b/.changeset/cuddly-seahorses-help.md new file mode 100644 index 000000000..6e0a79158 --- /dev/null +++ b/.changeset/cuddly-seahorses-help.md @@ -0,0 +1,7 @@ +--- +'skuba': patch +--- + +lint, test: Set timeout for Buildkite and GitHub integrations + +Transient network failures can impact annotations and autofixes. We now specify a 30 second timeout for these integration features to prevent them from hanging and indefinitely preoccupying your build agents. diff --git a/src/cli/lint/annotate/buildkite/index.ts b/src/cli/lint/annotate/buildkite/index.ts index d7b1644fe..0feccde06 100644 --- a/src/cli/lint/annotate/buildkite/index.ts +++ b/src/cli/lint/annotate/buildkite/index.ts @@ -17,7 +17,7 @@ export const createBuildkiteAnnotations = async ( return; } - const buildkiteOutput: string = [ + const buildkiteOutput = [ '`skuba lint` found issues that require triage:', ...createEslintAnnotations(eslint), ...createPrettierAnnotations(prettier), diff --git a/src/cli/lint/autofix.ts b/src/cli/lint/autofix.ts index aae6dcf70..ea80c6ef2 100644 --- a/src/cli/lint/autofix.ts +++ b/src/cli/lint/autofix.ts @@ -7,6 +7,7 @@ import { runESLint } from '../../cli/adapter/eslint'; import { runPrettier } from '../../cli/adapter/prettier'; import { isCiEnv } from '../../utils/env'; import { createLogger, log } from '../../utils/logging'; +import { throwOnTimeout } from '../../utils/wait'; import type { Input } from './types'; @@ -86,16 +87,19 @@ export const autofix = async (input: Pick): Promise => { return log.warn('No autofixes detected.'); } - await (process.env.GITHUB_ACTIONS - ? // GitHub's checkout action should preconfigure the Git CLI. - simpleGit().push() - : // In other CI environments (Buildkite) we fall back to GitHub App auth. - Git.push({ - auth: { type: 'gitHubApp' }, - dir: process.cwd(), - ref, - remoteRef: currentBranch, - })); + await throwOnTimeout( + process.env.GITHUB_ACTIONS + ? // GitHub's checkout action should preconfigure the Git CLI. + simpleGit().push() + : // In other CI environments (Buildkite) we fall back to GitHub App auth. + Git.push({ + auth: { type: 'gitHubApp' }, + dir: process.cwd(), + ref, + remoteRef: currentBranch, + }), + { s: 30 }, + ); log.warn(`Pushed fix commit ${ref}.`); } catch (err) { diff --git a/src/cli/lint/external.ts b/src/cli/lint/external.ts index a516ccf29..b1302b98f 100644 --- a/src/cli/lint/external.ts +++ b/src/cli/lint/external.ts @@ -2,6 +2,7 @@ import stream from 'stream'; import { inspect } from 'util'; import { log } from '../../utils/logging'; +import { throwOnTimeout } from '../../utils/wait'; import { createAnnotations } from './annotate'; import { autofix } from './autofix'; @@ -86,7 +87,10 @@ export const externalLint = async (input: Input) => { const { eslint, prettier, tscOk } = await lint({ ...input, tscOutputStream }); try { - await createAnnotations(eslint, prettier, tscOk, tscOutputStream); + await throwOnTimeout( + createAnnotations(eslint, prettier, tscOk, tscOutputStream), + { s: 30 }, + ); } catch (err) { log.warn('Failed to annotate lint results.'); log.subtle(inspect(err)); diff --git a/src/cli/test/reporters/github/index.ts b/src/cli/test/reporters/github/index.ts index 0c3a1223e..1ce20cc0d 100644 --- a/src/cli/test/reporters/github/index.ts +++ b/src/cli/test/reporters/github/index.ts @@ -9,6 +9,7 @@ import { enabledFromEnvironment, } from '../../../../api/github/environment'; import { log } from '../../../../utils/logging'; +import { throwOnTimeout } from '../../../../utils/wait'; import { generateAnnotationEntries } from './annotations'; @@ -37,13 +38,16 @@ export default class GitHubReporter implements Pick { ? '`skuba test` passed.' : '`skuba test` found issues that require triage.'; - await GitHub.createCheckRun({ - name, - annotations, - conclusion: isOk ? 'success' : 'failure', - summary, - title: `${build} ${isOk ? 'passed' : 'failed'}`, - }); + await throwOnTimeout( + GitHub.createCheckRun({ + name, + annotations, + conclusion: isOk ? 'success' : 'failure', + summary, + title: `${build} ${isOk ? 'passed' : 'failed'}`, + }), + { s: 30 }, + ); } } catch (err) { log.warn('Failed to report test results to GitHub.'); diff --git a/src/utils/error.test.ts b/src/utils/error.test.ts new file mode 100644 index 000000000..4ca14a6c0 --- /dev/null +++ b/src/utils/error.test.ts @@ -0,0 +1,19 @@ +import { inspect } from 'util'; + +import { createTerseError } from './error'; + +describe('createTerseError', () => { + it('creates a terse error for `util.inspect`', () => { + const message = 'Badness!'; + + const err = createTerseError(message); + + // Retains standard message and stack behaviour + expect(err.message).toBe(message); + expect(err.stack).not.toBe(message); + expect(err.stack).toContain(message); + + // Declares custom inspect function + expect(inspect(err)).toBe(message); + }); +}); diff --git a/src/utils/error.ts b/src/utils/error.ts index b373e9c43..dbed305cc 100644 --- a/src/utils/error.ts +++ b/src/utils/error.ts @@ -21,6 +21,20 @@ export const ConcurrentlyErrors = t.Array( }), ); +/** + * Creates an error that returns its plain `message` rather than a full stack + * trace when `util.inspect`ed. + * + * This can be useful for terser handling and logging of known error scenarios + * that have descriptive messages. + * + * https://nodejs.org/api/util.html#custom-inspection-functions-on-objects + */ +export const createTerseError = (message?: string) => + Object.assign(new Error(message), { + [inspect.custom]: () => message, + }); + const isExecaError = (err: unknown): err is ExecaError => hasNumberProp(err, 'exitCode'); diff --git a/src/utils/version.ts b/src/utils/version.ts index 0242b1046..9a9adc592 100644 --- a/src/utils/version.ts +++ b/src/utils/version.ts @@ -1,16 +1,13 @@ import latestVersion from 'latest-version'; import { getSkubaManifest } from './manifest'; - -const sleep = (ms: number) => - new Promise((resolve) => setTimeout(resolve, ms)); +import { withTimeout } from './wait'; const latestSkubaVersion = async (): Promise => { try { - // Don't pull an Apple; bail out before holding up the command for too long - const result = await Promise.race([latestVersion('skuba'), sleep(2_000)]); + const result = await withTimeout(latestVersion('skuba'), { s: 2 }); - return typeof result === 'string' ? result : null; + return result.ok ? result.value : null; } catch { return null; } diff --git a/src/utils/wait.test.ts b/src/utils/wait.test.ts new file mode 100644 index 000000000..99c6e9495 --- /dev/null +++ b/src/utils/wait.test.ts @@ -0,0 +1,98 @@ +import * as wait from './wait'; + +const sleep = jest.spyOn(wait, 'sleep'); + +beforeEach(jest.resetAllMocks); + +describe('throwOnTimeout', () => { + const withMicrotaskDelay = () => + Promise.resolve() + .then(() => undefined) + .then(() => undefined); + + it('propagates a fulfilled promise within the timeout', async () => { + sleep.mockImplementation(withMicrotaskDelay); + + const value = 123; + const promise = jest.fn().mockResolvedValue(value); + + await expect(wait.throwOnTimeout(promise(), { s: 3 })).resolves.toBe(value); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 3_000); + }); + + it('propagates a rejected promise within the timeout', async () => { + sleep.mockImplementation(withMicrotaskDelay); + + const err = new Error('Badness!'); + + const promise = jest.fn().mockRejectedValue(err); + + await expect(wait.throwOnTimeout(promise(), { s: 2 })).rejects.toThrow(err); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 2_000); + }); + + it('enforces the timeout', async () => { + sleep.mockResolvedValue(); + + const promise = jest.fn().mockImplementation(withMicrotaskDelay); + + await expect( + wait.throwOnTimeout(promise(), { s: 1 }), + ).rejects.toThrowErrorMatchingInlineSnapshot(`"Timed out after 1 second"`); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 1_000); + }); +}); + +describe('withTimeout', () => { + const withMicrotaskDelay = () => + Promise.resolve() + .then(() => undefined) + .then(() => undefined); + + it('propagates a fulfilled promise within the timeout', async () => { + sleep.mockImplementation(withMicrotaskDelay); + + const value = 123; + const promise = jest.fn().mockResolvedValue(value); + + await expect(wait.withTimeout(promise(), { s: 1 })).resolves.toStrictEqual({ + ok: true, + value, + }); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 1_000); + }); + + it('propagates a rejected promise within the timeout', async () => { + sleep.mockImplementation(withMicrotaskDelay); + + const err = new Error('Badness!'); + + const promise = jest.fn().mockRejectedValue(err); + + await expect(wait.withTimeout(promise(), { s: 2 })).rejects.toThrow(err); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 2_000); + }); + + it('enforces the timeout', async () => { + sleep.mockResolvedValue(); + + const promise = jest.fn().mockImplementation(withMicrotaskDelay); + + await expect(wait.withTimeout(promise(), { s: 3 })).resolves.toStrictEqual({ + ok: false, + }); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 3_000); + }); +}); diff --git a/src/utils/wait.ts b/src/utils/wait.ts new file mode 100644 index 000000000..c9c22f42a --- /dev/null +++ b/src/utils/wait.ts @@ -0,0 +1,29 @@ +import { createTerseError } from './error'; +import { pluralise } from './logging'; + +export const sleep = (ms: number) => + new Promise((resolve) => setTimeout(resolve, ms)); + +export const throwOnTimeout = async ( + promise: PromiseLike, + { s }: { s: number }, +): Promise => { + const result = await withTimeout(promise, { s }); + + if (!result.ok) { + throw createTerseError(`Timed out after ${pluralise(s, 'second')}`); + } + + return result.value; +}; + +type TimeoutResult = { ok: true; value: T } | { ok: false }; + +export const withTimeout = ( + promise: PromiseLike, + { s }: { s: number }, +): Promise> => + Promise.race>([ + promise.then((value) => ({ ok: true, value })), + sleep(s * 1_000).then(() => ({ ok: false })), + ]); From e0f5df9d71f3c99ed46e6aac797439207990d8e4 Mon Sep 17 00:00:00 2001 From: Ryan Ling Date: Sun, 10 Apr 2022 00:54:47 +1000 Subject: [PATCH 2/3] Support synchronous values too --- src/utils/wait.test.ts | 14 ++++++++++++++ src/utils/wait.ts | 4 ++-- 2 files changed, 16 insertions(+), 2 deletions(-) diff --git a/src/utils/wait.test.ts b/src/utils/wait.test.ts index 99c6e9495..e17bf6b48 100644 --- a/src/utils/wait.test.ts +++ b/src/utils/wait.test.ts @@ -55,6 +55,20 @@ describe('withTimeout', () => { .then(() => undefined) .then(() => undefined); + it('propagates a static value for easier `jest.mock`ing', async () => { + sleep.mockImplementation(withMicrotaskDelay); + + const value = 123; + + await expect(wait.withTimeout(value, { s: 1 })).resolves.toStrictEqual({ + ok: true, + value, + }); + + expect(sleep).toHaveBeenCalledTimes(1); + expect(sleep).toHaveBeenNthCalledWith(1, 1_000); + }); + it('propagates a fulfilled promise within the timeout', async () => { sleep.mockImplementation(withMicrotaskDelay); diff --git a/src/utils/wait.ts b/src/utils/wait.ts index c9c22f42a..cd9e77a7d 100644 --- a/src/utils/wait.ts +++ b/src/utils/wait.ts @@ -20,10 +20,10 @@ export const throwOnTimeout = async ( type TimeoutResult = { ok: true; value: T } | { ok: false }; export const withTimeout = ( - promise: PromiseLike, + promise: T | PromiseLike, { s }: { s: number }, ): Promise> => Promise.race>([ - promise.then((value) => ({ ok: true, value })), + Promise.resolve(promise).then((value) => ({ ok: true, value })), sleep(s * 1_000).then(() => ({ ok: false })), ]); From 19e89cd4002b8a7d18fabce452dae78b5e60e70c Mon Sep 17 00:00:00 2001 From: Ryan Ling Date: Sun, 10 Apr 2022 11:49:37 +1000 Subject: [PATCH 3/3] Clean up tests --- src/utils/wait.test.ts | 29 ++++++++++++----------------- 1 file changed, 12 insertions(+), 17 deletions(-) diff --git a/src/utils/wait.test.ts b/src/utils/wait.test.ts index e17bf6b48..10fed96ae 100644 --- a/src/utils/wait.test.ts +++ b/src/utils/wait.test.ts @@ -1,17 +1,17 @@ import * as wait from './wait'; +const delayMicrotask = () => + Promise.resolve() + .then(() => undefined) + .then(() => undefined); + const sleep = jest.spyOn(wait, 'sleep'); beforeEach(jest.resetAllMocks); describe('throwOnTimeout', () => { - const withMicrotaskDelay = () => - Promise.resolve() - .then(() => undefined) - .then(() => undefined); - it('propagates a fulfilled promise within the timeout', async () => { - sleep.mockImplementation(withMicrotaskDelay); + sleep.mockImplementation(delayMicrotask); const value = 123; const promise = jest.fn().mockResolvedValue(value); @@ -23,7 +23,7 @@ describe('throwOnTimeout', () => { }); it('propagates a rejected promise within the timeout', async () => { - sleep.mockImplementation(withMicrotaskDelay); + sleep.mockImplementation(delayMicrotask); const err = new Error('Badness!'); @@ -38,7 +38,7 @@ describe('throwOnTimeout', () => { it('enforces the timeout', async () => { sleep.mockResolvedValue(); - const promise = jest.fn().mockImplementation(withMicrotaskDelay); + const promise = jest.fn().mockImplementation(delayMicrotask); await expect( wait.throwOnTimeout(promise(), { s: 1 }), @@ -50,13 +50,8 @@ describe('throwOnTimeout', () => { }); describe('withTimeout', () => { - const withMicrotaskDelay = () => - Promise.resolve() - .then(() => undefined) - .then(() => undefined); - it('propagates a static value for easier `jest.mock`ing', async () => { - sleep.mockImplementation(withMicrotaskDelay); + sleep.mockImplementation(delayMicrotask); const value = 123; @@ -70,7 +65,7 @@ describe('withTimeout', () => { }); it('propagates a fulfilled promise within the timeout', async () => { - sleep.mockImplementation(withMicrotaskDelay); + sleep.mockImplementation(delayMicrotask); const value = 123; const promise = jest.fn().mockResolvedValue(value); @@ -85,7 +80,7 @@ describe('withTimeout', () => { }); it('propagates a rejected promise within the timeout', async () => { - sleep.mockImplementation(withMicrotaskDelay); + sleep.mockImplementation(delayMicrotask); const err = new Error('Badness!'); @@ -100,7 +95,7 @@ describe('withTimeout', () => { it('enforces the timeout', async () => { sleep.mockResolvedValue(); - const promise = jest.fn().mockImplementation(withMicrotaskDelay); + const promise = jest.fn().mockImplementation(delayMicrotask); await expect(wait.withTimeout(promise(), { s: 3 })).resolves.toStrictEqual({ ok: false,