From b25c08fe0efa56c957045f267cbd4fb31fad58fa Mon Sep 17 00:00:00 2001 From: Pete Gonzalez <4673363+octogonz@users.noreply.github.com> Date: Fri, 28 May 2021 17:36:14 -0700 Subject: [PATCH] Test lots of edge cases and improve the error reporting --- apps/heft/src/plugins/NodeServicePlugin.ts | 301 ++++++++++-------- .../subprocess/SubprocessTerminator.ts | 53 ++- build-tests/heft-fastify-test/src/start.ts | 1 - 3 files changed, 217 insertions(+), 138 deletions(-) diff --git a/apps/heft/src/plugins/NodeServicePlugin.ts b/apps/heft/src/plugins/NodeServicePlugin.ts index b3a9f20206f..b2381f8d6b0 100644 --- a/apps/heft/src/plugins/NodeServicePlugin.ts +++ b/apps/heft/src/plugins/NodeServicePlugin.ts @@ -110,79 +110,84 @@ export class NodeServicePlugin implements IHeftPlugin { heftSession.hooks.build.tap(PLUGIN_NAME, (build: IBuildStageContext) => { build.hooks.loadStageConfiguration.tapPromise(PLUGIN_NAME, async () => { - this._rawConfiguration = - await CoreConfigFiles.nodeServiceConfigurationLoader.tryLoadConfigurationFileForProjectAsync( - this._logger.terminal, - heftConfiguration.buildFolder, - heftConfiguration.rigConfig - ); + await this._loadStageConfiguration(heftConfiguration); - // defaults - this._configuration = { - commandName: 'serve', - ignoreMissingScript: false, - waitBeforeRestartMs: 2000, - waitForTerminateMs: 2000, - waitForKillMs: 2000 - }; - - // TODO: @rushstack/heft-config-file should be able to read a *.defaults.json file - if (this._rawConfiguration) { - this._pluginEnabled = true; - - if (this._rawConfiguration.commandName !== undefined) { - this._configuration.commandName = this._rawConfiguration.commandName; - } - if (this._rawConfiguration.ignoreMissingScript !== undefined) { - this._configuration.ignoreMissingScript = this._rawConfiguration.ignoreMissingScript; - } - if (this._rawConfiguration.waitBeforeRestartMs !== undefined) { - this._configuration.waitBeforeRestartMs = this._rawConfiguration.waitBeforeRestartMs; - } - if (this._rawConfiguration.waitForTerminateMs !== undefined) { - this._configuration.waitForTerminateMs = this._rawConfiguration.waitForTerminateMs; - } - if (this._rawConfiguration.waitForKillMs !== undefined) { - this._configuration.waitForKillMs = this._rawConfiguration.waitForKillMs; - } - - this._shellCommand = (heftConfiguration.projectPackageJson.scripts || {})[ - this._configuration.commandName - ]; - - if (this._shellCommand === undefined) { - if (this._configuration.ignoreMissingScript) { - this._logger.terminal.writeLine( - `The plugin is disabled because the project's package.json` + - ` does not have a "${this._configuration.commandName}" script` - ); - } else { - this._logger.terminal.writeErrorLine( - `The project's package.json does not have a "${this._configuration.commandName}" script` - ); - } - this._pluginEnabled = false; - } - } else { - this._logger.terminal.writeVerboseLine( - 'The plugin is disabled because its config file was not found: ' + - CoreConfigFiles.nodeServiceConfigurationLoader.projectRelativeFilePath - ); + if (this._pluginEnabled) { + build.hooks.postBuild.tap(PLUGIN_NAME, (bundle: IPostBuildSubstage) => { + bundle.hooks.run.tapPromise(PLUGIN_NAME, async () => { + await this._runCommandAsync(heftSession, heftConfiguration); + }); + }); + + build.hooks.compile.tap(PLUGIN_NAME, (compile: ICompileSubstage) => { + compile.hooks.afterEachIteration.tap(PLUGIN_NAME, this._compileHooks_afterEachIteration); + }); } }); + }); + } - if (this._pluginEnabled) { - build.hooks.postBuild.tap(PLUGIN_NAME, (bundle: IPostBuildSubstage) => { - bundle.hooks.run.tapPromise(PLUGIN_NAME, async () => { - await this._runCommandAsync(heftSession, heftConfiguration); - }); - }); + private async _loadStageConfiguration(heftConfiguration: HeftConfiguration): Promise { + this._rawConfiguration = + await CoreConfigFiles.nodeServiceConfigurationLoader.tryLoadConfigurationFileForProjectAsync( + this._logger.terminal, + heftConfiguration.buildFolder, + heftConfiguration.rigConfig + ); - build.hooks.compile.tap(PLUGIN_NAME, (compile: ICompileSubstage) => { - compile.hooks.afterEachIteration.tap(PLUGIN_NAME, this._compileHooks_afterEachIteration); - }); + // defaults + this._configuration = { + commandName: 'serve', + ignoreMissingScript: false, + waitBeforeRestartMs: 2000, + waitForTerminateMs: 2000, + waitForKillMs: 2000 + }; + + // TODO: @rushstack/heft-config-file should be able to read a *.defaults.json file + if (this._rawConfiguration) { + this._pluginEnabled = true; + + if (this._rawConfiguration.commandName !== undefined) { + this._configuration.commandName = this._rawConfiguration.commandName; } - }); + if (this._rawConfiguration.ignoreMissingScript !== undefined) { + this._configuration.ignoreMissingScript = this._rawConfiguration.ignoreMissingScript; + } + if (this._rawConfiguration.waitBeforeRestartMs !== undefined) { + this._configuration.waitBeforeRestartMs = this._rawConfiguration.waitBeforeRestartMs; + } + if (this._rawConfiguration.waitForTerminateMs !== undefined) { + this._configuration.waitForTerminateMs = this._rawConfiguration.waitForTerminateMs; + } + if (this._rawConfiguration.waitForKillMs !== undefined) { + this._configuration.waitForKillMs = this._rawConfiguration.waitForKillMs; + } + + this._shellCommand = (heftConfiguration.projectPackageJson.scripts || {})[ + this._configuration.commandName + ]; + + if (this._shellCommand === undefined) { + if (this._configuration.ignoreMissingScript) { + this._logger.terminal.writeLine( + `The plugin is disabled because the project's package.json` + + ` does not have a "${this._configuration.commandName}" script` + ); + } else { + throw new Error( + `The node-service task cannot start because the project's package.json ` + + `does not have a "${this._configuration.commandName}" script` + ); + } + this._pluginEnabled = false; + } + } else { + this._logger.terminal.writeVerboseLine( + 'The plugin is disabled because its config file was not found: ' + + CoreConfigFiles.nodeServiceConfigurationLoader.projectRelativeFilePath + ); + } } private async _runCommandAsync( @@ -195,7 +200,7 @@ export class NodeServicePlugin implements IHeftPlugin { } private _compileHooks_afterEachIteration = (): void => { - try { + this._trapUnhandledException(() => { // We've recompiled, so try launching again this._childProcessFailed = false; @@ -205,9 +210,7 @@ export class NodeServicePlugin implements IHeftPlugin { } else { this._stopChild(); } - } catch (error) { - console.error('UNCAUGHT: ' + error.toString()); - } + }); }; private _restartChild(): void { @@ -231,69 +234,98 @@ export class NodeServicePlugin implements IHeftPlugin { ); const childPid: number = this._activeChildProcess.pid; - this._logger.terminal.writeVerboseLine(`Started child ${childPid}`); + this._logger.terminal.writeVerboseLine(`Started service process #${childPid}`); this._activeChildProcess.on('close', (code: number, signal: string): void => { - // The 'close' event is emitted after a process has ended and the stdio streams of a child process - // have been closed. This is distinct from the 'exit' event, since multiple processes might share the - // same stdio streams. The 'close' event will always emit after 'exit' was already emitted, - // or 'error' if the child failed to spawn. - - if (this._state === State.Running) { - this._logger.terminal.writeWarningLine( - `Child #${childPid} terminated unexpectedly code=${code} signal=${signal}` - ); - this._childProcessFailed = true; - this._transitionToStopped(); - return; - } + this._trapUnhandledException(() => { + // The 'close' event is emitted after a process has ended and the stdio streams of a child process + // have been closed. This is distinct from the 'exit' event, since multiple processes might share the + // same stdio streams. The 'close' event will always emit after 'exit' was already emitted, + // or 'error' if the child failed to spawn. + + if (this._state === State.Running) { + this._logger.terminal.writeWarningLine( + `The service process #${childPid} terminated unexpectedly` + + this._formatCodeOrSignal(code, signal) + ); + this._childProcessFailed = true; + this._transitionToStopped(); + return; + } - if (this._state === State.Stopping || this._state === State.Killing) { - this._logger.terminal.writeVerboseLine( - `Child #${childPid} terminated successfully code=${code} signal=${signal}` - ); - this._transitionToStopped(); - return; - } + if (this._state === State.Stopping || this._state === State.Killing) { + this._logger.terminal.writeVerboseLine( + `The service process #${childPid} terminated successfully` + + this._formatCodeOrSignal(code, signal) + ); + this._transitionToStopped(); + return; + } + }); + }); + + // This is event only fires for Node.js >= 15.x + this._activeChildProcess.on('spawn', () => { + this._trapUnhandledException(() => { + // Print a newline to separate the service's STDOUT from Heft's output + console.log(); + }); }); - // This is event requires Node.js >= 15.x this._activeChildProcess.on('exit', (code: number | null, signal: string | null) => { - this._logger.terminal.writeVerboseLine(`Got EXIT event code=${code} signal=${signal}`); + this._trapUnhandledException(() => { + this._logger.terminal.writeVerboseLine( + `The service process fired its "exit" event` + this._formatCodeOrSignal(code, signal) + ); + }); }); this._activeChildProcess.on('error', (err: Error) => { - // "The 'error' event is emitted whenever: - // 1. The process could not be spawned, or - // 2. The process could not be killed, or - // 3. Sending a message to the child process failed. - // - // The 'exit' event may or may not fire after an error has occurred. When listening to both the 'exit' - // and 'error' events, guard against accidentally invoking handler functions multiple times." - - if (this._state === State.Running) { - this._logger.terminal.writeErrorLine(`Failed to start: ` + err.toString()); - this._childProcessFailed = true; - this._transitionToStopped(); - return; - } + this._trapUnhandledException(() => { + // "The 'error' event is emitted whenever: + // 1. The process could not be spawned, or + // 2. The process could not be killed, or + // 3. Sending a message to the child process failed. + // + // The 'exit' event may or may not fire after an error has occurred. When listening to both the 'exit' + // and 'error' events, guard against accidentally invoking handler functions multiple times." + + if (this._state === State.Running) { + this._logger.terminal.writeErrorLine(`Failed to start: ` + err.toString()); + this._childProcessFailed = true; + this._transitionToStopped(); + return; + } - if (this._state === State.Stopping) { - this._logger.terminal.writeWarningLine( - `Child #${childPid} rejected shutdown signal: ` + err.toString() - ); - this._transitionToKilling(); - return; - } + if (this._state === State.Stopping) { + this._logger.terminal.writeWarningLine( + `The service process #${childPid} rejected the shutdown signal: ` + err.toString() + ); + this._transitionToKilling(); + return; + } - if (this._state === State.Killing) { - this._logger.terminal.writeErrorLine(`Child #${childPid} rejected kill signal: ` + err.toString()); - this._transitionToStopped(); - return; - } + if (this._state === State.Killing) { + this._logger.terminal.writeErrorLine( + `The service process #${childPid} could not be killed: ` + err.toString() + ); + this._transitionToStopped(); + return; + } + }); }); } + private _formatCodeOrSignal(code: number | null | undefined, signal: string | null | undefined): string { + if (signal) { + return ` (signal=${code})`; + } + if (typeof code === 'number') { + return ` (exit code ${code})`; + } + return ''; + } + private _stopChild(): void { if (this._state !== State.Running) { return; @@ -311,15 +343,16 @@ export class NodeServicePlugin implements IHeftPlugin { this._state = State.Stopping; this._clearTimeout(); - this._logger.terminal.writeVerboseLine('Sending SIGTERM'); + this._logger.terminal.writeVerboseLine('Sending SIGTERM to gracefully shut down the service process'); - // Passing a negative PID terminates the entire group instead of just the one process + // Passing a negative PID terminates the entire group instead of just the one process. + // This works because we set detached=true for child_process.spawn() process.kill(-this._activeChildProcess.pid, 'SIGTERM'); this._clearTimeout(); this._timeout = setTimeout(() => { this._timeout = undefined; - this._logger.terminal.writeWarningLine('Child is taking too long to terminate'); + this._logger.terminal.writeWarningLine('The service process is taking too long to terminate'); this._transitionToKilling(); }, this._configuration.waitForTerminateMs); } @@ -329,21 +362,19 @@ export class NodeServicePlugin implements IHeftPlugin { this._state = State.Killing; this._clearTimeout(); - this._logger.terminal.writeVerboseLine('Sending SIGKILL'); - if (!this._activeChildProcess) { // All the code paths that set _activeChildProcess=undefined should also leave the Running state throw new InternalError('_activeChildProcess should not be undefined'); } - this._logger.terminal.writeVerboseLine('Sending SIGKILL'); + this._logger.terminal.writeVerboseLine('Attempting to killing the service process'); SubprocessTerminator.killProcessTree(this._activeChildProcess, SubprocessTerminator.RECOMMENDED_OPTIONS); this._clearTimeout(); this._timeout = setTimeout(() => { this._timeout = undefined; - this._logger.terminal.writeErrorLine('Abandoning child process because SIGKILL did not work'); + this._logger.terminal.writeErrorLine('Abandoning the service process because it could not be killed'); this._transitionToStopped(); }, this._configuration.waitForKillMs); } @@ -360,7 +391,7 @@ export class NodeServicePlugin implements IHeftPlugin { this._scheduleRestart(this._configuration.waitBeforeRestartMs); } else { this._logger.terminal.writeLine( - 'The child process failed. Waiting for a code change before restarting...' + 'The service process has failed. Waiting for watch mode to recompile before restarting...' ); } } @@ -372,7 +403,7 @@ export class NodeServicePlugin implements IHeftPlugin { } this._restartTime = newTime; - this._logger.terminal.writeVerboseLine('Extending timeout'); + this._logger.terminal.writeVerboseLine(`Sleeping for ${msFromNow} milliseconds`); this._clearTimeout(); this._timeout = setTimeout(() => { @@ -390,4 +421,16 @@ export class NodeServicePlugin implements IHeftPlugin { this._timeout = undefined; } } + + private _trapUnhandledException(action: () => void): void { + try { + action(); + } catch (error) { + this._logger.emitError(error); + this._logger.terminal.writeErrorLine('An unexpected error occurred'); + + // TODO: Provide a Heft facility for this + process.exit(1); + } + } } diff --git a/apps/heft/src/utilities/subprocess/SubprocessTerminator.ts b/apps/heft/src/utilities/subprocess/SubprocessTerminator.ts index d4738fd2bcf..9d11c187fc3 100644 --- a/apps/heft/src/utilities/subprocess/SubprocessTerminator.ts +++ b/apps/heft/src/utilities/subprocess/SubprocessTerminator.ts @@ -77,8 +77,10 @@ export class SubprocessTerminator { const pid: number = subprocess.pid; subprocess.on('close', (code: number, signal: string): void => { - SubprocessTerminator._logDebug(`untracking #${pid}`); - SubprocessTerminator._subprocessesByPid.delete(pid); + if (SubprocessTerminator._subprocessesByPid.has(pid)) { + SubprocessTerminator._logDebug(`untracking #${pid}`); + SubprocessTerminator._subprocessesByPid.delete(pid); + } }); SubprocessTerminator._subprocessesByPid.set(pid, { subprocess, @@ -92,6 +94,14 @@ export class SubprocessTerminator { subprocess: child_process.ChildProcess, subprocessOptions: ISubprocessOptions ): void { + const pid: number = subprocess.pid; + + // Don't attempt to kill the same process twice + if (SubprocessTerminator._subprocessesByPid.has(pid)) { + SubprocessTerminator._logDebug(`untracking #${pid} via killProcessTree()`); + this._subprocessesByPid.delete(subprocess.pid); + } + SubprocessTerminator._validateSubprocessOptions(subprocessOptions); if (typeof subprocess.exitCode === 'number') { @@ -113,8 +123,16 @@ export class SubprocessTerminator { subprocess.pid.toString() ]); - if (result.error) { - console.error('TaskKill.exe failed: ' + result.error.toString()); + if (result.status) { + const output: string = result.output.join('\n'); + // Nonzero exit code + if (output.indexOf('not found') >= 0) { + // The PID does not exist + } else { + // Another error occurred, for example TaskKill.exe does not support + // the expected CLI syntax + throw new Error(`TaskKill.exe returned exit code ${result.status}:\n` + output + '\n'); + } } } else { // Passing a negative PID terminates the entire group instead of just the one process @@ -147,10 +165,29 @@ export class SubprocessTerminator { const trackedSubprocesses: ITrackedSubprocess[] = Array.from( SubprocessTerminator._subprocessesByPid.values() ); - SubprocessTerminator._subprocessesByPid.clear(); + + let firstError: Error | undefined = undefined; for (const trackedSubprocess of trackedSubprocesses) { - SubprocessTerminator.killProcessTree(trackedSubprocess.subprocess, { detached: true }); + try { + SubprocessTerminator.killProcessTree(trackedSubprocess.subprocess, { detached: true }); + } catch (error) { + if (firstError === undefined) { + firstError = error; + } + } + } + + if (firstError !== undefined) { + // This is generally an unexpected error such as the TaskKill.exe command not being found, + // not a trivial issue such as a nonexistent PID. Since this occurs during process shutdown, + // we should not interfere with control flow by throwing an exception or calling process.exit(). + // So simply write to STDERR and ensure our exit code indicates the problem. + console.error('\nAn unexpected error was encountered while attempting to clean up child processes:'); + console.error(firstError.toString()); + if (!process.exitCode) { + process.exitCode = 1; + } } } } @@ -186,8 +223,8 @@ export class SubprocessTerminator { // For debugging private static _logDebug(message: string): void { - // const logLine: string = `SubprocessTerminator: [${process.pid}] ${message}`; + //const logLine: string = `SubprocessTerminator: [${process.pid}] ${message}`; // fs.writeFileSync('trace.log', logLine + '\n', { flag: 'a' }); - // console.log(logLine); + //console.log(logLine); } } diff --git a/build-tests/heft-fastify-test/src/start.ts b/build-tests/heft-fastify-test/src/start.ts index 9ca432559f8..6672db451e6 100644 --- a/build-tests/heft-fastify-test/src/start.ts +++ b/build-tests/heft-fastify-test/src/start.ts @@ -51,4 +51,3 @@ class MyApp { const myApp: MyApp = new MyApp(); myApp.start(); -//