From 53aaeef8b74fb68e7986e319f96e85dca3c2a407 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 23 Dec 2024 15:16:02 -0500 Subject: [PATCH 01/27] implement basic tracker class --- .../core/src/shared/utilities/processUtils.ts | 51 ++++++++++++++++++- 1 file changed, 50 insertions(+), 1 deletion(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 2e179da98b8..481813032f5 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -7,6 +7,8 @@ import * as proc from 'child_process' // eslint-disable-line no-restricted-impor import * as crossSpawn from 'cross-spawn' import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' +import { PollingSet } from './pollingSet' +import { getLogger } from '../logger/logger' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -61,6 +63,53 @@ export interface ChildProcessResult { export const eof = Symbol('EOF') +export class ChildProcessTracker extends Map { + static pollingInterval: number = 5000 + #processPoller: PollingSet + + public constructor() { + super() + this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => {}) + } + + private cleanUpProcesses() { + const terminatedProcesses = Array.from(this.#processPoller.values()).filter( + (pid: number) => !this.has(pid) || this.get(pid)?.stopped + ) + for (const pid of terminatedProcesses) { + this.#processPoller.delete(pid) + } + } + + public monitorProcesses() { + this.cleanUpProcesses() + getLogger().debug(`Active running processes size: ${this.#processPoller.size}`) + + for (const pid of this.#processPoller.values()) { + const process = this.get(pid) + if (process) { + getLogger().debug(`Active running process: ${process.toString()}`) + } + } + } + + public override set(key: number, value: ChildProcess): this { + this.#processPoller.add(key) + super.set(key, value) + return this + } + + public override delete(key: number): boolean { + this.#processPoller.delete(key) + return super.delete(key) + } + + public override clear(): void { + this.#processPoller.clear() + super.clear() + } +} + /** * Convenience class to manage a child process * To use: @@ -68,7 +117,7 @@ export const eof = Symbol('EOF') * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: Map = new Map() + static #runningProcesses: ChildProcessTracker = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined From d48f1b3faa0d89926bc3ee381ca9a8ded2d33c46 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 23 Dec 2024 16:25:38 -0500 Subject: [PATCH 02/27] add option in dev menu to start processes --- packages/core/src/dev/activation.ts | 19 +++++++++++++++++++ .../core/src/shared/utilities/processUtils.ts | 9 +++++---- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/packages/core/src/dev/activation.ts b/packages/core/src/dev/activation.ts index b4100b191ce..5064567ca82 100644 --- a/packages/core/src/dev/activation.ts +++ b/packages/core/src/dev/activation.ts @@ -24,6 +24,7 @@ import { getSessionId } from '../shared/telemetry/util' import { NotificationsController } from '../notifications/controller' import { DevNotificationsState } from '../notifications/types' import { QuickPickItem } from 'vscode' +import { ChildProcess } from '../shared/utilities/processUtils' interface MenuOption { readonly label: string @@ -44,6 +45,7 @@ export type DevFunction = | 'editAuthConnections' | 'notificationsSend' | 'forceIdeCrash' + | 'startChildProcess' export type DevOptions = { context: vscode.ExtensionContext @@ -126,6 +128,11 @@ const menuOptions: () => Record = () => { detail: `Will SIGKILL ExtHost, { pid: ${process.pid}, sessionId: '${getSessionId().slice(0, 8)}-...' }, but the IDE itself will not crash.`, executor: forceQuitIde, }, + startChildProcess: { + label: 'ChildProcess: Start child process', + detail: 'start a ChildProcess manually that is invoked through our wrapper', + executor: startChildProcess, + }, } } @@ -578,3 +585,15 @@ async function editNotifications() { await targetNotificationsController.pollForEmergencies() }) } + +async function startChildProcess() { + const result = await createInputBox({ + title: 'Enter a command', + }).prompt() + if (result) { + const [command, ...args] = result?.toString().split(' ') ?? [] + getLogger().info(`Starting child process: '${command}'`) + const processResult = await ChildProcess.run(command, args, { collect: true }) + getLogger().info(`Child process exited with code ${processResult.exitCode}`) + } +} diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 481813032f5..4141dc705f3 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -63,13 +63,14 @@ export interface ChildProcessResult { export const eof = Symbol('EOF') -export class ChildProcessTracker extends Map { - static pollingInterval: number = 5000 +class ChildProcessTracker extends Map { + static pollingInterval: number = 1000 #processPoller: PollingSet public constructor() { super() - this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => {}) + this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitorProcesses()) + getLogger().debug(`ChildProcessTracker created with polling interval: ${ChildProcessTracker.pollingInterval}`) } private cleanUpProcesses() { @@ -94,7 +95,7 @@ export class ChildProcessTracker extends Map { } public override set(key: number, value: ChildProcess): this { - this.#processPoller.add(key) + this.#processPoller.start(key) super.set(key, value) return this } From 44fe332ee735f6d50f5bd5e73521102c818f95d4 Mon Sep 17 00:00:00 2001 From: hkobew Date: Thu, 26 Dec 2024 16:16:16 -0500 Subject: [PATCH 03/27] add dependency to track pid usage --- package-lock.json | 20 +++++++++++++++++++ package.json | 2 ++ .../core/src/shared/utilities/processUtils.ts | 17 +++++++++++----- 3 files changed, 34 insertions(+), 5 deletions(-) diff --git a/package-lock.json b/package-lock.json index 8a549622f37..75a0e6b914d 100644 --- a/package-lock.json +++ b/package-lock.json @@ -16,6 +16,8 @@ ], "dependencies": { "@types/node": "^22.7.5", + "@types/pidusage": "^2.0.5", + "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" }, @@ -9196,6 +9198,12 @@ "dev": true, "license": "MIT" }, + "node_modules/@types/pidusage": { + "version": "2.0.5", + "resolved": "https://registry.npmjs.org/@types/pidusage/-/pidusage-2.0.5.tgz", + "integrity": "sha512-MIiyZI4/MK9UGUXWt0jJcCZhVw7YdhBuTOuqP/BjuLDLZ2PmmViMIQgZiWxtaMicQfAz/kMrZ5T7PKxFSkTeUA==", + "license": "MIT" + }, "node_modules/@types/prettier": { "version": "2.7.0", "dev": true, @@ -16985,6 +16993,18 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pidusage": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/pidusage/-/pidusage-3.0.2.tgz", + "integrity": "sha512-g0VU+y08pKw5M8EZ2rIGiEBaB8wrQMjYGFfW2QVIfyT8V+fq8YFLkvlz4bz5ljvFDJYNFCWT3PWqcRr2FKO81w==", + "license": "MIT", + "dependencies": { + "safe-buffer": "^5.2.1" + }, + "engines": { + "node": ">=10" + } + }, "node_modules/pkg-dir": { "version": "4.2.0", "dev": true, diff --git a/package.json b/package.json index e658a3a916e..2fcc6d6c837 100644 --- a/package.json +++ b/package.json @@ -72,6 +72,8 @@ }, "dependencies": { "@types/node": "^22.7.5", + "@types/pidusage": "^2.0.5", + "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 4141dc705f3..67211770b49 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,6 +9,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' +import pidusage from 'pidusage' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -82,15 +83,21 @@ class ChildProcessTracker extends Map { } } - public monitorProcesses() { + public async monitorProcesses() { this.cleanUpProcesses() getLogger().debug(`Active running processes size: ${this.#processPoller.size}`) for (const pid of this.#processPoller.values()) { - const process = this.get(pid) - if (process) { - getLogger().debug(`Active running process: ${process.toString()}`) - } + await this.monitorProcess(pid) + } + } + + private async monitorProcess(pid: number) { + if (this.has(pid)) { + const stats = await pidusage(pid) + getLogger().debug(`stats for ${pid}: %O`, stats) + } else { + getLogger().warn(`Missing process with id ${pid}`) } } From 9d40215bf79db1f8c142f6a387899ed7f806c59d Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 27 Dec 2024 15:58:52 -0500 Subject: [PATCH 04/27] warn on exceeding thresholds --- .../core/src/shared/utilities/processUtils.ts | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 67211770b49..705ca6fad2d 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -66,6 +66,12 @@ export const eof = Symbol('EOF') class ChildProcessTracker extends Map { static pollingInterval: number = 1000 + static thresholds: { memory: number; cpu: number; time: number } = { + memory: 100 * 1024 * 1024, // 100 MB + cpu: 50, + time: 30 * 1000, // 30 seconds + } + #processPoller: PollingSet public constructor() { @@ -96,6 +102,15 @@ class ChildProcessTracker extends Map { if (this.has(pid)) { const stats = await pidusage(pid) getLogger().debug(`stats for ${pid}: %O`, stats) + if (stats.memory > ChildProcessTracker.thresholds.memory) { + getLogger().warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) + } + if (stats.cpu > ChildProcessTracker.thresholds.cpu) { + getLogger().warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + } + if (stats.elapsed > ChildProcessTracker.thresholds.time) { + getLogger().warn(`Process ${pid} exceeded time threshold: ${stats.elapsed}`) + } } else { getLogger().warn(`Missing process with id ${pid}`) } From bcb6423861dd71455958f28b3a9996ac5d40cd6a Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 30 Dec 2024 10:53:38 -0500 Subject: [PATCH 05/27] add first test case --- .../core/src/shared/utilities/pollingSet.ts | 2 +- .../core/src/shared/utilities/processUtils.ts | 85 ++++++++++++------- .../shared/utilities/processUtils.test.ts | 23 ++++- 3 files changed, 76 insertions(+), 34 deletions(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index 321dde153b8..6f297c11bd8 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -44,7 +44,7 @@ export class PollingSet extends Set { this.clearTimer() } } - + // TODO(hkobew): Overwrite the add method instead of adding seperate method. If we add item to set, timer should always start. public start(id: T): void { this.add(id) this.pollTimer = this.pollTimer ?? globals.clock.setInterval(() => this.poll(), this.interval) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 705ca6fad2d..958fe379f4a 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -62,45 +62,53 @@ export interface ChildProcessResult { signal?: string } +interface Tracker { + add(item: T): void + delete(item: T): void + has(item: T): boolean + size(): number + cleanUp(): void + monitor(): void | Promise +} + export const eof = Symbol('EOF') -class ChildProcessTracker extends Map { - static pollingInterval: number = 1000 +export class ChildProcessTracker implements Tracker { + static pollingInterval: number = 10000 static thresholds: { memory: number; cpu: number; time: number } = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, time: 30 * 1000, // 30 seconds } - - #processPoller: PollingSet + #processByPid: Map = new Map() + #pids: PollingSet public constructor() { - super() - this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitorProcesses()) + this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) getLogger().debug(`ChildProcessTracker created with polling interval: ${ChildProcessTracker.pollingInterval}`) } - private cleanUpProcesses() { - const terminatedProcesses = Array.from(this.#processPoller.values()).filter( - (pid: number) => !this.has(pid) || this.get(pid)?.stopped + public cleanUp() { + const terminatedProcesses = Array.from(this.#pids.values()).filter( + (pid: number) => !this.#pids.has(pid) || this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { - this.#processPoller.delete(pid) + this.#pids.delete(pid) } } - public async monitorProcesses() { - this.cleanUpProcesses() - getLogger().debug(`Active running processes size: ${this.#processPoller.size}`) + public async monitor() { + this.cleanUp() + getLogger().debug(`Active running processes size: ${this.#pids.size}`) - for (const pid of this.#processPoller.values()) { - await this.monitorProcess(pid) + for (const pid of this.#pids.values()) { + await this.checkProcessUsage(pid) } } - private async monitorProcess(pid: number) { - if (this.has(pid)) { - const stats = await pidusage(pid) + private async checkProcessUsage(pid: number): Promise { + if (this.#pids.has(pid)) { + const stats = await this.getUsage(pid) getLogger().debug(`stats for ${pid}: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { getLogger().warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) @@ -116,20 +124,33 @@ class ChildProcessTracker extends Map { } } - public override set(key: number, value: ChildProcess): this { - this.#processPoller.start(key) - super.set(key, value) - return this + public add(childProcess: ChildProcess) { + const pid = childProcess.pid() + this.#processByPid.set(pid, childProcess) + this.#pids.start(pid) + } + + public delete(childProcess: ChildProcess) { + const pid = childProcess.pid() + this.#processByPid.delete(pid) + this.#pids.delete(pid) } - public override delete(key: number): boolean { - this.#processPoller.delete(key) - return super.delete(key) + public size() { + return this.#pids.size } - public override clear(): void { - this.#processPoller.clear() - super.clear() + public has(childProcess: ChildProcess) { + return this.#pids.has(childProcess.pid()) + } + + private async getUsage(pid: number): Promise<{ memory: number; cpu: number; elapsed: number }> { + const stats = await pidusage(pid) + return { + memory: stats.memory, + cpu: stats.cpu, + elapsed: stats.elapsed, + } } } @@ -140,7 +161,7 @@ class ChildProcessTracker extends Map { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: ChildProcessTracker = new ChildProcessTracker() + static #runningProcesses: Tracker = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -213,7 +234,7 @@ export class ChildProcess { const args = this.#args.concat(options.extraArgs ?? []) const debugDetail = this.#log.logLevelEnabled('debug') - ? ` (running processes: ${ChildProcess.#runningProcesses.size})` + ? ` (running processes: ${ChildProcess.#runningProcesses.size()})` : '' this.#log.info(`Command: ${this.toString(options.logging === 'noparams')}${debugDetail}`) @@ -381,7 +402,7 @@ export class ChildProcess { if (pid === undefined) { return } - ChildProcess.#runningProcesses.set(pid, this) + ChildProcess.#runningProcesses.add(this) const timeoutListener = options?.timeout?.token.onCancellationRequested(({ agent }) => { const message = agent === 'user' ? 'Cancelled: ' : 'Timed out: ' @@ -391,7 +412,7 @@ export class ChildProcess { const dispose = () => { timeoutListener?.dispose() - ChildProcess.#runningProcesses.delete(pid) + ChildProcess.#runningProcesses.delete(this) } process.on('exit', dispose) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index c6e3da722db..ca7f52b7eb6 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -7,10 +7,12 @@ import assert from 'assert' import * as os from 'os' import * as path from 'path' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, eof } from '../../../shared/utilities/processUtils' +import { ChildProcess, ChildProcessTracker, eof } from '../../../shared/utilities/processUtils' import { sleep } from '../../../shared/utilities/timeoutUtils' import { Timeout, waitUntil } from '../../../shared/utilities/timeoutUtils' import { fs } from '../../../shared' +import * as FakeTimers from '@sinonjs/fake-timers' +import { installFakeClock } from '../../testUtil' describe('ChildProcess', async function () { let tempFolder: string @@ -350,3 +352,22 @@ describe('ChildProcess', async function () { await writeShellFile(filename, file) } }) + +describe('ChildProcessTracker', function () { + let tracker: ChildProcessTracker + let clock: FakeTimers.InstalledClock + before(function () { + clock = installFakeClock() + tracker = new ChildProcessTracker() + }) + + it('removes stopped processes every X seconds', async function () { + const childProcess = new ChildProcess('echo', ['hi']) + await childProcess.run() + tracker.add(childProcess) + childProcess.stop() + assert.strictEqual(tracker.has(childProcess), true) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess), false) + }) +}) From 8975c3314bd8483746f26f2193f8b98bb07fa0da Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 30 Dec 2024 14:33:11 -0500 Subject: [PATCH 06/27] expand test suite --- .../core/src/shared/utilities/processUtils.ts | 14 +-- .../shared/utilities/processUtils.test.ts | 88 +++++++++++++++++-- 2 files changed, 90 insertions(+), 12 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 958fe379f4a..d78ec2d42d1 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -73,19 +73,23 @@ interface Tracker { export const eof = Symbol('EOF') +export interface ProcessStats { + memory: number + cpu: number + elapsed: number +} export class ChildProcessTracker implements Tracker { static pollingInterval: number = 10000 - static thresholds: { memory: number; cpu: number; time: number } = { + static thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, - time: 30 * 1000, // 30 seconds + elapsed: 30 * 1000, // 30 seconds } #processByPid: Map = new Map() #pids: PollingSet public constructor() { this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) - getLogger().debug(`ChildProcessTracker created with polling interval: ${ChildProcessTracker.pollingInterval}`) } public cleanUp() { @@ -116,7 +120,7 @@ export class ChildProcessTracker implements Tracker { if (stats.cpu > ChildProcessTracker.thresholds.cpu) { getLogger().warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } - if (stats.elapsed > ChildProcessTracker.thresholds.time) { + if (stats.elapsed > ChildProcessTracker.thresholds.elapsed) { getLogger().warn(`Process ${pid} exceeded time threshold: ${stats.elapsed}`) } } else { @@ -144,7 +148,7 @@ export class ChildProcessTracker implements Tracker { return this.#pids.has(childProcess.pid()) } - private async getUsage(pid: number): Promise<{ memory: number; cpu: number; elapsed: number }> { + public async getUsage(pid: number): Promise { const stats = await pidusage(pid) return { memory: stats.memory, diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index ca7f52b7eb6..5028ca3fb41 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -7,12 +7,15 @@ import assert from 'assert' import * as os from 'os' import * as path from 'path' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, ChildProcessTracker, eof } from '../../../shared/utilities/processUtils' +import { ChildProcess, ChildProcessTracker, eof, ProcessStats } from '../../../shared/utilities/processUtils' import { sleep } from '../../../shared/utilities/timeoutUtils' import { Timeout, waitUntil } from '../../../shared/utilities/timeoutUtils' import { fs } from '../../../shared' import * as FakeTimers from '@sinonjs/fake-timers' import { installFakeClock } from '../../testUtil' +import { isWin } from '../../../shared/vscode/env' +import Sinon from 'sinon' +import { assertLogsContain } from '../../globalSetup.test' describe('ChildProcess', async function () { let tempFolder: string @@ -353,6 +356,10 @@ describe('ChildProcess', async function () { } }) +function getSleepCmd() { + return isWin() ? 'timeout' : 'sleep' +} + describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock @@ -361,13 +368,80 @@ describe('ChildProcessTracker', function () { tracker = new ChildProcessTracker() }) - it('removes stopped processes every X seconds', async function () { - const childProcess = new ChildProcess('echo', ['hi']) - await childProcess.run() + it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { + // Start a 'sleep' command, check it only removes after we stop it. + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + tracker.add(childProcess) + assert.strictEqual(tracker.has(childProcess), true, 'failed to add sleep command') + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') + childProcess.stop(true) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') + }) + + it('multiple processes from same command are tracked seperately', async function () { + const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) + const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) + childProcess1.run().catch(() => assert.fail('sleep command threw an error')) + childProcess2.run().catch(() => assert.fail('sleep command threw an error')) + + tracker.add(childProcess1) + tracker.add(childProcess2) + + assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') + assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') + assert.strictEqual(tracker.size(), 2) + + childProcess1.stop() + await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) + assert.strictEqual(tracker.has(childProcess2), true, 'first process was not removed after stopping it') + assert.strictEqual(tracker.size(), 1) + + childProcess2.stop() + await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) + assert.strictEqual(tracker.size(), 0, 'second process was not removed after stopping it') + }) + + it('logs a warning message when system usage exceeds threshold', async function () { + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) tracker.add(childProcess) - childProcess.stop() - assert.strictEqual(tracker.has(childProcess), true) + + const usageMock = Sinon.stub(ChildProcessTracker.prototype, 'getUsage') + const highCpu: ProcessStats = { + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + elapsed: 0, + } + const highMemory: ProcessStats = { + cpu: 0, + memory: ChildProcessTracker.thresholds.memory + 1, + elapsed: 0, + } + + const highTime: ProcessStats = { + cpu: 0, + memory: 0, + elapsed: ChildProcessTracker.thresholds.elapsed + 1, + } + + usageMock.resolves(highCpu) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded cpu threshold', false, 'warn') + + usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess), false) + assertLogsContain('exceeded memory threshold', false, 'warn') + + usageMock.resolves(highTime) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded time threshold', false, 'warn') + + usageMock.restore() }) }) From 72681fd96253cd64e48789d02ccee2b84513aecc Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 11:20:45 -0500 Subject: [PATCH 07/27] simplify and expand test suite --- .../core/src/shared/utilities/pollingSet.ts | 5 +++ .../core/src/shared/utilities/processUtils.ts | 31 +++++++++++-------- .../shared/utilities/processUtils.test.ts | 22 +++++++------ 3 files changed, 35 insertions(+), 23 deletions(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index 6f297c11bd8..a9f7ef60fe4 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -49,4 +49,9 @@ export class PollingSet extends Set { this.add(id) this.pollTimer = this.pollTimer ?? globals.clock.setInterval(() => this.poll(), this.interval) } + + public override clear(): void { + this.pollTimer = undefined + super.clear() + } } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index d78ec2d42d1..029ecb3e1fa 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -62,13 +62,14 @@ export interface ChildProcessResult { signal?: string } -interface Tracker { +interface Tracker { add(item: T): void - delete(item: T): void + delete(id: P): void has(item: T): boolean size(): number cleanUp(): void monitor(): void | Promise + clear(): void } export const eof = Symbol('EOF') @@ -78,9 +79,9 @@ export interface ProcessStats { cpu: number elapsed: number } -export class ChildProcessTracker implements Tracker { - static pollingInterval: number = 10000 - static thresholds: ProcessStats = { +export class ChildProcessTracker implements Tracker { + static readonly pollingInterval: number = 10000 + static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, elapsed: 30 * 1000, // 30 seconds @@ -94,10 +95,10 @@ export class ChildProcessTracker implements Tracker { public cleanUp() { const terminatedProcesses = Array.from(this.#pids.values()).filter( - (pid: number) => !this.#pids.has(pid) || this.#processByPid.get(pid)?.stopped + (pid: number) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { - this.#pids.delete(pid) + this.delete(pid) } } @@ -134,10 +135,9 @@ export class ChildProcessTracker implements Tracker { this.#pids.start(pid) } - public delete(childProcess: ChildProcess) { - const pid = childProcess.pid() - this.#processByPid.delete(pid) - this.#pids.delete(pid) + public delete(childProcessId: number) { + this.#processByPid.delete(childProcessId) + this.#pids.delete(childProcessId) } public size() { @@ -156,6 +156,11 @@ export class ChildProcessTracker implements Tracker { elapsed: stats.elapsed, } } + + public clear() { + this.#pids.clear() + this.#processByPid.clear() + } } /** @@ -165,7 +170,7 @@ export class ChildProcessTracker implements Tracker { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: Tracker = new ChildProcessTracker() + static #runningProcesses: Tracker = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -416,7 +421,7 @@ export class ChildProcess { const dispose = () => { timeoutListener?.dispose() - ChildProcess.#runningProcesses.delete(this) + ChildProcess.#runningProcesses.delete(this.pid()) } process.on('exit', dispose) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 5028ca3fb41..4952bc1d64c 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -6,6 +6,7 @@ import assert from 'assert' import * as os from 'os' import * as path from 'path' +import * as sinon from 'sinon' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' import { ChildProcess, ChildProcessTracker, eof, ProcessStats } from '../../../shared/utilities/processUtils' import { sleep } from '../../../shared/utilities/timeoutUtils' @@ -14,7 +15,6 @@ import { fs } from '../../../shared' import * as FakeTimers from '@sinonjs/fake-timers' import { installFakeClock } from '../../testUtil' import { isWin } from '../../../shared/vscode/env' -import Sinon from 'sinon' import { assertLogsContain } from '../../globalSetup.test' describe('ChildProcess', async function () { @@ -368,6 +368,14 @@ describe('ChildProcessTracker', function () { tracker = new ChildProcessTracker() }) + afterEach(function () { + tracker.clear() + }) + + after(function () { + clock.uninstall() + }) + it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { // Start a 'sleep' command, check it only removes after we stop it. const childProcess = new ChildProcess(getSleepCmd(), ['90']) @@ -388,22 +396,16 @@ describe('ChildProcessTracker', function () { const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) childProcess1.run().catch(() => assert.fail('sleep command threw an error')) childProcess2.run().catch(() => assert.fail('sleep command threw an error')) - tracker.add(childProcess1) tracker.add(childProcess2) assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - assert.strictEqual(tracker.size(), 2) childProcess1.stop() - await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) + await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'first process was not removed after stopping it') assert.strictEqual(tracker.size(), 1) - - childProcess2.stop() - await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) - assert.strictEqual(tracker.size(), 0, 'second process was not removed after stopping it') }) it('logs a warning message when system usage exceeds threshold', async function () { @@ -411,7 +413,7 @@ describe('ChildProcessTracker', function () { childProcess.run().catch(() => assert.fail('sleep command threw an error')) tracker.add(childProcess) - const usageMock = Sinon.stub(ChildProcessTracker.prototype, 'getUsage') + const usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, @@ -442,6 +444,6 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded time threshold', false, 'warn') - usageMock.restore() + sinon.restore() }) }) From 5c652b61df62b5a20750eea0abd6f7616b45eef6 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 13:14:13 -0500 Subject: [PATCH 08/27] add more tests --- .../shared/utilities/processUtils.test.ts | 35 +++++++++++++++++-- 1 file changed, 33 insertions(+), 2 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 4952bc1d64c..9274a678217 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -363,13 +363,17 @@ function getSleepCmd() { describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock + let usageMock: sinon.SinonStub + before(function () { clock = installFakeClock() tracker = new ChildProcessTracker() + usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') }) afterEach(function () { tracker.clear() + usageMock.reset() }) after(function () { @@ -413,7 +417,6 @@ describe('ChildProcessTracker', function () { childProcess.run().catch(() => assert.fail('sleep command threw an error')) tracker.add(childProcess) - const usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, @@ -443,7 +446,35 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highTime) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded time threshold', false, 'warn') + }) + + it('includes pid in logs', async function () { + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + tracker.add(childProcess) + + usageMock.resolves({ + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + elapsed: 0, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain(childProcess.pid().toString(), false, 'warn') + }) + + it('does not log for processes within threshold', async function () { + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + + usageMock.resolves({ + cpu: ChildProcessTracker.thresholds.cpu - 1, + memory: ChildProcessTracker.thresholds.memory - 1, + elapsed: ChildProcessTracker.thresholds.elapsed - 1, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) - sinon.restore() + assert.throws(() => assertLogsContain(childProcess.pid().toString(), false, 'warn')) }) }) From 6bb8c7430ddab6c89d271f2b2f6c4693406c4849 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 14:05:53 -0500 Subject: [PATCH 09/27] refactor --- .../core/src/shared/utilities/processUtils.ts | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 029ecb3e1fa..3d719f30e33 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -67,8 +67,6 @@ interface Tracker { delete(id: P): void has(item: T): boolean size(): number - cleanUp(): void - monitor(): void | Promise clear(): void } @@ -79,7 +77,7 @@ export interface ProcessStats { cpu: number elapsed: number } -export class ChildProcessTracker implements Tracker { +export class ChildProcessTracker { static readonly pollingInterval: number = 10000 static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB @@ -93,7 +91,7 @@ export class ChildProcessTracker implements Tracker { this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) } - public cleanUp() { + private cleanUp() { const terminatedProcesses = Array.from(this.#pids.values()).filter( (pid: number) => this.#processByPid.get(pid)?.stopped ) @@ -102,7 +100,7 @@ export class ChildProcessTracker implements Tracker { } } - public async monitor() { + private async monitor() { this.cleanUp() getLogger().debug(`Active running processes size: ${this.#pids.size}`) @@ -148,6 +146,11 @@ export class ChildProcessTracker implements Tracker { return this.#pids.has(childProcess.pid()) } + public clear() { + this.#pids.clear() + this.#processByPid.clear() + } + public async getUsage(pid: number): Promise { const stats = await pidusage(pid) return { @@ -156,11 +159,6 @@ export class ChildProcessTracker implements Tracker { elapsed: stats.elapsed, } } - - public clear() { - this.#pids.clear() - this.#processByPid.clear() - } } /** From a9224d3c5f37db9da08bdac8590be9e6638e5f9f Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 14:56:18 -0500 Subject: [PATCH 10/27] remove tracker interface --- packages/core/src/shared/utilities/processUtils.ts | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 3d719f30e33..a1062f2f277 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -62,14 +62,6 @@ export interface ChildProcessResult { signal?: string } -interface Tracker { - add(item: T): void - delete(id: P): void - has(item: T): boolean - size(): number - clear(): void -} - export const eof = Symbol('EOF') export interface ProcessStats { @@ -168,7 +160,7 @@ export class ChildProcessTracker { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: Tracker = new ChildProcessTracker() + static #runningProcesses = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined From 4bfff0ad09c8ff4cbf0c37332ef0b80123a5664a Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 09:46:17 -0500 Subject: [PATCH 11/27] refactor wording --- packages/core/src/dev/activation.ts | 2 +- packages/core/src/shared/utilities/processUtils.ts | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/core/src/dev/activation.ts b/packages/core/src/dev/activation.ts index 5064567ca82..b986a95e44e 100644 --- a/packages/core/src/dev/activation.ts +++ b/packages/core/src/dev/activation.ts @@ -130,7 +130,7 @@ const menuOptions: () => Record = () => { }, startChildProcess: { label: 'ChildProcess: Start child process', - detail: 'start a ChildProcess manually that is invoked through our wrapper', + detail: 'Start ChildProcess from our utility wrapper for testing', executor: startChildProcess, }, } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index a1062f2f277..d2b6f035918 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -139,6 +139,9 @@ export class ChildProcessTracker { } public clear() { + for (const childProcess of this.#processByPid.values()) { + childProcess.stop(true) + } this.#pids.clear() this.#processByPid.clear() } From 2df75062fe2cea60958692cf40b8a9645894b1c1 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:11:01 -0500 Subject: [PATCH 12/27] use topic logger --- packages/core/src/shared/logger/logger.ts | 2 +- .../core/src/shared/utilities/processUtils.ts | 25 ++++++++++++------- 2 files changed, 17 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/logger/logger.ts b/packages/core/src/shared/logger/logger.ts index 9cc04aa6585..d5bf5f13380 100644 --- a/packages/core/src/shared/logger/logger.ts +++ b/packages/core/src/shared/logger/logger.ts @@ -5,7 +5,7 @@ import * as vscode from 'vscode' -export type LogTopic = 'crashMonitoring' | 'dev/beta' | 'notifications' | 'test' | 'unknown' +export type LogTopic = 'crashMonitoring' | 'dev/beta' | 'notifications' | 'test' | 'childProcess' | 'unknown' class ErrorLog { constructor( diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index d2b6f035918..346b4151e6e 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -76,6 +76,7 @@ export class ChildProcessTracker { cpu: 50, elapsed: 30 * 1000, // 30 seconds } + static readonly logger = getLogger('childProcess') #processByPid: Map = new Map() #pids: PollingSet @@ -94,7 +95,7 @@ export class ChildProcessTracker { private async monitor() { this.cleanUp() - getLogger().debug(`Active running processes size: ${this.#pids.size}`) + ChildProcessTracker.logger.debug(`Active running processes size: ${this.#pids.size}`) for (const pid of this.#pids.values()) { await this.checkProcessUsage(pid) @@ -102,20 +103,26 @@ export class ChildProcessTracker { } private async checkProcessUsage(pid: number): Promise { - if (this.#pids.has(pid)) { - const stats = await this.getUsage(pid) - getLogger().debug(`stats for ${pid}: %O`, stats) + if (!this.#pids.has(pid)) { + ChildProcessTracker.logger.warn(`ChildProcess: Missing process with id ${pid}`) + return + } + const stats = await this.getUsage(pid) + if (stats) { + ChildProcessTracker.logger.debug(`stats for ${pid}: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { - getLogger().warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) + ChildProcessTracker.logger.warn( + `ChildProcess: Process ${pid} exceeded memory threshold: ${stats.memory}` + ) } if (stats.cpu > ChildProcessTracker.thresholds.cpu) { - getLogger().warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + ChildProcessTracker.logger.warn(`ChildProcess: Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } if (stats.elapsed > ChildProcessTracker.thresholds.elapsed) { - getLogger().warn(`Process ${pid} exceeded time threshold: ${stats.elapsed}`) + ChildProcessTracker.logger.warn( + `ChildProcess: Process ${pid} exceeded time threshold: ${stats.elapsed}` + ) } - } else { - getLogger().warn(`Missing process with id ${pid}`) } } From efe336e1db71ccb0dd52fe05c86bbdc92ad43e57 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:11:19 -0500 Subject: [PATCH 13/27] improve test performance by properly stopping timer --- .../core/src/shared/utilities/pollingSet.ts | 2 +- .../shared/utilities/processUtils.test.ts | 35 ++++++++++--------- 2 files changed, 19 insertions(+), 18 deletions(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index a9f7ef60fe4..1f0d57c1843 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -51,7 +51,7 @@ export class PollingSet extends Set { } public override clear(): void { - this.pollTimer = undefined + this.clearTimer() super.clear() } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 9274a678217..882cb3311ff 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -394,23 +394,24 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') }) - - it('multiple processes from same command are tracked seperately', async function () { - const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) - const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) - childProcess1.run().catch(() => assert.fail('sleep command threw an error')) - childProcess2.run().catch(() => assert.fail('sleep command threw an error')) - tracker.add(childProcess1) - tracker.add(childProcess2) - - assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') - assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - - childProcess1.stop() - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess2), true, 'first process was not removed after stopping it') - assert.strictEqual(tracker.size(), 1) - }) + for (const _ of Array.from({ length: 1000 })) { + it('multiple processes from same command are tracked seperately', async function () { + const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) + const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) + childProcess1.run().catch(() => assert.fail('sleep command threw an error')) + childProcess2.run().catch(() => assert.fail('sleep command threw an error')) + tracker.add(childProcess1) + tracker.add(childProcess2) + + assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') + assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') + + childProcess1.stop() + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') + assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') + }) + } it('logs a warning message when system usage exceeds threshold', async function () { const childProcess = new ChildProcess(getSleepCmd(), ['90']) From 30ab5b5c7f8486de9cb9988f9adc309e0c6a94e0 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:20:26 -0500 Subject: [PATCH 14/27] fix circular dep --- packages/core/src/shared/utilities/pollingSet.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index 1f0d57c1843..68ee34c4c21 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -3,7 +3,7 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { globals } from '..' +import globals from '../extensionGlobals' /** * A useful abstraction that does the following: From 10537e124a01218a16960e364210f3352586e1ab Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:22:50 -0500 Subject: [PATCH 15/27] add debugging messages for flaky test --- packages/core/src/shared/utilities/processUtils.ts | 2 ++ packages/core/src/test/shared/utilities/processUtils.test.ts | 1 + 2 files changed, 3 insertions(+) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 346b4151e6e..2cc8e1739ad 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -85,10 +85,12 @@ export class ChildProcessTracker { } private cleanUp() { + console.log('in clean up') const terminatedProcesses = Array.from(this.#pids.values()).filter( (pid: number) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { + console.log('removing %s', pid) this.delete(pid) } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 882cb3311ff..e31877894f9 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -407,6 +407,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') childProcess1.stop() + console.log('child process 1 stopped') await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') From 46a556bdb28522185069a1fd2d7d0cc093cd0040 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:31:44 -0500 Subject: [PATCH 16/27] add safe wrapper around stop --- packages/core/src/shared/utilities/processUtils.ts | 5 ++--- .../src/test/shared/utilities/processUtils.test.ts | 10 +++++++--- 2 files changed, 9 insertions(+), 6 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 2cc8e1739ad..56b99284c88 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -85,12 +85,10 @@ export class ChildProcessTracker { } private cleanUp() { - console.log('in clean up') const terminatedProcesses = Array.from(this.#pids.values()).filter( (pid: number) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { - console.log('removing %s', pid) this.delete(pid) } } @@ -173,6 +171,7 @@ export class ChildProcessTracker { */ export class ChildProcess { static #runningProcesses = new ChildProcessTracker() + static stopTimeout = 3000 #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -389,7 +388,7 @@ export class ChildProcess { child.kill(signal) if (force === true) { - waitUntil(async () => this.stopped, { timeout: 3000, interval: 200, truthy: true }) + waitUntil(async () => this.stopped, { timeout: ChildProcess.stopTimeout, interval: 200, truthy: true }) .then((stopped) => { if (!stopped) { child.kill('SIGKILL') diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index e31877894f9..d5a56ac5141 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -360,6 +360,11 @@ function getSleepCmd() { return isWin() ? 'timeout' : 'sleep' } +async function stopAndWait(cp: ChildProcess) { + cp.stop(true) + await waitUntil(async () => cp.stopped, { timeout: ChildProcess.stopTimeout * 2, interval: 100, truthy: true }) +} + describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock @@ -389,7 +394,7 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') - childProcess.stop(true) + await stopAndWait(childProcess) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') @@ -406,8 +411,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - childProcess1.stop() - console.log('child process 1 stopped') + await stopAndWait(childProcess1) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') From 3c1531f68014db51589a3638176652297c5f7853 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:46:31 -0500 Subject: [PATCH 17/27] avoid waitUntil with stubbed clock --- .../src/test/shared/utilities/processUtils.test.ts | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index d5a56ac5141..86f8a2e83db 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -360,9 +360,10 @@ function getSleepCmd() { return isWin() ? 'timeout' : 'sleep' } -async function stopAndWait(cp: ChildProcess) { +// ChildProcess.stop is non-async and doesn't wait for the process to be stopped. +async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { cp.stop(true) - await waitUntil(async () => cp.stopped, { timeout: ChildProcess.stopTimeout * 2, interval: 100, truthy: true }) + await clock.tickAsync(ChildProcess.stopTimeout) } describe('ChildProcessTracker', function () { @@ -394,12 +395,12 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') - await stopAndWait(childProcess) + await stopAndWait(childProcess, clock) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') }) - for (const _ of Array.from({ length: 1000 })) { + for (const _ of Array.from({ length: 100 })) { it('multiple processes from same command are tracked seperately', async function () { const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) @@ -411,7 +412,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - await stopAndWait(childProcess1) + await stopAndWait(childProcess1, clock) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') From e9b4605c0d796d4deb8b3a5d7e0c801867757f88 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:16:51 -0500 Subject: [PATCH 18/27] remove dependency --- package-lock.json | 20 ------- package.json | 2 - .../core/src/shared/utilities/processUtils.ts | 55 ++++++++++++++----- .../shared/utilities/processUtils.test.ts | 13 ----- 4 files changed, 42 insertions(+), 48 deletions(-) diff --git a/package-lock.json b/package-lock.json index 75a0e6b914d..8a549622f37 100644 --- a/package-lock.json +++ b/package-lock.json @@ -16,8 +16,6 @@ ], "dependencies": { "@types/node": "^22.7.5", - "@types/pidusage": "^2.0.5", - "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" }, @@ -9198,12 +9196,6 @@ "dev": true, "license": "MIT" }, - "node_modules/@types/pidusage": { - "version": "2.0.5", - "resolved": "https://registry.npmjs.org/@types/pidusage/-/pidusage-2.0.5.tgz", - "integrity": "sha512-MIiyZI4/MK9UGUXWt0jJcCZhVw7YdhBuTOuqP/BjuLDLZ2PmmViMIQgZiWxtaMicQfAz/kMrZ5T7PKxFSkTeUA==", - "license": "MIT" - }, "node_modules/@types/prettier": { "version": "2.7.0", "dev": true, @@ -16993,18 +16985,6 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, - "node_modules/pidusage": { - "version": "3.0.2", - "resolved": "https://registry.npmjs.org/pidusage/-/pidusage-3.0.2.tgz", - "integrity": "sha512-g0VU+y08pKw5M8EZ2rIGiEBaB8wrQMjYGFfW2QVIfyT8V+fq8YFLkvlz4bz5ljvFDJYNFCWT3PWqcRr2FKO81w==", - "license": "MIT", - "dependencies": { - "safe-buffer": "^5.2.1" - }, - "engines": { - "node": ">=10" - } - }, "node_modules/pkg-dir": { "version": "4.2.0", "dev": true, diff --git a/package.json b/package.json index 2fcc6d6c837..e658a3a916e 100644 --- a/package.json +++ b/package.json @@ -72,8 +72,6 @@ }, "dependencies": { "@types/node": "^22.7.5", - "@types/pidusage": "^2.0.5", - "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 56b99284c88..a9ef46364bc 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,7 +9,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' -import pidusage from 'pidusage' +import { isWin } from '../vscode/env' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -67,14 +67,12 @@ export const eof = Symbol('EOF') export interface ProcessStats { memory: number cpu: number - elapsed: number } export class ChildProcessTracker { static readonly pollingInterval: number = 10000 static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, - elapsed: 30 * 1000, // 30 seconds } static readonly logger = getLogger('childProcess') #processByPid: Map = new Map() @@ -118,11 +116,6 @@ export class ChildProcessTracker { if (stats.cpu > ChildProcessTracker.thresholds.cpu) { ChildProcessTracker.logger.warn(`ChildProcess: Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } - if (stats.elapsed > ChildProcessTracker.thresholds.elapsed) { - ChildProcessTracker.logger.warn( - `ChildProcess: Process ${pid} exceeded time threshold: ${stats.elapsed}` - ) - } } } @@ -154,11 +147,47 @@ export class ChildProcessTracker { } public async getUsage(pid: number): Promise { - const stats = await pidusage(pid) - return { - memory: stats.memory, - cpu: stats.cpu, - elapsed: stats.elapsed, + const getWindowsUsage = () => { + const cpuOutput = proc + .execFileSync('wmic', [ + 'path', + 'Win32_PerfFormattedData_PerfProc_Process', + 'where', + `IDProcess=${pid}`, + 'get', + 'PercentProcessorTime', + ]) + .toString() + const memOutput = proc + .execFileSync('wmic', ['process', 'where', `ProcessId=${pid}`, 'get', 'WorkingSetSize']) + .toString() + + const cpuPercentage = parseFloat(cpuOutput.split('\n')[1]) + const memoryBytes = parseInt(memOutput.split('\n')[1]) * 1024 + + return { + cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memory: memoryBytes, + } + } + const getUnixUsage = () => { + const cpuMemOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', '%cpu,%mem']).toString() + const rssOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', 'rss']).toString() + + const cpuMemLines = cpuMemOutput.split('\n')[1].trim().split(/\s+/) + const cpuPercentage = parseFloat(cpuMemLines[0]) + const memoryBytes = parseInt(rssOutput.split('\n')[1]) * 1024 + + return { + cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memory: memoryBytes, + } + } + try { + return isWin() ? getWindowsUsage() : getUnixUsage() + } catch (e) { + ChildProcessTracker.logger.warn(`ChildProcess: Failed to get process stats for ${pid}: ${e}`) + return { cpu: 0, memory: 0 } } } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 86f8a2e83db..e867bb7d887 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -427,18 +427,10 @@ describe('ChildProcessTracker', function () { const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, - elapsed: 0, } const highMemory: ProcessStats = { cpu: 0, memory: ChildProcessTracker.thresholds.memory + 1, - elapsed: 0, - } - - const highTime: ProcessStats = { - cpu: 0, - memory: 0, - elapsed: ChildProcessTracker.thresholds.elapsed + 1, } usageMock.resolves(highCpu) @@ -449,10 +441,6 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') - - usageMock.resolves(highTime) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain('exceeded time threshold', false, 'warn') }) it('includes pid in logs', async function () { @@ -477,7 +465,6 @@ describe('ChildProcessTracker', function () { usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu - 1, memory: ChildProcessTracker.thresholds.memory - 1, - elapsed: ChildProcessTracker.thresholds.elapsed - 1, }) await clock.tickAsync(ChildProcessTracker.pollingInterval) From c1975f9754ccd620c1de163c66b00360a318df05 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:28:38 -0500 Subject: [PATCH 19/27] avoid circular dep --- packages/core/src/shared/utilities/processUtils.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index a9ef46364bc..7e7b34d0808 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,7 +9,6 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' -import { isWin } from '../vscode/env' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -184,7 +183,8 @@ export class ChildProcessTracker { } } try { - return isWin() ? getWindowsUsage() : getUnixUsage() + // isWin() leads to circular dependency. + return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() } catch (e) { ChildProcessTracker.logger.warn(`ChildProcess: Failed to get process stats for ${pid}: ${e}`) return { cpu: 0, memory: 0 } From 59f8215f3f5992be03664b8a01b2c691824921cc Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:29:48 -0500 Subject: [PATCH 20/27] fix logging statements --- packages/core/src/shared/utilities/processUtils.ts | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 7e7b34d0808..0ed88df0bfd 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -101,19 +101,17 @@ export class ChildProcessTracker { private async checkProcessUsage(pid: number): Promise { if (!this.#pids.has(pid)) { - ChildProcessTracker.logger.warn(`ChildProcess: Missing process with id ${pid}`) + ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) return } const stats = await this.getUsage(pid) if (stats) { ChildProcessTracker.logger.debug(`stats for ${pid}: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { - ChildProcessTracker.logger.warn( - `ChildProcess: Process ${pid} exceeded memory threshold: ${stats.memory}` - ) + ChildProcessTracker.logger.warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) } if (stats.cpu > ChildProcessTracker.thresholds.cpu) { - ChildProcessTracker.logger.warn(`ChildProcess: Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + ChildProcessTracker.logger.warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } } } @@ -186,7 +184,7 @@ export class ChildProcessTracker { // isWin() leads to circular dependency. return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() } catch (e) { - ChildProcessTracker.logger.warn(`ChildProcess: Failed to get process stats for ${pid}: ${e}`) + ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}: ${e}`) return { cpu: 0, memory: 0 } } } From 39175c054f6a5ac464ab0fd6a52dbdaac2d1050c Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:38:12 -0500 Subject: [PATCH 21/27] clean up tests --- .../shared/utilities/processUtils.test.ts | 22 +++++++++---------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index e867bb7d887..336a05960c3 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -366,6 +366,12 @@ async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { await clock.tickAsync(ChildProcess.stopTimeout) } +function startSleepProcess(timeout: number = 90) { + const childProcess = new ChildProcess(getSleepCmd(), [timeout.toString()]) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + return childProcess +} + describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock @@ -388,8 +394,7 @@ describe('ChildProcessTracker', function () { it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { // Start a 'sleep' command, check it only removes after we stop it. - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess = startSleepProcess() tracker.add(childProcess) assert.strictEqual(tracker.has(childProcess), true, 'failed to add sleep command') @@ -402,10 +407,8 @@ describe('ChildProcessTracker', function () { }) for (const _ of Array.from({ length: 100 })) { it('multiple processes from same command are tracked seperately', async function () { - const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) - const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) - childProcess1.run().catch(() => assert.fail('sleep command threw an error')) - childProcess2.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess1 = startSleepProcess() + const childProcess2 = startSleepProcess() tracker.add(childProcess1) tracker.add(childProcess2) @@ -420,8 +423,7 @@ describe('ChildProcessTracker', function () { } it('logs a warning message when system usage exceeds threshold', async function () { - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess = startSleepProcess() tracker.add(childProcess) const highCpu: ProcessStats = { @@ -444,14 +446,12 @@ describe('ChildProcessTracker', function () { }) it('includes pid in logs', async function () { - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess = startSleepProcess() tracker.add(childProcess) usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, - elapsed: 0, }) await clock.tickAsync(ChildProcessTracker.pollingInterval) From e04eefe3eba3426e716110c3e7d1a012bbb9100d Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:53:09 -0500 Subject: [PATCH 22/27] increase waiting period to avoid flakiness --- packages/core/src/test/shared/utilities/processUtils.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 336a05960c3..5a249eaa66e 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -363,7 +363,7 @@ function getSleepCmd() { // ChildProcess.stop is non-async and doesn't wait for the process to be stopped. async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { cp.stop(true) - await clock.tickAsync(ChildProcess.stopTimeout) + await clock.tickAsync(ChildProcess.stopTimeout * 2) } function startSleepProcess(timeout: number = 90) { From abf3603ae31f66b2aeeeee82b752208f460f8e48 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 10:33:43 -0500 Subject: [PATCH 23/27] add some debugging information for flaky test --- .../core/src/test/shared/utilities/processUtils.test.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 5a249eaa66e..7668391786c 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -364,6 +364,7 @@ function getSleepCmd() { async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { cp.stop(true) await clock.tickAsync(ChildProcess.stopTimeout * 2) + assert.ok(cp.stopped, `Failed to stop process with id: ${cp.pid()}`) } function startSleepProcess(timeout: number = 90) { @@ -405,7 +406,7 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') }) - for (const _ of Array.from({ length: 100 })) { + for (const _ of Array.from({ length: 1000 })) { it('multiple processes from same command are tracked seperately', async function () { const childProcess1 = startSleepProcess() const childProcess2 = startSleepProcess() @@ -417,6 +418,10 @@ describe('ChildProcessTracker', function () { await stopAndWait(childProcess1, clock) await clock.tickAsync(ChildProcessTracker.pollingInterval) + if (tracker.has(childProcess1)) { + console.log('process: %O', childProcess1) + console.log('tracker: %O', tracker) + } assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') }) From 4f2eaf07475cdf81c3a603dd71a1d631316326b3 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 11:32:22 -0500 Subject: [PATCH 24/27] handle result and process individually and explicitly --- .../shared/utilities/processUtils.test.ts | 96 ++++++++++++------- 1 file changed, 60 insertions(+), 36 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 7668391786c..9b1acb54567 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -8,7 +8,13 @@ import * as os from 'os' import * as path from 'path' import * as sinon from 'sinon' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, ChildProcessTracker, eof, ProcessStats } from '../../../shared/utilities/processUtils' +import { + ChildProcess, + ChildProcessResult, + ChildProcessTracker, + eof, + ProcessStats, +} from '../../../shared/utilities/processUtils' import { sleep } from '../../../shared/utilities/timeoutUtils' import { Timeout, waitUntil } from '../../../shared/utilities/timeoutUtils' import { fs } from '../../../shared' @@ -356,21 +362,24 @@ describe('ChildProcess', async function () { } }) +interface RunningProcess { + childProcess: ChildProcess + result: Promise +} + function getSleepCmd() { return isWin() ? 'timeout' : 'sleep' } -// ChildProcess.stop is non-async and doesn't wait for the process to be stopped. -async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { - cp.stop(true) - await clock.tickAsync(ChildProcess.stopTimeout * 2) - assert.ok(cp.stopped, `Failed to stop process with id: ${cp.pid()}`) +async function stopAndWait(runningProcess: RunningProcess): Promise { + runningProcess.childProcess.stop(true) + await runningProcess.result } -function startSleepProcess(timeout: number = 90) { +function startSleepProcess(timeout: number = 90): RunningProcess { const childProcess = new ChildProcess(getSleepCmd(), [timeout.toString()]) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) - return childProcess + const result = childProcess.run().catch(() => assert.fail('sleep command threw an error')) + return { childProcess, result } } describe('ChildProcessTracker', function () { @@ -395,41 +404,51 @@ describe('ChildProcessTracker', function () { it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { // Start a 'sleep' command, check it only removes after we stop it. - const childProcess = startSleepProcess() - tracker.add(childProcess) - assert.strictEqual(tracker.has(childProcess), true, 'failed to add sleep command') + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'failed to add sleep command') await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') - await stopAndWait(childProcess, clock) + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'process was mistakenly removed') + await stopAndWait(runningProcess) await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') + assert.strictEqual(tracker.has(runningProcess.childProcess), false, 'process was not removed after stopping') }) for (const _ of Array.from({ length: 1000 })) { it('multiple processes from same command are tracked seperately', async function () { - const childProcess1 = startSleepProcess() - const childProcess2 = startSleepProcess() - tracker.add(childProcess1) - tracker.add(childProcess2) + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() + tracker.add(runningProcess1.childProcess) + tracker.add(runningProcess2.childProcess) - assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') - assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') + assert.strictEqual(tracker.has(runningProcess1.childProcess), true, 'Missing first process') + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'Missing second process') - await stopAndWait(childProcess1, clock) + await stopAndWait(runningProcess1) await clock.tickAsync(ChildProcessTracker.pollingInterval) - if (tracker.has(childProcess1)) { - console.log('process: %O', childProcess1) - console.log('tracker: %O', tracker) - } - assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') - assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'second process was mistakenly removed') + assert.strictEqual( + tracker.has(runningProcess1.childProcess), + false, + 'first process was not removed after stopping it' + ) + + await stopAndWait(runningProcess2) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual( + tracker.has(runningProcess2.childProcess), + false, + 'second process was not removed after stopping it' + ) + + assert.strictEqual(tracker.size(), 0, 'expected tracker to be empty') }) } it('logs a warning message when system usage exceeds threshold', async function () { - const childProcess = startSleepProcess() - tracker.add(childProcess) + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, @@ -448,11 +467,13 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') + + await stopAndWait(runningProcess) }) it('includes pid in logs', async function () { - const childProcess = startSleepProcess() - tracker.add(childProcess) + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu + 1, @@ -460,12 +481,13 @@ describe('ChildProcessTracker', function () { }) await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain(childProcess.pid().toString(), false, 'warn') + assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn') + + await stopAndWait(runningProcess) }) it('does not log for processes within threshold', async function () { - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const runningProcess = startSleepProcess() usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu - 1, @@ -474,6 +496,8 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.throws(() => assertLogsContain(childProcess.pid().toString(), false, 'warn')) + assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + + await stopAndWait(runningProcess) }) }) From b0976b32e718a678a0ef95b28151a8107e425782 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 11:48:40 -0500 Subject: [PATCH 25/27] remove repeat tests --- .../shared/utilities/processUtils.test.ts | 59 +++++++++---------- 1 file changed, 29 insertions(+), 30 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 9b1acb54567..93d042f904d 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -415,36 +415,35 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(runningProcess.childProcess), false, 'process was not removed after stopping') }) - for (const _ of Array.from({ length: 1000 })) { - it('multiple processes from same command are tracked seperately', async function () { - const runningProcess1 = startSleepProcess() - const runningProcess2 = startSleepProcess() - tracker.add(runningProcess1.childProcess) - tracker.add(runningProcess2.childProcess) - - assert.strictEqual(tracker.has(runningProcess1.childProcess), true, 'Missing first process') - assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'Missing second process') - - await stopAndWait(runningProcess1) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'second process was mistakenly removed') - assert.strictEqual( - tracker.has(runningProcess1.childProcess), - false, - 'first process was not removed after stopping it' - ) - - await stopAndWait(runningProcess2) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual( - tracker.has(runningProcess2.childProcess), - false, - 'second process was not removed after stopping it' - ) - - assert.strictEqual(tracker.size(), 0, 'expected tracker to be empty') - }) - } + + it('multiple processes from same command are tracked seperately', async function () { + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() + tracker.add(runningProcess1.childProcess) + tracker.add(runningProcess2.childProcess) + + assert.strictEqual(tracker.has(runningProcess1.childProcess), true, 'Missing first process') + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'Missing second process') + + await stopAndWait(runningProcess1) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'second process was mistakenly removed') + assert.strictEqual( + tracker.has(runningProcess1.childProcess), + false, + 'first process was not removed after stopping it' + ) + + await stopAndWait(runningProcess2) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual( + tracker.has(runningProcess2.childProcess), + false, + 'second process was not removed after stopping it' + ) + + assert.strictEqual(tracker.size(), 0, 'expected tracker to be empty') + }) it('logs a warning message when system usage exceeds threshold', async function () { const runningProcess = startSleepProcess() From ec3abbfc4a792a85ce1376c23f991fd61794a04b Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 12:41:38 -0500 Subject: [PATCH 26/27] reword logging statement --- packages/core/src/shared/utilities/processUtils.ts | 8 ++++---- .../core/src/test/shared/utilities/processUtils.test.ts | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 0ed88df0bfd..de6d5875c79 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -68,7 +68,7 @@ export interface ProcessStats { cpu: number } export class ChildProcessTracker { - static readonly pollingInterval: number = 10000 + static readonly pollingInterval: number = 10000 // Check usage every 10 seconds static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, @@ -106,7 +106,7 @@ export class ChildProcessTracker { } const stats = await this.getUsage(pid) if (stats) { - ChildProcessTracker.logger.debug(`stats for ${pid}: %O`, stats) + ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { ChildProcessTracker.logger.warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) } @@ -127,7 +127,7 @@ export class ChildProcessTracker { this.#pids.delete(childProcessId) } - public size() { + public get size() { return this.#pids.size } @@ -271,7 +271,7 @@ export class ChildProcess { const args = this.#args.concat(options.extraArgs ?? []) const debugDetail = this.#log.logLevelEnabled('debug') - ? ` (running processes: ${ChildProcess.#runningProcesses.size()})` + ? ` (running processes: ${ChildProcess.#runningProcesses.size})` : '' this.#log.info(`Command: ${this.toString(options.logging === 'noparams')}${debugDetail}`) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 93d042f904d..3a12ae01df5 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -442,7 +442,7 @@ describe('ChildProcessTracker', function () { 'second process was not removed after stopping it' ) - assert.strictEqual(tracker.size(), 0, 'expected tracker to be empty') + assert.strictEqual(tracker.size, 0, 'expected tracker to be empty') }) it('logs a warning message when system usage exceeds threshold', async function () { From 7a702fffe3ecfd4bda3f8765ec56ade67ece80d4 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 15 Jan 2025 09:51:40 -0500 Subject: [PATCH 27/27] refactor sub-functions --- .../core/src/shared/utilities/processUtils.ts | 24 ++++++++++--------- .../shared/utilities/processUtils.test.ts | 8 +++---- 2 files changed, 17 insertions(+), 15 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index de6d5875c79..3fcd7864438 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -104,7 +104,7 @@ export class ChildProcessTracker { ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) return } - const stats = await this.getUsage(pid) + const stats = this.getUsage(pid) if (stats) { ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { @@ -143,8 +143,16 @@ export class ChildProcessTracker { this.#processByPid.clear() } - public async getUsage(pid: number): Promise { - const getWindowsUsage = () => { + public getUsage(pid: number): ProcessStats { + try { + // isWin() leads to circular dependency. + return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() + } catch (e) { + ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}: ${e}`) + return { cpu: 0, memory: 0 } + } + + function getWindowsUsage() { const cpuOutput = proc .execFileSync('wmic', [ 'path', @@ -167,7 +175,8 @@ export class ChildProcessTracker { memory: memoryBytes, } } - const getUnixUsage = () => { + + function getUnixUsage() { const cpuMemOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', '%cpu,%mem']).toString() const rssOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', 'rss']).toString() @@ -180,13 +189,6 @@ export class ChildProcessTracker { memory: memoryBytes, } } - try { - // isWin() leads to circular dependency. - return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() - } catch (e) { - ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}: ${e}`) - return { cpu: 0, memory: 0 } - } } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 3a12ae01df5..0e6f474ed10 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -458,12 +458,12 @@ describe('ChildProcessTracker', function () { memory: ChildProcessTracker.thresholds.memory + 1, } - usageMock.resolves(highCpu) + usageMock.returns(highCpu) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded cpu threshold', false, 'warn') - usageMock.resolves(highMemory) + usageMock.returns(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') @@ -474,7 +474,7 @@ describe('ChildProcessTracker', function () { const runningProcess = startSleepProcess() tracker.add(runningProcess.childProcess) - usageMock.resolves({ + usageMock.returns({ cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, }) @@ -488,7 +488,7 @@ describe('ChildProcessTracker', function () { it('does not log for processes within threshold', async function () { const runningProcess = startSleepProcess() - usageMock.resolves({ + usageMock.returns({ cpu: ChildProcessTracker.thresholds.cpu - 1, memory: ChildProcessTracker.thresholds.memory - 1, })