Allow the extension host to restart as many times as desired (#1022)

cspell.json

@@ -30,6 +30,7 @@
     "hopkinson",
     "iframes",
     "iife",
+    "interprocess",
     "iusfm",
     "iusj",
     "iusx",

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 () => {

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();
 }
 

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<number> | undefined;
 let extensionHost: ChildProcess | ChildProcessByStdio<null, Readable, Readable> | undefined;
 
-let resolveClose: (value: void | PromiseLike<void>) => void;
-const closePromise: Promise<void> = new Promise<void>((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<number>(
+    `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,
 };
 

src/node/models/interprocess-messages.model.ts

@@ -0,0 +1,2 @@
+export const gracefulShutdownMessage = 'gracefulShutdown';
+export const heartbeatMessage = 'heartbeat';