Fixed extension host crashing in production, reformatted logs, temporarily removed auto updater

.erb/configs/webpack.config.base.ts

@@ -65,34 +65,39 @@ const configuration: webpack.Configuration = {
 
     new webpack.IgnorePlugin({
       checkResource(resource, context) {
-        // Don't include stuff from the main folder or @main... in renderer and renderer folder in main folder
+        // Don't include stuff from process folders in each others' packages.
+        // Ex: Don't include stuff from the main folder or @main... in renderer and renderer folder in main folder
+
+        const isInMain = (res: string) =>
+          res.startsWith('@main') || res.includes('main/');
+        const isInExtensionHost = (res: string) =>
+          res.startsWith('@extension-host') || res.includes('extension-host/');
+        const isInRenderer = (res: string) =>
+          res.startsWith('@renderer') ||
+          (res.includes('renderer/') && !res.includes('electron-log-preload'));
+        // Group of processes running in node: main, extension-host
+        const isInNode = (res: string) =>
+          res.startsWith('@node') || res.includes('node/');
+        // Group of processes running as network clients: renderer, extension-host
+        const isInClient = (res: string) =>
+          res.startsWith('@client') || res.includes('client/');
+
         let exclude = false;
         switch (processType) {
           case 'renderer':
             exclude =
-              resource.startsWith('@main') ||
-              resource.includes('main/') ||
-              resource.startsWith('@extension-host') ||
-              resource.includes('extension-host/') ||
-              resource.startsWith('@node') ||
-              resource.includes('node/');
+              isInMain(resource) ||
+              isInExtensionHost(resource) ||
+              isInNode(resource);
             break;
           case 'extension-host':
-            exclude =
-              resource.startsWith('@main') ||
-              resource.includes('main/') ||
-              resource.startsWith('@renderer') ||
-              resource.includes('renderer/');
+            exclude = isInMain(resource) || isInRenderer(resource);
             break;
           default: // main
             exclude =
-              resource.startsWith('@renderer') ||
-              (/renderer\//.test(resource) &&
-                !resource.includes('electron-log-preload')) ||
-              resource.startsWith('@extension-host') ||
-              resource.includes('extension-host/') ||
-              resource.startsWith('@client') ||
-              resource.includes('client/');
+              isInRenderer(resource) ||
+              isInExtensionHost(resource) ||
+              isInClient(resource);
             break;
         }
 

src/main/main.ts

@@ -14,7 +14,8 @@ import {
   ipcMain,
   IpcMainInvokeEvent,
 } from 'electron';
-import { autoUpdater } from 'electron-updater';
+// Removed until we have a release. See https://github.com/paranext/paranext-core/issues/83
+/* import { autoUpdater } from 'electron-updater'; */
 import windowStateKeeper from 'electron-window-state';
 import '@main/globalThis';
 import dotnetDataProvider from '@main/services/dotnet-data-provider.service';
@@ -30,12 +31,13 @@ logger.log('Starting main');
 
 // #region ELECTRON SETUP
 
-class AppUpdater {
+// Removed until we have a release. See https://github.com/paranext/paranext-core/issues/83
+/* class AppUpdater {
   constructor() {
     autoUpdater.logger = logger;
     autoUpdater.checkForUpdatesAndNotify();
   }
-}
+} */
 
 // Keep a global reference of the window object. If you don't, the window will
 // be closed automatically when the JavaScript object is garbage collected.
@@ -133,7 +135,8 @@ const createWindow = async () => {
 
   // Remove this if your app does not use auto updates
   // eslint-disable-next-line
-  new AppUpdater();
+  // Removed until we have a release. See https://github.com/paranext/paranext-core/issues/83
+  // new AppUpdater();
 };
 
 app.on('window-all-closed', () => {

src/main/services/dotnet-data-provider.service.ts

@@ -1,9 +1,22 @@
 import { ChildProcessWithoutNullStreams, spawn } from 'child_process';
 import path from 'path';
-import logger from '@shared/util/logger';
+import logger, { formatLog } from '@shared/util/logger';
+
+/** Pretty name for the process this service manages. Used in logs */
+const DOTNET_DATA_PROVIDER_NAME = 'dotnet data provider';
 
 let dotnet: ChildProcessWithoutNullStreams | undefined;
 
+// log functions for inside the data provider process
+function logProcessError(message: unknown) {
+  logger.error(
+    formatLog(message?.toString() || '', DOTNET_DATA_PROVIDER_NAME, 'error'),
+  );
+}
+function logProcessInfo(message: unknown) {
+  logger.log(formatLog(message?.toString() || '', DOTNET_DATA_PROVIDER_NAME));
+}
+
 /**
  * Hard kills the Dotnet Data Provider.
  * TODO: add a more elegant shutdown to avoid this if we possibly can
@@ -12,10 +25,10 @@ function killDotnetDataProvider() {
   if (!dotnet) return;
 
   if (dotnet.kill()) {
-    logger.log('[dotnet data provider] was killed');
+    logger.info('killed dotnet data provider');
   } else {
     logger.error(
-      '[dotnet data provider] was not stopped! Investigate other .kill() options',
+      'dotnet data provider was not stopped! Investigate other .kill() options',
     );
   }
   dotnet = undefined;
@@ -51,19 +64,18 @@ function startDotnetDataProvider() {
 
   dotnet = spawn(command, args);
 
-  dotnet.stdout.on('data', (data) => {
-    logger.log(`[dotnet data provider] stdout: ${data}`);
-  });
-
-  dotnet.stderr.on('data', (data) => {
-    logger.error(`[dotnet data provider] stderr: ${data}`);
-  });
+  dotnet.stdout.on('data', logProcessInfo);
+  dotnet.stderr.on('data', logProcessError);
 
   dotnet.on('close', (code, signal) => {
     if (signal) {
-      logger.log(`[dotnet data provider] terminated with signal ${signal}`);
+      logger.info(
+        `'close' event: dotnet data provider terminated with signal ${signal}`,
+      );
     } else {
-      logger.log(`[dotnet data provider] exited with code ${code}`);
+      logger.info(
+        `'close' event: dotnet data provider exited with code ${code}`,
+      );
     }
     // TODO: listen for 'exit' event as well?
     // TODO: unsubscribe event listeners

src/main/services/extension-host.service.ts

@@ -2,17 +2,30 @@
  * Service that runs the extension-host process from the main file
  */
 
-import logger from '@shared/util/logger';
+import logger, { formatLog } from '@shared/util/logger';
 import { ChildProcess, ChildProcessByStdio, fork, spawn } from 'child_process';
 import { app } from 'electron';
 import path from 'path';
 import { Readable } from 'stream';
 
+/** Pretty name for the process this service manages. Used in logs */
+const EXTENSION_HOST_NAME = 'extension host';
+
 let extensionHost:
   | ChildProcess
   | ChildProcessByStdio<null, Readable, Readable>
   | undefined;
 
+// log functions for inside the extension host process
+function logProcessError(message: unknown) {
+  logger.error(
+    formatLog(message?.toString() || '', EXTENSION_HOST_NAME, 'error'),
+  );
+}
+function logProcessInfo(message: unknown) {
+  logger.log(formatLog(message?.toString() || '', EXTENSION_HOST_NAME));
+}
+
 /**
  * Hard kills the extension host process.
  * TODO: add a more elegant shutdown to avoid this if we possibly can
@@ -21,25 +34,15 @@ function killExtensionHost() {
   if (!extensionHost) return;
 
   if (extensionHost.kill()) {
-    logger.log('[extension host] was killed');
+    logger.info('killed extension host process');
   } else {
     logger.error(
-      '[extension host] was not stopped! Investigate other .kill() options',
+      'extension host process was not stopped! Investigate other .kill() options',
     );
   }
   extensionHost = undefined;
 }
 
-const formatExtensionHostLog = (message: string, tag = '') => {
-  const messageNoEndLine = message.trimEnd();
-  const openTag = `{eh${tag ? ' ' : ''}${tag}}`;
-  const closeTag = `{/eh${tag ? ' ' : ''}${tag}}`;
-  if (messageNoEndLine.includes('\n'))
-    // Multi-line
-    return `${openTag}\n${messageNoEndLine}\n${closeTag}`;
-  return `${openTag} ${messageNoEndLine} ${closeTag}`;
-};
-
 /**
  * Starts the extension host process if it isn't already running.
  */
@@ -67,23 +70,22 @@ function startExtensionHost() {
 
   if (!extensionHost.stderr || !extensionHost.stdout)
     logger.error(
-      "[extension host] Could not connect to extension host's stderr or stdout! You will not see extension host console logs here.",
-    );
-  else if (process.env.IN_VSCODE !== 'true') {
-    // When launched from VSCode, don't re-print the console stuff because it somehow shows it already
-    extensionHost.stderr.on('data', (data) =>
-      logger.error(formatExtensionHostLog(data.toString(), 'err')),
-    );
-    extensionHost.stdout.on('data', (data) =>
-      logger.log(formatExtensionHostLog(data.toString())),
+      "Could not connect to extension host's stderr or stdout! You will not see extension host console logs here.",
     );
+  else {
+    extensionHost.stderr.on('data', logProcessError);
+    extensionHost.stdout.on('data', logProcessInfo);
   }
 
   extensionHost.on('close', (code, signal) => {
     if (signal) {
-      logger.log(`[extension host 'close'] terminated with signal ${signal}`);
+      logger.info(
+        `'close' event: extension host process terminated with signal ${signal}`,
+      );
     } else {
-      logger.log(`[extension host 'close'] exited with code ${code}`);
+      logger.info(
+        `'close' event: extension host process exited with code ${code}`,
+      );
     }
     // TODO: listen for 'exit' event as well?
     // TODO: unsubscribe event listeners

src/shared/util/logger.ts

@@ -1,5 +1,30 @@
-import log from 'electron-log';
-import { isClient } from './InternalUtil';
+import log, { LogLevel } from 'electron-log';
+import {
+  getProcessType,
+  isClient,
+  isRenderer,
+} from '@shared/util/InternalUtil';
+
+/**
+ * Format a string of a service message
+ * @param message message from the service
+ * @param serviceName name of the service to show in the log
+ * @param tag optional tag at the end of the service name
+ * @returns formatted string of a service message
+ */
+// We can assume we will have more utility functions at some point. This is not the only thing this module will do
+// eslint-disable-next-line import/prefer-default-export
+export function formatLog(message: string, serviceName: string, tag = '') {
+  // Remove the new line at the end of every message coming from stdout from other processes
+  const messageTrimmed = message.trimEnd();
+  const openTag = `[${serviceName}${tag ? ' ' : ''}${tag}]`;
+  if (messageTrimmed.includes('\n')) {
+    const closeTag = `[/${serviceName}${tag ? ' ' : ''}${tag}]`;
+    // Multi-line
+    return `\n${openTag}\n${messageTrimmed}\n${closeTag}`;
+  }
+  return `${openTag} ${messageTrimmed}`;
+}
 
 /**
  * Abstract and shim the logger
@@ -9,6 +34,25 @@ const isProduction = process.env.NODE_ENV === 'production';
 const level = isProduction ? 'error' : 'info';
 if (isClient()) {
   log.transports.console.level = level;
+  if (isRenderer())
+    // On the renderer, insert formatting before sending
+    log.hooks.push((message) => {
+      return {
+        ...message,
+        data: message.data.map((logLine) =>
+          // We just checked above if message.variables is null
+          // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
+          formatLog(
+            logLine,
+            getProcessType(),
+            // Renderer sends back with log level of log. Not sure why it's not in the type
+            (message.level as LogLevel | 'log') === 'log'
+              ? undefined
+              : message.level,
+          ),
+        ),
+      };
+    });
 } else {
   log.initialize();
   log.transports.console.level = level;