Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
{
"changes": [
{
"packageName": "@microsoft/rush",
"comment": "",
"type": "none"
}
],
"packageName": "@microsoft/rush",
"email": "3408176+TheLarkInn@users.noreply.github.com"
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
{
"changes": [
{
"packageName": "@rushstack/rush-client-core",
"comment": "Fix the error reported for a crashed daemon, which included the stack of its crash report when FORCE_COLOR was set.",
"type": "patch"
}
],
"packageName": "@rushstack/rush-client-core",
"email": "3408176+TheLarkInn@users.noreply.github.com"
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
{
"changes": [
{
"packageName": "@rushstack/rush-daemon-transport",
"comment": "",
"type": "none"
}
],
"packageName": "@rushstack/rush-daemon-transport",
"email": "3408176+TheLarkInn@users.noreply.github.com"
}
12 changes: 8 additions & 4 deletions libraries/rush-client-core/src/DaemonDisconnect.ts
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,8 @@ const SOURCE_ARROW: RegExp = /^\s*\^[\^~]*\s*$/;
const STACK_FRAME: RegExp = /^\s+at /;
const TRACE_UNCAUGHT_HINT: string = '(Use `node --trace-uncaught';
const CONTROL_CHARACTERS: RegExp = /\p{Cc}/gu;
// eslint-disable-next-line no-control-regex
const ANSI_ESCAPE_SEQUENCE: RegExp = /\x1b\[[\x30-\x3f]*[\x20-\x2f]*[\x40-\x7e]/gu;

/** The daemon process that serves a request, and the size of its launcher log when the request was sent. */
export interface IServingDaemon {
Expand Down Expand Up @@ -122,12 +124,14 @@ export async function explainLostConnectionAsync(
/**
* Returns the first fatal error in launcher log lines: V8's `FATAL ERROR:` line, or the message of Node's report
* of an uncaught exception (its location, source line and caret, the error with its stack, then the Node.js
* version). Returns undefined when the first report does not have that shape.
* version). Returns undefined when the first report does not have that shape. ANSI escape sequences are ignored:
* with FORCE_COLOR, Node.js colors the report although the log is not a terminal.
*/
export function findLoggedFatalError(lines: ReadonlyArray<string>): string | undefined {
for (let index: number = 0; index < lines.length; index++) {
if (V8_FATAL_ERROR.test(lines[index])) return lines[index].trim();
if (NODE_REPORT_TRAILER.test(lines[index])) return findUncaughtErrorMessage(lines, index);
const plainLines: string[] = lines.map((line: string) => line.replace(ANSI_ESCAPE_SEQUENCE, ''));
for (let index: number = 0; index < plainLines.length; index++) {
if (V8_FATAL_ERROR.test(plainLines[index])) return plainLines[index].trim();
if (NODE_REPORT_TRAILER.test(plainLines[index])) return findUncaughtErrorMessage(plainLines, index);
}
return undefined;
}
Expand Down
84 changes: 45 additions & 39 deletions libraries/rush-client-core/src/test/DaemonDisconnect.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -41,32 +41,7 @@ import { withUnreapedChildAsync } from './UnreapedChildProcess';
const linuxIt: typeof it = process.platform === 'linux' ? it : it.skip;
const posixIt: typeof it = process.platform === 'win32' ? it.skip : it;

/** The lines that this Node.js version writes to stderr when `script` fails with an uncaught error. */
function getCrashReport(script: string): string[] {
const { status, stderr } = spawnSync(process.execPath, ['-e', script], { encoding: 'utf8' });
expect(status).not.toBe(0);
return stderr.split(/\r?\n/);
}

describe(findLoggedFatalError.name, () => {
it('returns the message of an uncaught error without its stack', () => {
const report: string[] = getCrashReport("setImmediate(() => { throw new Error('first\\nsecond'); })");
expect(findLoggedFatalError(['rushd started', ...report])).toBe('Error: first second');
});

it('returns the message of an unhandled rejection', () => {
expect(findLoggedFatalError(getCrashReport("Promise.reject(new TypeError('rejected'))"))).toBe(
'TypeError: rejected'
);
expect(findLoggedFatalError(getCrashReport("Promise.reject('reason')"))).toMatch(
/^UnhandledPromiseRejection: .* "reason"\.$/
);
});

it('returns a thrown value that is not an error', () => {
expect(findLoggedFatalError(getCrashReport("throw 'a plain string'"))).toBe('a plain string');
});

it("returns V8's fatal error line", () => {
const lines: string[] = [
'<--- JS stacktrace --->',
Expand All @@ -79,21 +54,52 @@ describe(findLoggedFatalError.name, () => {
);
});

it('returns the first report', () => {
const lines: string[] = [
...getCrashReport("throw new Error('first')"),
...getCrashReport("throw new Error('second')")
];
expect(findLoggedFatalError(lines)).toBe('Error: first');
});
// CI services often set FORCE_COLOR, with which Node.js colors its report although stderr is not a terminal.
describe.each(['0', '1'])('with FORCE_COLOR=%s', (forceColor: string) => {
/** The lines that this Node.js version writes to stderr when `script` fails with an uncaught error. */
function getCrashReport(script: string): string[] {
const { status, stderr } = spawnSync(process.execPath, ['-e', script], {
encoding: 'utf8',
env: { ...process.env, FORCE_COLOR: forceColor }
});
expect(status).not.toBe(0);
return stderr.split(/\r?\n/);
}

it('returns the message of an uncaught error without its stack', () => {
const report: string[] = getCrashReport("setImmediate(() => { throw new Error('first\\nsecond'); })");
expect(findLoggedFatalError(['rushd started', ...report])).toBe('Error: first second');
});

it('returns the message of an unhandled rejection', () => {
expect(findLoggedFatalError(getCrashReport("Promise.reject(new TypeError('rejected'))"))).toBe(
'TypeError: rejected'
);
expect(findLoggedFatalError(getCrashReport("Promise.reject('reason')"))).toMatch(
/^UnhandledPromiseRejection: .* "reason"\.$/
);
});

it('returns a thrown value that is not an error', () => {
expect(findLoggedFatalError(getCrashReport("throw 'a plain string'"))).toBe('a plain string');
});

it('returns undefined without a complete report', () => {
const report: string[] = getCrashReport("throw new Error('boom')");
const trailer: number = report.findIndex((line) => line.startsWith('Node.js v'));
expect(trailer).toBeGreaterThan(0);
expect(findLoggedFatalError(report.slice(0, trailer))).toBeUndefined();
expect(findLoggedFatalError(report.slice(3))).toBeUndefined();
expect(findLoggedFatalError(['rushd started', 'Node.js v22.0.0'])).toBeUndefined();
it('returns the first report', () => {
const lines: string[] = [
...getCrashReport("throw new Error('first')"),
...getCrashReport("throw new Error('second')")
];
expect(findLoggedFatalError(lines)).toBe('Error: first');
});

it('returns undefined without a complete report', () => {
const report: string[] = getCrashReport("throw new Error('boom')");
const trailer: number = report.findIndex((line) => line.startsWith('Node.js v'));
expect(trailer).toBeGreaterThan(0);
expect(findLoggedFatalError(report.slice(0, trailer))).toBeUndefined();
expect(findLoggedFatalError(report.slice(3))).toBeUndefined();
expect(findLoggedFatalError(['rushd started', 'Node.js v22.0.0'])).toBeUndefined();
});
});
});

Expand Down
26 changes: 16 additions & 10 deletions libraries/rush-client-core/src/test/NativeLockHolder.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -39,15 +39,24 @@ function writeLockFile(
fs.utimesSync(filePath, time, time);
}

/** Says that it runs, then runs until its stdin ends. */
const PROGRAM_SCRIPT: string =
"process.stdout.write('started');process.stdin.resume();process.stdin.on('end',()=>process.exit(0));";

/** Starts `node <args>` to run {@link PROGRAM_SCRIPT}, and waits until it runs. */
async function startNodeAsync(args: string[]): Promise<ChildProcess> {
const child: ChildProcess = spawn(process.execPath, args, { stdio: ['pipe', 'pipe', 'ignore'] });
await once(child, 'spawn');
// Just after the spawn event, the process can still be in exec, before /proc shows its command line.
await once(child.stdout!, 'data');
return child;
}

/** Starts a process that looks like `<program> <args>` to /proc, and runs until its stdin ends. */
async function startProgramAsync(folder: string, program: string, args: string[]): Promise<ChildProcess> {
const script: string = path.join(folder, program);
fs.writeFileSync(script, "process.stdin.resume();process.stdin.on('end',()=>process.exit(0));");
const child: ChildProcess = spawn(process.execPath, [script, ...args], {
stdio: ['pipe', 'ignore', 'ignore']
});
await once(child, 'spawn');
return child;
fs.writeFileSync(script, PROGRAM_SCRIPT);
return await startNodeAsync([script, ...args]);
}

async function stopProgramAsync(child: ChildProcess): Promise<void> {
Expand Down Expand Up @@ -196,10 +205,7 @@ describe(findNativeLockHolder.name, () => {

linuxIt('names only the PID of a holder whose command it cannot shorten', async () => {
const folder: string = createLockFolder('no-command');
const holder: ChildProcess = spawn(process.execPath, ['-e', 'process.stdin.resume()'], {
stdio: ['pipe', 'ignore', 'ignore']
});
await once(holder, 'spawn');
const holder: ChildProcess = await startNodeAsync(['-e', PROGRAM_SCRIPT]);
children.push(holder);
writeLockFile(folder, holder.pid!);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -370,8 +370,9 @@ function unlinkSockets(folder: string): void {
}, 30000);

it('names the parent that has not reaped an owner that exited', async () => {
// "sleep 0" exits at once, and the shell, now "sleep 600", never reaps it.
const parent: ChildProcess = await startChildAsync('sh', ['-c', 'sleep 0 & echo $!; exec sleep 600']);
// The shell, once it is "sleep 600", never reaps "sleep 1". A child that exits before that exec, as "sleep 0"
// can on a busy machine, is reaped by the shell.
const parent: ChildProcess = await startChildAsync('sh', ['-c', 'sleep 1 & echo $!; exec sleep 600']);
const [output] = await once(parent.stdout!, 'data');
const zombie: number = Number(String(output));
await waitForStateAsync(zombie, 'Z');
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -18,14 +18,15 @@ import { createTestDaemonPaths } from './TestDaemonFixture';

const linuxIt: jest.It = process.platform === 'linux' ? it : it.skip;
const SLEEP_ARGS: string[] = ['-e', 'setTimeout(() => {}, 30000)'];
// Writes the PID as plain text: with FORCE_COLOR, which CI services often set, console.log colors a number.
const HOLD_STDIO_ARGS: string[] = [
'-e',
`
const { spawn } = require('node:child_process');
const child = spawn(process.execPath, ${JSON.stringify(SLEEP_ARGS)}, {
stdio: ['ignore', 'inherit', 'inherit']
});
console.log(child.pid);
process.stdout.write(String(child.pid));
process.exit(0);
`
];
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ import type { IStartedProcess } from './ProcessWaitFixture';
import { createTestDaemonPaths } from './TestDaemonFixture';

const linuxIt: jest.It = process.platform === 'linux' ? it : it.skip;
const SLEEP_ARGS: string[] = ['-e', 'setTimeout(() => {}, 30000)'];
const SLEEP_ARGS: string[] = ['-e', "process.stdout.write('started'); setTimeout(() => {}, 30000)"];
const NAME: string = 'RUSHD_TEST_ENVIRONMENT_ENTRY';
const VALUE: string = '/tmp/rushd-1000/key.pid.json.groups-4242';
const FOREIGN_FOLDER: string = '/elsewhere.groups-4242';
Expand Down Expand Up @@ -49,11 +49,13 @@ linuxIt('marks the processes started while it records, and removes only its own
linuxIt('finds only an exact entry of the environment that a process started with', async () => {
const child: ChildProcess = spawn(process.execPath, SLEEP_ARGS, {
env: { [NAME]: VALUE },
stdio: 'ignore'
stdio: ['ignore', 'pipe', 'ignore']
});
await once(child, 'spawn');
const pid: number = Number(child.pid);
started = identifyStarted([pid]);
// Just after the spawn event, the process can still be in exec, before /proc shows its environment.
await once(child.stdout!, 'data');
expect(hasEnvironmentEntry(pid, ENTRY)).toBe(true);
for (const entry of [`${NAME}=${FOREIGN_FOLDER}`, `${NAME}=`, NAME, `${ENTRY}/`, VALUE]) {
expect(hasEnvironmentEntry(pid, entry)).toBe(false);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -7,30 +7,26 @@ import { once } from 'node:events';
import * as fs from 'node:fs';
import * as path from 'node:path';

import { DAEMON_OPERATION_GROUPS_ENV_VAR } from '../DaemonOperationGroupMarker';
import { DAEMON_OPERATION_GROUPS_ENV_VAR, getOperationGroupsMarker } from '../DaemonOperationGroupMarker';
import { reapDeadDaemonOperationGroupsAsync } from '../DaemonOperationGroupReaper';
import { getOperationGroupsFolder } from '../DaemonOperationGroups';
import { POSIX_PROCESS_GROUP_OPS } from '../DaemonProcessGroup';
import { hasEnvironmentEntry } from '../DaemonProcessStat';
import type { IDaemonOrphanReaperOptions } from '../DaemonReapOptions';
import type { IDaemonOrphanReap } from '../DaemonReclaimOptions';

import { DEAD_PID } from './OrphanReaperFixture';
import { identifyStarted, isAlive, killStillRunning, waitUntilAsync } from './ProcessWaitFixture';
import type { IStartedProcess } from './ProcessWaitFixture';
import { createTestDaemonPaths } from './TestDaemonFixture';
import { readTicks } from './UptimeTicksFixture';

const linuxIt: jest.It = process.platform === 'linux' ? it : it.skip;
const PROC_UPTIME: string = '/proc/uptime';
const UTF8: BufferEncoding = 'utf8';
const DECIMAL_POINT: string = '.';
const FRACTION_START: number = 0;
const HUNDREDTHS_DIGITS: number = 2;
const TICKS_PER_SECOND: number = 100;
// Twice the 1 s after a mark in which a reap considers a process as started by the marked spawn.
const LONG_BEFORE_TICKS: number = 200;
const NO_TICKS: number = 0;
const GRACE_MS: number = 500;
// Enough for the 5 s wait for the sleeper to be gone, so a failure shows what the reap did.
// Enough for the 5 s waits for the sleeper to start and to be gone, so a failure shows what the reap did.
const TEST_TIMEOUT_MS: number = 15000;
const SLEEP_SECONDS: string = '30';
const OPTIONS: IDaemonOrphanReaperOptions = {
Expand All @@ -50,18 +46,15 @@ afterEach(() => {
started = [];
});

// The clock ticks since boot, read with this test's own parser.
function readTicks(): number {
const [seconds, fraction] = fs.readFileSync(PROC_UPTIME, UTF8).split(DECIMAL_POINT);
return Number(seconds) * TICKS_PER_SECOND + Number(fraction.slice(FRACTION_START, HUNDREDTHS_DIGITS));
}

async function spawnMarkedSleeperAsync(folder: string): Promise<number> {
const env: NodeJS.ProcessEnv = { PATH: process.env.PATH, [DAEMON_OPERATION_GROUPS_ENV_VAR]: folder };
const sleeper: ChildProcess = spawn('sleep', [SLEEP_SECONDS], { detached: true, stdio: 'ignore', env });
await once(sleeper, 'spawn');
started = identifyStarted([Number(sleeper.pid)]);
return Number(sleeper.pid);
const pid: number = Number(sleeper.pid);
started = identifyStarted([pid]);
// Just after the spawn event, the sleeper can still be in exec, before /proc shows its environment.
expect(await waitUntilAsync(() => hasEnvironmentEntry(pid, getOperationGroupsMarker(folder)))).toBe(true);
return pid;
}

// Marks a spawn `ticksBefore` ticks ago in the dead daemon's folder, starts a detached sleeper with the daemon's
Expand All @@ -84,11 +77,15 @@ async function reapAfterMarkAsync(ticksBefore: number): Promise<IMarkedReap> {
return { sleeper, outcome, reaped };
}

linuxIt('reaps an unrecorded detached process with the marker that started just after a spawn mark', async () => {
const { sleeper, outcome, reaped } = await reapAfterMarkAsync(NO_TICKS);
const gone: boolean = await waitUntilAsync(() => !isAlive(sleeper));
expect({ outcome, reaped, gone }).toEqual({ outcome: 'terminated', reaped: [[sleeper]], gone: true });
}, TEST_TIMEOUT_MS);
linuxIt(
'reaps an unrecorded detached process with the marker that started just after a spawn mark',
async () => {
const { sleeper, outcome, reaped } = await reapAfterMarkAsync(NO_TICKS);
const gone: boolean = await waitUntilAsync(() => !isAlive(sleeper));
expect({ outcome, reaped, gone }).toEqual({ outcome: 'terminated', reaped: [[sleeper]], gone: true });
},
TEST_TIMEOUT_MS
);

linuxIt('never signals a process with the marker that started over 1 s after the spawn mark', async () => {
const { sleeper, outcome, reaped } = await reapAfterMarkAsync(LONG_BEFORE_TICKS);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,11 +8,13 @@ import { hasEnvironmentEntry } from '../DaemonProcessStat';

import { killFakeDaemonAsync, startFakeDaemonAsync } from './FakeOperationDaemonFixture';
import type { IFakeDaemon } from './FakeOperationDaemonFixture';
import { identifyStarted, killStillRunning } from './ProcessWaitFixture';
import { identifyStarted, killStillRunning, waitUntilAsync } from './ProcessWaitFixture';
import type { IStartedProcess } from './ProcessWaitFixture';
import { createTestDaemonPaths } from './TestDaemonFixture';

const linuxIt: jest.It = process.platform === 'linux' ? it : it.skip;
// Enough for the 5 s wait for the marker, so a failure shows which process lacks it.
const TEST_TIMEOUT_MS: number = 15000;

let started: IStartedProcess[] = [];
afterEach(() => {
Expand All @@ -32,10 +34,12 @@ linuxIt(
const otherMarker: string = getOperationGroupsMarker(
getOperationGroupsFolder(paths.lockfilePath, process.pid)
);
expect(fake.pids.map((pid: number) => hasEnvironmentEntry(pid, marker))).toEqual(
fake.pids.map(() => true)
);
const hasMarker = (pid: number): boolean => hasEnvironmentEntry(pid, marker);
// A grandchild can still be in exec, before /proc shows its environment.
await waitUntilAsync(() => fake.pids.every(hasMarker));
expect(fake.pids.map(hasMarker)).toEqual(fake.pids.map(() => true));
expect(fake.pids.some((pid: number) => hasEnvironmentEntry(pid, otherMarker))).toBe(false);
await killFakeDaemonAsync(fake);
}
},
TEST_TIMEOUT_MS
);
17 changes: 17 additions & 0 deletions libraries/rush-daemon-transport/src/test/UptimeTicksFixture.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,17 @@
// Copyright (c) Microsoft Corporation. All rights reserved. Licensed under the MIT license.
// See LICENSE in the project root for license information.

import * as fs from 'node:fs';

const PROC_UPTIME: string = '/proc/uptime';
const UTF8: BufferEncoding = 'utf8';
const DECIMAL_POINT: string = '.';
const FRACTION_START: number = 0;
const HUNDREDTHS_DIGITS: number = 2;
const TICKS_PER_SECOND: number = 100;

/** The clock ticks since boot, read with the tests' own parser. */
export function readTicks(): number {
const [seconds, fraction] = fs.readFileSync(PROC_UPTIME, UTF8).split(DECIMAL_POINT);
return Number(seconds) * TICKS_PER_SECOND + Number(fraction.slice(FRACTION_START, HUNDREDTHS_DIGITS));
}
Loading
Loading