[WIP] Move process label to a global context

docs/node-renderer/error-reporting-and-tracing.md

@@ -47,13 +47,17 @@ Import these functions from `@shakacode-tools/react-on-rails-pro-node-renderer/i
 ### Error reporting services
 - `addErrorNotifier` and `addMessageNotifier` tell React on Rails Pro how to report errors to your chosen service.
 - Use `addNotifier` if the service uses the same reporting function for both JavaScript `Error`s and string messages.
+- `globalContext` contains the current process's label.
 
 For example, integrating with BugSnag can be as simple as
 ```js
 const Bugsnag = require('@bugsnag/js');
-const { addNotifier } = require('@shakacode-tools/react-on-rails-pro-node-renderer/integrations/api');
+const { addNotifier, globalContext } = require('@shakacode-tools/react-on-rails-pro-node-renderer/integrations/api');
 
-Bugsnag.start({ /* your options */ });
+Bugsnag.start({
+  metadata: globalContext,  
+  /* your apiKey and other options */
+});
 
 addNotifier((msg) => { Bugsnag.notify(msg); });
 ```

packages/node-renderer/src/integrations/api.ts

@@ -23,7 +23,8 @@
  * @module
  */
 
-export { addErrorNotifier, addMessageNotifier, addNotifier } from '../shared/errorReporter';
+export { globalContext } from '../shared/log';
+export { addErrorNotifier, addMessageNotifier, addNotifier, message, error } from '../shared/errorReporter';
 export {
   setupTracing,
   TracingContext,

packages/node-renderer/src/integrations/honeybadger.ts

@@ -1,6 +1,9 @@
-import { notify } from '@honeybadger-io/js';
+import Honeybadger from '@honeybadger-io/js';
 import { addNotifier } from '../shared/errorReporter';
+import { globalContext } from '../shared/log';
 
 export function init() {
-  addNotifier((msg) => notify(msg));
+  Honeybadger.setContext(globalContext);
+
+  addNotifier((msg) => Honeybadger.notify(msg));
 }

packages/node-renderer/src/integrations/sentry.ts

@@ -1,7 +1,8 @@
-import { captureException, captureMessage, startSpan } from '@sentry/node';
+import { captureException, captureMessage, getGlobalScope, startSpan } from '@sentry/node';
 import { StartSpanOptions } from '@sentry/types';
 import { addErrorNotifier, addMessageNotifier } from '../shared/errorReporter';
 import { setupTracing } from '../shared/tracing';
+import { globalContext } from '../shared/log';
 
 declare module '../shared/tracing' {
   interface UnitOfWorkOptions {
@@ -10,6 +11,8 @@ declare module '../shared/tracing' {
 }
 
 export function init({ tracing = false } = {}) {
+  getGlobalScope().setExtras(globalContext);
+
   addMessageNotifier((msg) => {
     captureMessage(msg);
   });

packages/node-renderer/src/integrations/sentry6.ts

@@ -1,7 +1,8 @@
-import { captureException, captureMessage, startTransaction } from '@sentry/node';
+import { captureException, captureMessage, getGlobalScope, startTransaction } from '@sentry/node';
 import { CaptureContext, TransactionContext } from '@sentry/types';
 import { addErrorNotifier, addMessageNotifier, message } from '../shared/errorReporter';
 import { setupTracing } from '../shared/tracing';
+import { globalContext } from '../shared/log';
 
 declare module '../shared/tracing' {
   interface TracingContext {
@@ -14,6 +15,8 @@ declare module '../shared/tracing' {
 }
 
 export function init({ tracing = false } = {}) {
+  getGlobalScope().setExtras(globalContext);
+
   addMessageNotifier((msg, tracingContext) => {
     captureMessage(msg, tracingContext?.sentry6);
   });

packages/node-renderer/src/shared/locks.ts

@@ -1,9 +1,10 @@
 import lockfile, { Options } from 'lockfile';
 import { promisify } from 'util';
 
+import cluster from 'cluster';
 import debug from './debug';
 import log from './log';
-import { delay, workerIdLabel } from './utils';
+import { delay } from './utils';
 
 const lockfileLockAsync = promisify<string, Options>(lockfile.lock);
 const lockfileUnlockAsync = promisify(lockfile.unlock);
@@ -48,8 +49,7 @@ const lockfileOptions = {
 };
 
 export async function unlock(lockfileName: string) {
-  debug('Worker %s: About to unlock %s', workerIdLabel(), lockfileName);
-  log.info('Worker %s: About to unlock %s', workerIdLabel(), lockfileName);
+  log.info('About to unlock %s', lockfileName);
 
   await lockfileUnlockAsync(lockfileName);
 }
@@ -69,22 +69,21 @@ type LockResult = {
 
 export async function lock(filename: string): Promise<LockResult> {
   const lockfileName = `${filename}.lock`;
-  const workerId = workerIdLabel();
 
   try {
-    debug('Worker %s: About to request lock %s', workerId, lockfileName);
-    log.info('Worker %s: About to request lock %s', workerId, lockfileName);
+    log.info('About to request lock %s', lockfileName);
     await lockfileLockAsync(lockfileName, lockfileOptions);
 
+    const workerId = cluster.worker?.id ?? 'NO WORKER ID';
     // eslint-disable-next-line @typescript-eslint/no-unnecessary-condition -- the const may be changed to test threading
     if (TEST_LOCKFILE_THREADING) {
       debug('Worker %i: handleNewBundleProvided sleeping 5s', workerId);
       await delay(5000);
       debug('Worker %i: handleNewBundleProvided done sleeping 5s', workerId);
     }
-    debug('After acquired lock in pid', lockfileName);
+    debug('Worker %i: After acquired lock %s', workerId, lockfileName);
   } catch (error) {
-    log.info('Worker %s: Failed to acquire lock %s, error %s', workerId, lockfileName, error);
+    log.info(error, 'Failed to acquire lock %s', lockfileName);
     return { lockfileName, wasLockAcquired: false, errorMessage: error as Error };
   }
   return { lockfileName, wasLockAcquired: true, errorMessage: null };

packages/node-renderer/src/shared/log.ts

@@ -1,5 +1,6 @@
 import pino from 'pino';
 import type { PrettyOptions } from 'pino-pretty';
+import cluster from 'cluster';
 
 let pretty = false;
 
@@ -13,7 +14,15 @@ if (process.env.NODE_ENV === 'development' || process.env.NODE_ENV === 'test') {
   }
 }
 
+/**
+ * Context that should be included in every log message (including integrations).
+ */
+export const globalContext = {
+  process: cluster.isPrimary ? 'primary' : `worker #${cluster.worker?.id}`,
+};
+
 export const sharedLoggerOptions: pino.LoggerOptions = {
+  base: globalContext,
   formatters: {
     level: (label) => ({ level: label }),
   },
@@ -40,8 +49,6 @@ export const sharedLoggerOptions: pino.LoggerOptions = {
 const log = pino(
   {
     name: 'RORP',
-    // Omit pid and hostname
-    base: undefined,
     ...sharedLoggerOptions,
   },
   // https://getpino.io/#/docs/help?id=best-performance-for-logging-to-stdout doesn't recommend

packages/node-renderer/src/shared/utils.ts

@@ -1,4 +1,3 @@
-import cluster from 'cluster';
 import path from 'path';
 import { MultipartFile } from '@fastify/multipart';
 import { createWriteStream, ensureDir, move, MoveOptions } from 'fs-extra';
@@ -11,11 +10,6 @@ import type { RenderResult } from '../worker/vm';
 
 export const TRUNCATION_FILLER = '\n... TRUNCATED ...\n';
 
-export function workerIdLabel() {
-  // eslint-disable-next-line @typescript-eslint/no-unnecessary-condition -- worker is nullable in the primary process
-  return cluster?.worker?.id || 'NO WORKER ID';
-}
-
 // From https://stackoverflow.com/a/831583/1009332
 export function smartTrim(value: unknown, maxLength = getConfig().maxDebugSnippetLength) {
   let string;

packages/node-renderer/src/worker.ts

@@ -21,7 +21,6 @@ import {
   formatExceptionMessage,
   moveUploadedAssets,
   ResponseResult,
-  workerIdLabel,
   saveMultipartFile,
   Asset,
 } from './shared/utils';
@@ -231,7 +230,7 @@ export default function run(config: Partial<Config>) {
         const msg = formatExceptionMessage(
           taskDescription,
           errorMessage,
-          `Failed to acquire lock ${lockfileName}. Worker: ${workerIdLabel()}.`,
+          `Failed to acquire lock ${lockfileName}`,
         );
         await setResponse(errorResponseResult(msg), res);
       } else {
@@ -264,7 +263,7 @@ export default function run(config: Partial<Config>) {
           }
         } catch (error) {
           log.warn({
-            msg: `Error unlocking ${lockfileName} from worker ${workerIdLabel()}`,
+            msg: `Error unlocking ${lockfileName}`,
             err: error,
             task: taskDescription,
           });
@@ -312,11 +311,9 @@ export default function run(config: Partial<Config>) {
 
   // In tests we will run worker in master thread, so we need to ensure server
   // will not listen:
-  // we are extracting worker from cluster to avoid false TS error
-  const { worker } = cluster;
-  if (cluster.isWorker && worker !== undefined) {
+  if (cluster.isWorker) {
     app.listen({ port }, () => {
-      log.info(`Node renderer worker #${worker.id} listening on port ${port}!`);
+      log.info(`Listening on port ${port}!`);
     });
   }
 

packages/node-renderer/src/worker/handleRenderRequest.ts

@@ -5,7 +5,6 @@
  * @module worker/handleRenderRequest
  */
 
-import cluster from 'cluster';
 import path from 'path';
 import { lock, unlock } from '../shared/locks';
 import fileExistsAsync from '../shared/fileExistsAsync';
@@ -14,7 +13,6 @@ import {
   Asset,
   formatExceptionMessage,
   errorResponseResult,
-  workerIdLabel,
   moveUploadedAssets,
   ResponseResult,
   moveUploadedAsset,
@@ -28,7 +26,7 @@ import { buildVM, getVmBundleFilePath, runInVM } from './vm';
 
 async function prepareResult(renderingRequest: string): Promise<ResponseResult> {
   try {
-    const result = await runInVM(renderingRequest, cluster);
+    const result = await runInVM(renderingRequest);
 
     let exceptionMessage = null;
     if (!result) {
@@ -95,7 +93,7 @@ async function handleNewBundleProvided(
       const msg = formatExceptionMessage(
         renderingRequest,
         errorMessage,
-        `Failed to acquire lock ${lockfileName}. Worker: ${workerIdLabel()}.`,
+        `Failed to acquire lock ${lockfileName}.`,
       );
       return Promise.resolve(errorResponseResult(msg));
     }
@@ -144,17 +142,13 @@ to ${bundleFilePathPerTimestamp})`,
     }
   } finally {
     if (lockAcquired) {
-      log.info('About to unlock %s from worker %i', lockfileName, workerIdLabel());
+      log.info('About to unlock %s', lockfileName);
       try {
         if (lockfileName) {
           await unlock(lockfileName);
         }
       } catch (error) {
-        const msg = formatExceptionMessage(
-          renderingRequest,
-          error,
-          `Error unlocking ${lockfileName} from worker ${workerIdLabel()}.`,
-        );
+        const msg = formatExceptionMessage(renderingRequest, error, `Error unlocking ${lockfileName}.`);
         log.warn(msg);
       }
     }
@@ -208,7 +202,7 @@ export = async function handleRenderRequest({
 
     // The bundle exists, but the VM has not yet been created.
     // Another worker must have written it or it was saved during deployment.
-    log.info('Bundle %s exists. Building VM for worker %s.', bundleFilePathPerTimestamp, workerIdLabel());
+    log.info('Bundle %s exists. Building VM.', bundleFilePathPerTimestamp);
     await buildVM(bundleFilePathPerTimestamp);
 
     return prepareResult(renderingRequest);

packages/node-renderer/src/worker/vm.ts

@@ -7,7 +7,6 @@ import fs from 'fs';
 import path from 'path';
 import vm from 'vm';
 import m from 'module';
-import cluster from 'cluster';
 import type { Readable } from 'stream';
 import { promisify } from 'util';
 import type { ReactOnRails as ROR } from 'react-on-rails';
@@ -162,10 +161,7 @@ export async function buildVM(filePath: string) {
       vm.runInContext(bundleContents, context);
     }
 
-    // isWorker check is required for JS unit testing:
-    if (cluster.isWorker && cluster.worker !== undefined) {
-      log.debug(`Built VM for worker #${cluster.worker.id}`);
-    }
+    log.debug('Built VM');
 
     if (log.level === 'debug') {
       log.debug(
@@ -191,9 +187,8 @@ export async function buildVM(filePath: string) {
 /**
  *
  * @param renderingRequest JS Code to execute for SSR
- * @param vmCluster
  */
-export async function runInVM(renderingRequest: string, vmCluster?: typeof cluster): Promise<RenderResult> {
+export async function runInVM(renderingRequest: string): Promise<RenderResult> {
   const { bundlePath } = getConfig();
 
   try {
@@ -202,9 +197,7 @@ export async function runInVM(renderingRequest: string, vmCluster?: typeof clust
     }
 
     if (log.level === 'debug') {
-      // worker is nullable in the primary process
-      const workerId = vmCluster?.worker?.id;
-      log.debug(`worker ${workerId ? `${workerId} ` : ''}received render request with code
+      log.debug(`Received render request with code
 ${smartTrim(renderingRequest)}`);
       const debugOutputPathCode = path.join(bundlePath, 'code.js');
       log.debug(`Full code executed written to: ${debugOutputPathCode}`);