diff --git a/cspell.json b/cspell.json index 53f24d95df..abea72f0e7 100644 --- a/cspell.json +++ b/cspell.json @@ -30,6 +30,7 @@ "hopkinson", "iframes", "iife", + "interprocess", "iusfm", "iusj", "iusx", diff --git a/src/extension-host/extension-host.ts b/src/extension-host/extension-host.ts index 720a6530c9..0eb3cc64ba 100644 --- a/src/extension-host/extension-host.ts +++ b/src/extension-host/extension-host.ts @@ -7,19 +7,28 @@ import logger from '@shared/services/logger.service'; import networkObjectService from '@shared/services/network-object.service'; import dataProviderService from '@shared/services/data-provider.service'; import extensionAssetService from '@shared/services/extension-asset.service'; -import { getErrorMessage, substring } from 'platform-bible-utils'; +import { getErrorMessage, isString, substring } from 'platform-bible-utils'; import { CommandNames } from 'papi-shared-types'; import { registerCommand } from '@shared/services/command.service'; import { initialize as initializeMenuData } from '@extension-host/services/menu-data.service-host'; import { initialize as initializeSettingsService } from '@extension-host/services/settings.service-host'; import { startProjectSettingsService } from '@extension-host/services/project-settings.service-host'; import { initialize as initializeLocalizationService } from '@extension-host/services/localization.service-host'; +import { gracefulShutdownMessage } from '@node/models/interprocess-messages.model'; logger.info( `Starting extension-host${globalThis.isNoisyDevModeEnabled ? ' in noisy dev mode' : ''}`, ); logger.info(`Extension host process.env.NODE_ENV = ${process.env.NODE_ENV}`); +// Make a graceful way to tear down the process since Windows and POSIX operating systems handle it differently +process.on('message', (message) => { + if (isString(message) && message === gracefulShutdownMessage) { + logger.info('Shutting down process due to graceful shutdown message'); + process.exit(); + } +}); + // #region Services setup (async () => { diff --git a/src/main/main.ts b/src/main/main.ts index 273f822aea..c16f9a9bac 100644 --- a/src/main/main.ts +++ b/src/main/main.ts @@ -368,7 +368,9 @@ async function main() { } async function restartExtensionHost() { + logger.info('Restarting extension host'); await extensionHostService.waitForClose(PROCESS_CLOSE_TIME_OUT); + logger.debug('Extension host closed, restarting now'); await extensionHostService.start(); } diff --git a/src/main/services/extension-host.service.ts b/src/main/services/extension-host.service.ts index b48d43a65d..8705f28bb5 100644 --- a/src/main/services/extension-host.service.ts +++ b/src/main/services/extension-host.service.ts @@ -6,50 +6,85 @@ import { commandLineArgumentsAliases, } from '@node/utils/command-line.util'; import logger, { formatLog, WARN_TAG } from '@shared/services/logger.service'; -import { includes, split, waitForDuration } from 'platform-bible-utils'; +import { AsyncVariable, includes, split, waitForDuration } from 'platform-bible-utils'; import { ChildProcess, ChildProcessByStdio, fork, spawn } from 'child_process'; import { app } from 'electron'; import path from 'path'; import { Readable } from 'stream'; +import { gracefulShutdownMessage } from '@node/models/interprocess-messages.model'; /** Pretty name for the process this service manages. Used in logs */ const EXTENSION_HOST_NAME = 'extension host'; +let processInstanceCounter = 0; +// Resolves to the current process instance counter value for debug logging purposes +let processLifetimeVariable: AsyncVariable | undefined; let extensionHost: ChildProcess | ChildProcessByStdio | undefined; -let resolveClose: (value: void | PromiseLike) => void; -const closePromise: Promise = new Promise((resolve) => { - resolveClose = resolve; -}); +function createNewProcessLifetimeVariable(): void { + if (processLifetimeVariable) + throw new Error('Previous instance of the extension host process was not cleaned up'); + + processInstanceCounter += 1; + processLifetimeVariable = new AsyncVariable( + `extension host shutting down #${processInstanceCounter.toString()}`, + -1, + ); +} + +function resolveProcessLifetimeVariable(): void { + if (!processLifetimeVariable) + throw new Error('Extension host process tracking was not properly initialized'); + + processLifetimeVariable.resolveToValue(processInstanceCounter); + processLifetimeVariable = undefined; +} // log functions for inside the extension host process function logProcessError(message: unknown) { - let msg = message?.toString() || ''; + let msg = message?.toString() ?? ''; if (includes(msg, WARN_TAG)) { msg = split(msg, WARN_TAG).join(''); logger.warn(formatLog(msg, EXTENSION_HOST_NAME, 'warning')); } else logger.error(formatLog(msg, EXTENSION_HOST_NAME, 'error')); } + function logProcessInfo(message: unknown) { - logger.info(formatLog(message?.toString() || '', EXTENSION_HOST_NAME)); + logger.info(formatLog(message?.toString() ?? '', EXTENSION_HOST_NAME)); } async function waitForExtensionHost(maxWaitTimeInMS: number) { - const didClose = await waitForDuration(async () => { - await closePromise; + let didExit = await waitForDuration(async () => { + if (!processLifetimeVariable) { + logger.warn('Extension host process lifetime variable was not initialized'); + return false; + } + // This does nothing in development because nodemon is in the way, but the hard kill will work + extensionHost?.send(gracefulShutdownMessage, (error) => { + if (error) logger.warn(`Error sending graceful shutdown message: ${error}`); + }); + await processLifetimeVariable.promise; + return true; + }, maxWaitTimeInMS / 2); + + if (!didExit) hardKillExtensionHost(); + + // Give the hard "kill" time to complete before returning so we don't restart too soon + didExit = await waitForDuration(async () => { + if (processLifetimeVariable) await processLifetimeVariable.promise; return true; - }, maxWaitTimeInMS); + }, maxWaitTimeInMS / 2); - if (!didClose) killExtensionHost(); + if (!didExit) logger.warn(`Extension host did not exit within ${maxWaitTimeInMS.toString()} ms`); } -/** Hard kills the extension host process. */ -// TODO: add a more elegant shutdown to avoid this if we possibly can -function killExtensionHost() { +function hardKillExtensionHost() { if (!extensionHost) return; - if (extensionHost.kill()) { - logger.info('killed extension host process'); + // On POSIX systems, SIGKILL should immediately terminate the process by the OS. + // On Windows the signal is ignored. Node.js tries to hard kill the process in some other way. + if (extensionHost.kill('SIGKILL')) { + logger.info('signal sent to kill extension host process'); } else { logger.error('extension host process was not stopped! Investigate other .kill() options'); } @@ -74,6 +109,8 @@ function getCommandLineArgumentsToForward() { async function startExtensionHost() { if (extensionHost) return; + createNewProcessLifetimeVariable(); + // In production, fork a new process for the extension host // In development, spawn nodemon to watch the extension-host /** Arguments that will be passed to the extension host no matter how we start the process */ @@ -140,26 +177,14 @@ async function startExtensionHost() { extensionHost?.stderr?.removeListener('data', logProcessError); extensionHost?.stdout?.removeListener('data', logProcessInfo); extensionHost = undefined; - resolveClose(); - }); - - extensionHost.once('close', (code, signal) => { - if (signal) { - logger.info(`'close' event: extension host process terminated with signal ${signal}`); - } else { - logger.info(`'close' event: extension host process exited with code ${code}`); - } - extensionHost?.stderr?.removeListener('data', logProcessError); - extensionHost?.stdout?.removeListener('data', logProcessInfo); - extensionHost = undefined; - resolveClose(); + resolveProcessLifetimeVariable(); }); } /** Service that runs the extension-host process from the main file */ const extensionHostService = { start: startExtensionHost, - kill: killExtensionHost, + kill: hardKillExtensionHost, waitForClose: waitForExtensionHost, }; diff --git a/src/node/models/interprocess-messages.model.ts b/src/node/models/interprocess-messages.model.ts new file mode 100644 index 0000000000..0d73f0b471 --- /dev/null +++ b/src/node/models/interprocess-messages.model.ts @@ -0,0 +1,2 @@ +export const gracefulShutdownMessage = 'gracefulShutdown'; +export const heartbeatMessage = 'heartbeat';