diff --git a/docs/node-renderer/error-reporting-and-tracing.md b/docs/node-renderer/error-reporting-and-tracing.md index 83ba4f6eb..aea180be4 100644 --- a/docs/node-renderer/error-reporting-and-tracing.md +++ b/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); }); ``` diff --git a/packages/node-renderer/src/integrations/api.ts b/packages/node-renderer/src/integrations/api.ts index 8a5092f4f..99d10e996 100644 --- a/packages/node-renderer/src/integrations/api.ts +++ b/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, diff --git a/packages/node-renderer/src/integrations/honeybadger.ts b/packages/node-renderer/src/integrations/honeybadger.ts index 1387c9678..74525824e 100644 --- a/packages/node-renderer/src/integrations/honeybadger.ts +++ b/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)); } diff --git a/packages/node-renderer/src/integrations/sentry.ts b/packages/node-renderer/src/integrations/sentry.ts index d9c980af0..0a52d2431 100644 --- a/packages/node-renderer/src/integrations/sentry.ts +++ b/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); }); diff --git a/packages/node-renderer/src/integrations/sentry6.ts b/packages/node-renderer/src/integrations/sentry6.ts index 293f706b8..ef4b578b4 100644 --- a/packages/node-renderer/src/integrations/sentry6.ts +++ b/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); }); diff --git a/packages/node-renderer/src/shared/locks.ts b/packages/node-renderer/src/shared/locks.ts index 32956d308..16a3b9156 100644 --- a/packages/node-renderer/src/shared/locks.ts +++ b/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(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 { 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 }; diff --git a/packages/node-renderer/src/shared/log.ts b/packages/node-renderer/src/shared/log.ts index 0212bd4b6..96c6a1146 100644 --- a/packages/node-renderer/src/shared/log.ts +++ b/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 diff --git a/packages/node-renderer/src/shared/utils.ts b/packages/node-renderer/src/shared/utils.ts index 3ee24d212..4044e9061 100644 --- a/packages/node-renderer/src/shared/utils.ts +++ b/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; diff --git a/packages/node-renderer/src/worker.ts b/packages/node-renderer/src/worker.ts index 667ae162f..be2926cbf 100644 --- a/packages/node-renderer/src/worker.ts +++ b/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) { 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) { } } 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) { // 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}!`); }); } diff --git a/packages/node-renderer/src/worker/handleRenderRequest.ts b/packages/node-renderer/src/worker/handleRenderRequest.ts index 3547d7ba0..7fbddca25 100644 --- a/packages/node-renderer/src/worker/handleRenderRequest.ts +++ b/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 { 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); diff --git a/packages/node-renderer/src/worker/vm.ts b/packages/node-renderer/src/worker/vm.ts index 50dea1280..a3adaece0 100644 --- a/packages/node-renderer/src/worker/vm.ts +++ b/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 { +export async function runInVM(renderingRequest: string): Promise { 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}`);