From e98721e4e501793a1a3e28e6b914484705777517 Mon Sep 17 00:00:00 2001 From: Brent Date: Tue, 19 May 2026 15:15:04 -0400 Subject: [PATCH 1/5] feat: add structuredErrorHandler middleware alongside errorMiddleware MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Existing errorMiddleware accepts an onError(err) callback for side-effect logging. When consumers pass console.log (as several integration services do), errors are stringified via error.toString() and emitted as bare INFO log lines with no attributes — no stack trace, no integration context, nothing actionable in Datadog. Adds a new structuredErrorHandler export that preserves the same response shape (500 / application/json / { message }) but emits errors structurally: - Default: looks for a StructuredErrorLogger at req.logger (attached by upstream middleware such as plugin/integration setup) and calls req.logger.error(message, err, { operation, httpMethod, httpUrl }). Falls back to console.error(err) when no req.logger is present, so errors are never silently lost. - Override: optional onError(err, req) callback for full control. The callback receives both the error and the request so consumers can extract request-scoped context however they like. Named separately from errorMiddleware so existing consumers that swap without first wiring req.logger upstream get an observable console.error fallback instead of silent data loss, per code-review feedback on screener-integration-service#87. Exports the StructuredErrorLogger interface so consumers can type their request logger against the contract the SDK consumes. Includes 8 unit tests covering: logger-present happy path, missing req.logger fallback, malformed req.logger fallback, logger throw safety, onError override, onError throw safety, 500 response handling, and headers-already-sent delegation. --- src/sdk/middleware.ts | 76 ++++++++++++++++ test/sdk/middleware.test.ts | 171 ++++++++++++++++++++++++++++++++++++ 2 files changed, 247 insertions(+) create mode 100644 test/sdk/middleware.test.ts diff --git a/src/sdk/middleware.ts b/src/sdk/middleware.ts index 00a3365..3f6c13f 100644 --- a/src/sdk/middleware.ts +++ b/src/sdk/middleware.ts @@ -114,3 +114,79 @@ export function errorMiddleware(onError: (err: Error) => void = () => {}): Error res.end(JSON.stringify({ message: err.message })); }; } + +/** + * Minimal structured-logger shape that `structuredErrorHandler` looks for at + * `req.logger`. Any logger exposing this method (e.g. the StructuredLogger + * from `@envoy/envoy-integrations-internal-sdk`) is compatible. + */ +export interface StructuredErrorLogger { + error(message: string, error: Error, metadata?: Record): void; +} + +interface RequestWithLogger extends Request { + logger?: StructuredErrorLogger; +} + +/** + * Like {@link errorMiddleware} but emits errors as structured log events + * instead of relying on `error.toString()` via a side-effect callback. + * + * Default behavior (when no `onError` callback is supplied): + * - If upstream middleware has attached a `StructuredErrorLogger` at + * `req.logger`, call `req.logger.error(message, err, metadata)`. The + * metadata includes `operation`, `httpMethod`, and `httpUrl` so Datadog + * (or any structured log store) can index on them. + * - Otherwise, fall back to `console.error(err)` so errors are never + * silently lost. + * + * Pass an `onError` callback to take full control of how the error is logged + * — the SDK invokes it with both the error and the request, so callers can + * extract request-scoped context however they like. + * + * Named separately from `errorMiddleware` so existing consumers that switch + * over without first wiring `req.logger` upstream don't silently lose the + * structured payload — the fallback `console.error` makes that scenario + * observable instead of silent. + * + * @category Middleware + */ +export function structuredErrorHandler( + onError?: (err: Error, req: Request) => void, +): ErrorRequestHandler { + return (err: Error, req: Request, res: Response, next: NextFunction): void => { + if (onError) { + try { + onError(err, req); + } catch (cbErr) { + // Don't let a logging callback failure swallow the original error. + // eslint-disable-next-line no-console + console.error('structuredErrorHandler: onError callback threw', cbErr); + } + } else { + const requestLogger = (req as RequestWithLogger).logger; + if (requestLogger && typeof requestLogger.error === 'function') { + try { + requestLogger.error('Unhandled error in request pipeline', err, { + operation: 'structuredErrorHandler', + httpMethod: req.method, + httpUrl: req.originalUrl, + }); + } catch (logErr) { + // eslint-disable-next-line no-console + console.error('structuredErrorHandler: req.logger.error threw', logErr); + } + } else { + // No request-scoped logger attached — surface the raw error so it isn't lost. + // eslint-disable-next-line no-console + console.error(err); + } + } + if (res.headersSent) { + return next(err); + } + res.statusCode = HttpStatus.UNEXPECTED_FAILURE; + res.setHeader('Content-Type', 'application/json'); + res.end(JSON.stringify({ message: err.message })); + }; +} diff --git a/test/sdk/middleware.test.ts b/test/sdk/middleware.test.ts new file mode 100644 index 0000000..10c6a23 --- /dev/null +++ b/test/sdk/middleware.test.ts @@ -0,0 +1,171 @@ +import type { NextFunction, Request, Response } from 'express'; + +import { structuredErrorHandler } from '../../src/sdk/middleware'; + +type MockResponse = { + headersSent: boolean; + statusCode: number; + setHeader: jest.Mock; + end: jest.Mock; +}; + +function buildReq(overrides: Partial = {}): Request { + return { + method: 'POST', + originalUrl: '/some/path', + ...overrides, + } as Request; +} + +function buildRes(headersSent = false): MockResponse { + return { + headersSent, + statusCode: 0, + setHeader: jest.fn(), + end: jest.fn(), + }; +} + +describe('structuredErrorHandler', () => { + /* eslint-disable no-console */ + const originalConsoleError = console.error; + let consoleErrorSpy: jest.Mock; + + beforeEach(() => { + consoleErrorSpy = jest.fn(); + console.error = consoleErrorSpy; + }); + + afterEach(() => { + console.error = originalConsoleError; + }); + /* eslint-enable no-console */ + + describe('default behavior (no onError callback)', () => { + it('calls req.logger.error with message, err, and {operation, httpMethod, httpUrl}', () => { + const loggerError = jest.fn(); + const req = buildReq({ logger: { error: loggerError } }); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorHandler()(err, req, res as unknown as Response, next); + + expect(loggerError).toHaveBeenCalledTimes(1); + expect(loggerError).toHaveBeenCalledWith('Unhandled error in request pipeline', err, { + operation: 'structuredErrorHandler', + httpMethod: 'POST', + httpUrl: '/some/path', + }); + expect(consoleErrorSpy).not.toHaveBeenCalled(); + }); + + it('falls back to console.error when req.logger is missing', () => { + const req = buildReq(); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorHandler()(err, req, res as unknown as Response, next); + + expect(consoleErrorSpy).toHaveBeenCalledTimes(1); + expect(consoleErrorSpy).toHaveBeenCalledWith(err); + }); + + it('falls back to console.error when req.logger has no error method', () => { + const req = buildReq({ logger: { info: jest.fn() } }); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorHandler()(err, req, res as unknown as Response, next); + + expect(consoleErrorSpy).toHaveBeenCalledTimes(1); + expect(consoleErrorSpy).toHaveBeenCalledWith(err); + }); + + it('does not propagate exceptions thrown by req.logger.error', () => { + const loggerError = jest.fn(() => { + throw new Error('logger blew up'); + }); + const req = buildReq({ logger: { error: loggerError } }); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + expect(() => { + structuredErrorHandler()(err, req, res as unknown as Response, next); + }).not.toThrow(); + + // Original error log was attempted; the logger's throw was caught and surfaced via console. + expect(loggerError).toHaveBeenCalled(); + expect(consoleErrorSpy).toHaveBeenCalledWith( + 'structuredErrorHandler: req.logger.error threw', + expect.any(Error), + ); + }); + }); + + describe('with onError callback', () => { + it('invokes the callback with (err, req) and does not touch req.logger', () => { + const onError = jest.fn(); + const loggerError = jest.fn(); + const req = buildReq({ logger: { error: loggerError } }); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorHandler(onError)(err, req, res as unknown as Response, next); + + expect(onError).toHaveBeenCalledTimes(1); + expect(onError).toHaveBeenCalledWith(err, req); + expect(loggerError).not.toHaveBeenCalled(); + }); + + it('does not propagate exceptions thrown by the callback', () => { + const onError = jest.fn(() => { + throw new Error('callback blew up'); + }); + const req = buildReq(); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + expect(() => { + structuredErrorHandler(onError)(err, req, res as unknown as Response, next); + }).not.toThrow(); + expect(consoleErrorSpy).toHaveBeenCalledWith( + 'structuredErrorHandler: onError callback threw', + expect.any(Error), + ); + }); + }); + + describe('response handling', () => { + it('sends a 500 JSON response when headers have not been sent', () => { + const req = buildReq(); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorHandler()(err, req, res as unknown as Response, next); + + expect(res.statusCode).toBe(500); + expect(res.setHeader).toHaveBeenCalledWith('Content-Type', 'application/json'); + expect(res.end).toHaveBeenCalledWith(JSON.stringify({ message: 'boom' })); + expect(next).not.toHaveBeenCalled(); + }); + + it('delegates to next(err) when headers have already been sent', () => { + const req = buildReq(); + const res = buildRes(true); + const next = jest.fn(); + const err = new Error('boom'); + + structuredErrorHandler()(err, req, res as unknown as Response, next as unknown as NextFunction); + + expect(next).toHaveBeenCalledWith(err); + expect(res.end).not.toHaveBeenCalled(); + }); + }); +}); From 9fd7062cd76310653a792d6b4d9fa0347493b8a6 Mon Sep 17 00:00:00 2001 From: Zach Matarasso Date: Tue, 19 May 2026 15:56:08 -0400 Subject: [PATCH 2/5] refactor: structuredErrorMiddleware + envoyMiddleware loggerFactory MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Tightens the structured-error pipeline so consumers can rely on a typed contract instead of inline casts: - New StructuredLogger module exporting the minimum interface the SDK needs (`error(message, err, metadata?)`) plus an `isRequestWithLogger` type guard. structuredErrorMiddleware now narrows req.logger through the guard instead of an unchecked cast + ad-hoc typeof check. - EnvoyBaseRequest declares `logger?: StructuredLogger`, so downstream handlers see it as typed without each consumer redeclaring the shape. - envoyMiddleware accepts `loggerFactory?: (req, ctx) => StructuredLogger` and attaches the result to req.logger synchronously at the top of the handler, before body parsing and EnvoyPluginAPI.loginAsPlugin(). The ctx surfaces `integrationName` parsed from `?name=` — the dispatch convention used by Envoy monolith integration services — so factories can build a child logger pre-tagged with it. A throwing factory is caught and surfaced via console.error rather than breaking the request. - Renamed structuredErrorHandler -> structuredErrorMiddleware to match the existing `errorMiddleware` naming convention in the same file. Tests: 91 passing (added cases for the type guard, the integrationName context wiring, factory-throw recovery, and the null-logger fallback). Co-Authored-By: Claude Opus 4.7 (1M context) --- src/index.ts | 1 + src/sdk/EnvoyRequest.ts | 9 ++ src/sdk/StructuredLogger.ts | 49 ++++++++++ src/sdk/middleware.ts | 143 ++++++++++++++++++++++-------- test/sdk/StructuredLogger.test.ts | 49 ++++++++++ test/sdk/middleware.test.ts | 142 ++++++++++++++++++++++++++--- 6 files changed, 341 insertions(+), 52 deletions(-) create mode 100644 src/sdk/StructuredLogger.ts create mode 100644 test/sdk/StructuredLogger.test.ts diff --git a/src/index.ts b/src/index.ts index cf5e96d..5a921c3 100644 --- a/src/index.ts +++ b/src/index.ts @@ -58,6 +58,7 @@ export * from './sdk/filters'; export * from './sdk/handlers'; export * from './sdk/loggers'; export * from './sdk/middleware'; +export * from './sdk/StructuredLogger'; export * from './util/EnvoySignatureVerifier'; export * from './util/axiosConstructor'; diff --git a/src/sdk/EnvoyRequest.ts b/src/sdk/EnvoyRequest.ts index 22acf07..37edccf 100644 --- a/src/sdk/EnvoyRequest.ts +++ b/src/sdk/EnvoyRequest.ts @@ -1,6 +1,7 @@ import { Request } from 'express'; import EnvoyPluginSDK from './EnvoyPluginSDK'; import EnvoyMeta, { EnvoyEventMeta, EnvoyRouteMeta } from './EnvoyMeta'; +import { StructuredLogger } from './StructuredLogger'; import EntryPayload from '../payloads/EntryPayload'; import InvitePayload from '../payloads/InvitePayload'; import LocationPayload from '../payloads/LocationPayload'; @@ -37,6 +38,14 @@ export interface VerifiedRequest extends Request { */ export interface EnvoyBaseRequest extends VerifiedRequest { envoy: EnvoyPluginSDK; + /** + * Request-scoped structured logger. Set by `envoyMiddleware` when a + * `loggerFactory` option is provided, or by a downstream middleware that + * attaches a context-enriched child logger. May be absent when the caller + * has not opted into request-scoped logging — narrow with + * {@link isRequestWithLogger} before use. + */ + logger?: StructuredLogger; } /** diff --git a/src/sdk/StructuredLogger.ts b/src/sdk/StructuredLogger.ts new file mode 100644 index 0000000..c49cce0 --- /dev/null +++ b/src/sdk/StructuredLogger.ts @@ -0,0 +1,49 @@ +import { Request } from 'express'; + +/** + * Minimum contract the SDK requires from a logger attached to a request. + * + * Any logger that implements this `error` signature — including the + * `StructuredLogger` from `@envoy/envoy-integrations-internal-sdk` — is + * compatible with the SDK middleware (`envoyMiddleware`, `structuredErrorMiddleware`). + * + * Kept intentionally narrow: callers are free to attach a logger with + * additional methods (`info`, `warn`, `debug`, etc.), but the SDK only + * relies on `error` so it stays decoupled from any specific logging library. + * + * @category Logger + */ +export interface StructuredLogger { + error(message: string, error: Error, metadata?: Record): void; +} + +/** + * An express `Request` that has been augmented with a `StructuredLogger` at + * `req.logger` — usually by `envoyMiddleware` (when a `loggerFactory` option + * is provided) or by a downstream middleware that wants to attach a + * context-enriched child logger. + * + * @category Logger + */ +export interface RequestWithLogger extends Request { + logger: StructuredLogger; +} + +/** + * Type guard that narrows a request to {@link RequestWithLogger} when a + * usable structured logger is present at `req.logger`. + * + * Use this instead of an unchecked cast when consuming `req.logger` from + * middleware/handlers — the runtime check ensures that downstream code only + * runs against a logger object that actually implements `error()`. + * + * @category Logger + */ +export function isRequestWithLogger(req: Request): req is RequestWithLogger { + const candidate = (req as { logger?: unknown }).logger; + return ( + typeof candidate === 'object' && + candidate !== null && + typeof (candidate as { error?: unknown }).error === 'function' + ); +} diff --git a/src/sdk/middleware.ts b/src/sdk/middleware.ts index 3f6c13f..d5cb61c 100644 --- a/src/sdk/middleware.ts +++ b/src/sdk/middleware.ts @@ -8,6 +8,69 @@ import EnvoyResponse from './EnvoyResponse'; import EnvoyPluginJobAttachment, { EnvoyPluginScreenerJobAttachment } from './EnvoyPluginJobAttachment'; import EnvoyPluginSDK from './EnvoyPluginSDK'; import EnvoyPluginAPI from './EnvoyPluginAPI'; +import { StructuredLogger, isRequestWithLogger } from './StructuredLogger'; + +/** + * Request-scoped context that `envoyMiddleware` makes available to a + * `loggerFactory` so the factory can produce a logger pre-tagged with the + * usual Envoy fields. + * + * Only the fields that can be derived from the raw express `Request` (before + * body parsing) are populated here — richer context (install id, company id, + * event name, etc.) lives on `req.envoy.meta` and should be added by a + * downstream middleware once the SDK has finished initializing. + * + * @category Middleware + */ +export interface EnvoyLoggerContext { + /** + * Integration name parsed from the `?name=` query param. + * + * NOTE: this is a convention used by Envoy monolith integration services + * (e.g. `screener-integration-service`, `access-control-integration-service`) + * that fan out to plugin-specific routes via a single `?name=` + * dispatcher. Standalone single-purpose plugins that don't use the + * `?name=` query param will receive `undefined` here. + */ + integrationName?: string; +} + +/** + * Options for {@link envoyMiddleware}. + * + * Combines the signature-verifier options (which configure how Envoy's HMAC + * header is checked) with an optional `loggerFactory` hook for attaching a + * request-scoped {@link StructuredLogger}. + * + * @category Middleware + */ +export interface EnvoyMiddlewareOptions extends Partial { + /** + * If provided, invoked at the start of every request to build a + * {@link StructuredLogger}. The result is attached to `req.logger` so it's + * available for the rest of the middleware chain (including + * `structuredErrorMiddleware`). + * + * The factory is called *before* the request body is parsed and *before* + * `req.envoy` is set up, so it can only depend on the raw express + * `Request` plus the {@link EnvoyLoggerContext} the middleware can derive + * from it (currently the `?name=` integration name used by Envoy monolith + * integration services). Downstream middleware can replace `req.logger` + * with a richer child logger once more context (install id, company id, + * etc.) is available on `req.envoy.meta`. + */ + loggerFactory?: (req: Request, context: EnvoyLoggerContext) => StructuredLogger; +} + +/** + * Pulls the integration name from `req.query.name` if (and only if) it is a + * single string. This matches the dispatch convention used by Envoy monolith + * integration services — see {@link EnvoyLoggerContext.integrationName}. + */ +function extractIntegrationName(req: Request): string | undefined { + const candidate = req.query?.name; + return typeof candidate === 'string' ? candidate : undefined; +} /** * Sets up an {@link EnvoyPluginSDK} object in the path `req.envoy`. @@ -16,10 +79,16 @@ import EnvoyPluginAPI from './EnvoyPluginAPI'; * Also verifies that the request is coming from Envoy, * as well as managing the plugin access token lifecycle. * + * If a `loggerFactory` is supplied, attaches the produced + * {@link StructuredLogger} to `req.logger` so it's available throughout the + * middleware chain — including any error that fires inside this middleware + * before `req.envoy` finishes initializing. + * * @category Middleware */ -export function envoyMiddleware(options?: EnvoySignatureVerifierOptions): RequestHandler { - const signatureVerifier = new EnvoySignatureVerifier(options); +export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandler { + const { loggerFactory, ...verifierOptions } = options ?? {}; + const signatureVerifier = new EnvoySignatureVerifier(verifierOptions as EnvoySignatureVerifierOptions); const verify = (req: VerifiedRequest, res: Response, rawBody: Buffer) => { req[VERIFIED] = signatureVerifier.verify(req, rawBody); }; @@ -28,6 +97,19 @@ export function envoyMiddleware(options?: EnvoySignatureVerifierOptions): Reques let threshold = 0; return (req: Request, res: Response, next: NextFunction) => { + if (loggerFactory) { + try { + const context: EnvoyLoggerContext = { + integrationName: extractIntegrationName(req), + }; + (req as Request & { logger?: StructuredLogger }).logger = loggerFactory(req, context); + } catch (factoryErr) { + // A failing loggerFactory must not break the request pipeline — surface + // the error so it's debuggable, then continue without a request logger. + // eslint-disable-next-line no-console + console.error('envoyMiddleware: loggerFactory threw', factoryErr); + } + } json(req, res, async (err) => { if (err) { return next(err); @@ -115,29 +197,17 @@ export function errorMiddleware(onError: (err: Error) => void = () => {}): Error }; } -/** - * Minimal structured-logger shape that `structuredErrorHandler` looks for at - * `req.logger`. Any logger exposing this method (e.g. the StructuredLogger - * from `@envoy/envoy-integrations-internal-sdk`) is compatible. - */ -export interface StructuredErrorLogger { - error(message: string, error: Error, metadata?: Record): void; -} - -interface RequestWithLogger extends Request { - logger?: StructuredErrorLogger; -} - /** * Like {@link errorMiddleware} but emits errors as structured log events - * instead of relying on `error.toString()` via a side-effect callback. + * instead of stringifying via a side-effect callback. * * Default behavior (when no `onError` callback is supplied): - * - If upstream middleware has attached a `StructuredErrorLogger` at - * `req.logger`, call `req.logger.error(message, err, metadata)`. The + * - If upstream middleware has attached a {@link StructuredLogger} at + * `req.logger` (typically via `envoyMiddleware`'s `loggerFactory` + * option), calls `req.logger.error(message, err, metadata)`. The * metadata includes `operation`, `httpMethod`, and `httpUrl` so Datadog * (or any structured log store) can index on them. - * - Otherwise, fall back to `console.error(err)` so errors are never + * - Otherwise, falls back to `console.error(err)` so errors are never * silently lost. * * Pass an `onError` callback to take full control of how the error is logged @@ -151,9 +221,7 @@ interface RequestWithLogger extends Request { * * @category Middleware */ -export function structuredErrorHandler( - onError?: (err: Error, req: Request) => void, -): ErrorRequestHandler { +export function structuredErrorMiddleware(onError?: (err: Error, req: Request) => void): ErrorRequestHandler { return (err: Error, req: Request, res: Response, next: NextFunction): void => { if (onError) { try { @@ -161,26 +229,23 @@ export function structuredErrorHandler( } catch (cbErr) { // Don't let a logging callback failure swallow the original error. // eslint-disable-next-line no-console - console.error('structuredErrorHandler: onError callback threw', cbErr); + console.error('structuredErrorMiddleware: onError callback threw', cbErr); } - } else { - const requestLogger = (req as RequestWithLogger).logger; - if (requestLogger && typeof requestLogger.error === 'function') { - try { - requestLogger.error('Unhandled error in request pipeline', err, { - operation: 'structuredErrorHandler', - httpMethod: req.method, - httpUrl: req.originalUrl, - }); - } catch (logErr) { - // eslint-disable-next-line no-console - console.error('structuredErrorHandler: req.logger.error threw', logErr); - } - } else { - // No request-scoped logger attached — surface the raw error so it isn't lost. + } else if (isRequestWithLogger(req)) { + try { + req.logger.error('Unhandled error in request pipeline', err, { + operation: 'structuredErrorMiddleware', + httpMethod: req.method, + httpUrl: req.originalUrl, + }); + } catch (logErr) { // eslint-disable-next-line no-console - console.error(err); + console.error('structuredErrorMiddleware: req.logger.error threw', logErr); } + } else { + // No request-scoped logger attached — surface the raw error so it isn't lost. + // eslint-disable-next-line no-console + console.error(err); } if (res.headersSent) { return next(err); diff --git a/test/sdk/StructuredLogger.test.ts b/test/sdk/StructuredLogger.test.ts new file mode 100644 index 0000000..21bd698 --- /dev/null +++ b/test/sdk/StructuredLogger.test.ts @@ -0,0 +1,49 @@ +import type { Request } from 'express'; + +import { isRequestWithLogger } from '../../src/sdk/StructuredLogger'; + +function reqWith(logger: unknown): Request { + return { logger } as unknown as Request; +} + +describe('isRequestWithLogger', () => { + it('narrows when req.logger has a callable error method', () => { + const req = reqWith({ error: jest.fn() }); + + expect(isRequestWithLogger(req)).toBe(true); + + if (isRequestWithLogger(req)) { + // Type guard narrows `req` to RequestWithLogger so this access is well-typed. + expect(typeof req.logger.error).toBe('function'); + } + }); + + it('returns false when req.logger is missing', () => { + expect(isRequestWithLogger({} as Request)).toBe(false); + }); + + it('returns false when req.logger is null', () => { + expect(isRequestWithLogger(reqWith(null))).toBe(false); + }); + + it('returns false when req.logger is a non-object', () => { + expect(isRequestWithLogger(reqWith('string-logger'))).toBe(false); + expect(isRequestWithLogger(reqWith(42))).toBe(false); + }); + + it('returns false when req.logger.error is not a function', () => { + expect(isRequestWithLogger(reqWith({ error: 'not a fn' }))).toBe(false); + expect(isRequestWithLogger(reqWith({ info: jest.fn() }))).toBe(false); + }); + + it('accepts loggers with additional methods beyond error', () => { + const fullLogger = { + error: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + debug: jest.fn(), + }; + + expect(isRequestWithLogger(reqWith(fullLogger))).toBe(true); + }); +}); diff --git a/test/sdk/middleware.test.ts b/test/sdk/middleware.test.ts index 10c6a23..9e0a5a3 100644 --- a/test/sdk/middleware.test.ts +++ b/test/sdk/middleware.test.ts @@ -1,6 +1,6 @@ import type { NextFunction, Request, Response } from 'express'; -import { structuredErrorHandler } from '../../src/sdk/middleware'; +import { envoyMiddleware, structuredErrorMiddleware } from '../../src/sdk/middleware'; type MockResponse = { headersSent: boolean; @@ -13,6 +13,7 @@ function buildReq(overrides: Partial = {}): Requ return { method: 'POST', originalUrl: '/some/path', + headers: {}, ...overrides, } as Request; } @@ -26,7 +27,7 @@ function buildRes(headersSent = false): MockResponse { }; } -describe('structuredErrorHandler', () => { +describe('structuredErrorMiddleware', () => { /* eslint-disable no-console */ const originalConsoleError = console.error; let consoleErrorSpy: jest.Mock; @@ -49,11 +50,11 @@ describe('structuredErrorHandler', () => { const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); - structuredErrorHandler()(err, req, res as unknown as Response, next); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); expect(loggerError).toHaveBeenCalledTimes(1); expect(loggerError).toHaveBeenCalledWith('Unhandled error in request pipeline', err, { - operation: 'structuredErrorHandler', + operation: 'structuredErrorMiddleware', httpMethod: 'POST', httpUrl: '/some/path', }); @@ -66,7 +67,7 @@ describe('structuredErrorHandler', () => { const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); - structuredErrorHandler()(err, req, res as unknown as Response, next); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); expect(consoleErrorSpy).toHaveBeenCalledTimes(1); expect(consoleErrorSpy).toHaveBeenCalledWith(err); @@ -78,7 +79,19 @@ describe('structuredErrorHandler', () => { const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); - structuredErrorHandler()(err, req, res as unknown as Response, next); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); + + expect(consoleErrorSpy).toHaveBeenCalledTimes(1); + expect(consoleErrorSpy).toHaveBeenCalledWith(err); + }); + + it('falls back to console.error when req.logger is null', () => { + const req = buildReq({ logger: null }); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorMiddleware()(err, req, res as unknown as Response, next); expect(consoleErrorSpy).toHaveBeenCalledTimes(1); expect(consoleErrorSpy).toHaveBeenCalledWith(err); @@ -94,13 +107,13 @@ describe('structuredErrorHandler', () => { const err = new Error('boom'); expect(() => { - structuredErrorHandler()(err, req, res as unknown as Response, next); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); }).not.toThrow(); // Original error log was attempted; the logger's throw was caught and surfaced via console. expect(loggerError).toHaveBeenCalled(); expect(consoleErrorSpy).toHaveBeenCalledWith( - 'structuredErrorHandler: req.logger.error threw', + 'structuredErrorMiddleware: req.logger.error threw', expect.any(Error), ); }); @@ -115,7 +128,7 @@ describe('structuredErrorHandler', () => { const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); - structuredErrorHandler(onError)(err, req, res as unknown as Response, next); + structuredErrorMiddleware(onError)(err, req, res as unknown as Response, next); expect(onError).toHaveBeenCalledTimes(1); expect(onError).toHaveBeenCalledWith(err, req); @@ -132,15 +145,118 @@ describe('structuredErrorHandler', () => { const err = new Error('boom'); expect(() => { - structuredErrorHandler(onError)(err, req, res as unknown as Response, next); + structuredErrorMiddleware(onError)(err, req, res as unknown as Response, next); }).not.toThrow(); expect(consoleErrorSpy).toHaveBeenCalledWith( - 'structuredErrorHandler: onError callback threw', + 'structuredErrorMiddleware: onError callback threw', expect.any(Error), ); }); }); + describe('end-to-end with envoyMiddleware loggerFactory', () => { + it('honors a logger attached by envoyMiddleware loggerFactory option', () => { + const loggerError = jest.fn(); + // Build the envoy middleware with a loggerFactory; we only care that + // req.logger is set synchronously, so we don't drive a full request. + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory: () => ({ error: loggerError }), + }); + + const req = buildReq(); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + + // envoyMiddleware synchronously invokes loggerFactory and attaches req.logger + // before delegating to body-parser. We don't care about what body-parser does + // here — we just verify req.logger is now usable by structuredErrorMiddleware. + middleware(req, res as unknown as Response, next); + + const err = new Error('boom'); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); + + expect(loggerError).toHaveBeenCalledWith('Unhandled error in request pipeline', err, { + operation: 'structuredErrorMiddleware', + httpMethod: 'POST', + httpUrl: '/some/path', + }); + }); + + it('passes integrationName from req.query.name to the loggerFactory', () => { + const loggerFactory = jest.fn(() => ({ error: jest.fn() })); + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory, + }); + + const req = buildReq({ query: { name: 'checkr' } } as Partial); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + + middleware(req, res as unknown as Response, next); + + expect(loggerFactory).toHaveBeenCalledTimes(1); + expect(loggerFactory).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); + }); + + it('passes integrationName: undefined when ?name= is missing or not a string', () => { + const loggerFactory = jest.fn(() => ({ error: jest.fn() })); + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory, + }); + + const next = jest.fn() as unknown as NextFunction; + + // No query at all. + const reqA = buildReq(); + middleware(reqA, buildRes() as unknown as Response, next); + expect(loggerFactory).toHaveBeenLastCalledWith(reqA, { integrationName: undefined }); + + // Repeated query param (express parses to string[]) — not a single string, + // so we deliberately drop it rather than guess. + const reqB = buildReq({ query: { name: ['a', 'b'] } } as unknown as Partial); + middleware(reqB, buildRes() as unknown as Response, next); + expect(loggerFactory).toHaveBeenLastCalledWith(reqB, { integrationName: undefined }); + }); + + it('continues without a logger when loggerFactory throws', () => { + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory: () => { + throw new Error('factory blew up'); + }, + }); + + const req = buildReq(); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + + middleware(req, res as unknown as Response, next); + + // Surfaced via console.error, never thrown. + expect(consoleErrorSpy).toHaveBeenCalledWith('envoyMiddleware: loggerFactory threw', expect.any(Error)); + // And req.logger should not be set, so the fallback path kicks in downstream. + const err = new Error('boom'); + consoleErrorSpy.mockClear(); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); + expect(consoleErrorSpy).toHaveBeenCalledWith(err); + }); + }); + describe('response handling', () => { it('sends a 500 JSON response when headers have not been sent', () => { const req = buildReq(); @@ -148,7 +264,7 @@ describe('structuredErrorHandler', () => { const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); - structuredErrorHandler()(err, req, res as unknown as Response, next); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); expect(res.statusCode).toBe(500); expect(res.setHeader).toHaveBeenCalledWith('Content-Type', 'application/json'); @@ -162,7 +278,7 @@ describe('structuredErrorHandler', () => { const next = jest.fn(); const err = new Error('boom'); - structuredErrorHandler()(err, req, res as unknown as Response, next as unknown as NextFunction); + structuredErrorMiddleware()(err, req, res as unknown as Response, next as unknown as NextFunction); expect(next).toHaveBeenCalledWith(err); expect(res.end).not.toHaveBeenCalled(); From c28f74c048bc70819bf2ef24e303ea0f19839933 Mon Sep 17 00:00:00 2001 From: Zach Matarasso Date: Tue, 19 May 2026 16:46:01 -0400 Subject: [PATCH 3/5] refactor: expand EnvoyLoggerContext to mirror the internal SDK's extractLoggingContext MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Pulls every standard Envoy logging facet onto EnvoyLoggerContext so a service can swap its bespoke pluginMiddleware logger setup for the SDK's loggerFactory without losing any Datadog facet it already indexes on: - integrationName (from req.query.name — Envoy monolith services convention) - companyId, locationId, installId (from req.envoy.meta) - recordId, recordType (from req.envoy.payload — event requests only) - event, category (from req.envoy.meta.event + mirrored category mapping) The loggerFactory now runs once per request, after req.envoy is initialized, so the factory receives the full context in a single call. Errors that fire before req.envoy is set up (body parser, plugin login) fall through to console.error in structuredErrorMiddleware — same trade-off the current errorMiddleware(console.log) pattern makes. extractLoggerContext is exported so a downstream middleware can rebuild the same context when replacing req.logger with a more enriched child logger. The extractor is defensive against EnvoyPluginSDK's meta/payload getters throwing on unverified requests — a bad signature should not also cost us log context. isRequestWithLogger reshaped from a multi-line && chain to an early-return shape so prettier and eslint's operator-linebreak rule agree on layout. Tests: 95 passing (added direct unit tests for extractLoggerContext across event/route/unknown-event/missing-envoy shapes, plus an end-to-end test that drives envoyMiddleware with EnvoyPluginAPI.loginAsPlugin stubbed and body-parser short-circuited via req._body + req[VERIFIED]). Co-Authored-By: Claude Opus 4.7 (1M context) --- src/sdk/StructuredLogger.ts | 9 +- src/sdk/middleware.ts | 194 +++++++++++++++++++++++------ test/sdk/middleware.test.ts | 239 ++++++++++++++++++++++++++---------- 3 files changed, 332 insertions(+), 110 deletions(-) diff --git a/src/sdk/StructuredLogger.ts b/src/sdk/StructuredLogger.ts index c49cce0..4f1f616 100644 --- a/src/sdk/StructuredLogger.ts +++ b/src/sdk/StructuredLogger.ts @@ -41,9 +41,8 @@ export interface RequestWithLogger extends Request { */ export function isRequestWithLogger(req: Request): req is RequestWithLogger { const candidate = (req as { logger?: unknown }).logger; - return ( - typeof candidate === 'object' && - candidate !== null && - typeof (candidate as { error?: unknown }).error === 'function' - ); + if (typeof candidate !== 'object' || candidate === null) { + return false; + } + return typeof (candidate as { error?: unknown }).error === 'function'; } diff --git a/src/sdk/middleware.ts b/src/sdk/middleware.ts index d5cb61c..cff330b 100644 --- a/src/sdk/middleware.ts +++ b/src/sdk/middleware.ts @@ -13,12 +13,16 @@ import { StructuredLogger, isRequestWithLogger } from './StructuredLogger'; /** * Request-scoped context that `envoyMiddleware` makes available to a * `loggerFactory` so the factory can produce a logger pre-tagged with the - * usual Envoy fields. + * standard Envoy fields. * - * Only the fields that can be derived from the raw express `Request` (before - * body parsing) are populated here — richer context (install id, company id, - * event name, etc.) lives on `req.envoy.meta` and should be added by a - * downstream middleware once the SDK has finished initializing. + * Mirrors the `EnvoyLoggingContext` that + * `@envoy/envoy-integrations-internal-sdk` builds via `extractLoggingContext`, + * so a service can swap its bespoke `pluginMiddleware` logger setup for the + * SDK's built-in one without losing any Datadog facets it already indexes + * on (`companyId`, `installId`, `event`, etc.). Every field is optional — + * route requests don't carry `event`/`category`, validation requests have no + * `recordId`/`recordType`, and the `?name=` convention only applies to + * monolith services. * * @category Middleware */ @@ -27,14 +31,69 @@ export interface EnvoyLoggerContext { * Integration name parsed from the `?name=` query param. * * NOTE: this is a convention used by Envoy monolith integration services - * (e.g. `screener-integration-service`, `access-control-integration-service`) - * that fan out to plugin-specific routes via a single `?name=` - * dispatcher. Standalone single-purpose plugins that don't use the - * `?name=` query param will receive `undefined` here. + * (e.g. `screener-integration-service`, `pacs-integration-service`, + * `access-control-integration-service`) that fan out to plugin-specific + * routes via a single `?name=` dispatcher. Standalone + * single-purpose plugins that don't use the `?name=` query param will + * receive `undefined` here. */ integrationName?: string; + /** `req.envoy.meta.company.id` — the Envoy company that originated the request. */ + companyId?: string; + /** `req.envoy.meta.location.id` — the Envoy location the request is scoped to. */ + locationId?: string; + /** `req.envoy.meta.install_id` — the specific plugin installation that fired the request. */ + installId?: string; + /** `req.envoy.payload.id` — the visitor/invite/entry record id (event requests only). */ + recordId?: string; + /** `req.envoy.payload.type` — the JSON:API type of the payload (event requests only). */ + recordType?: string; + /** + * `req.envoy.meta.event` — the Envoy event name (e.g. `entry_sign_in`, + * `invite_created`). Only present on event requests; route requests + * (validation URLs, options URLs, etc.) will have this `undefined`. + */ + event?: string; + /** + * Coarse-grained grouping of `event` (e.g. `Visitor`, `Workplace`, + * `Desks`, `Communication`). Mirrors the category mapping used by + * `extractLoggingContext` in the internal SDK so cross-service Datadog + * dashboards keep working. + */ + category?: string; } +/** + * Mirrors the category mapping in + * `@envoy/envoy-integrations-internal-sdk`'s `extractLoggingContext`. Kept + * here so the SDK can populate `EnvoyLoggerContext.category` without taking + * a dependency on the internal SDK (which itself depends on this SDK). + */ +const ENVOY_EVENT_CATEGORIES: Readonly> = { + entry_sign_in: 'Visitor', + entry_sign_out: 'Visitor', + entry_screen_requested: 'Visitor', + entry_screened: 'Visitor', + entry_reviewed: 'Visitor', + entry_manually_updated: 'Visitor', + invite_created: 'Visitor', + invite_updated: 'Visitor', + invite_removed: 'Visitor', + invite_reviewed: 'Visitor', + upcoming_visit: 'Visitor', + invite_screen_requested: 'Visitor', + identity_verification_requested: 'Visitor', + entry_badge_print_requested: 'Visitor', + employee_entry_sign_in: 'Workplace', + employee_entry_sign_out: 'Workplace', + employee_invite_created: 'Workplace', + employee_invite_updated: 'Workplace', + employee_upcoming_visit: 'Workplace', + desk_sign_in: 'Desks', + takeover_started: 'Communication', + takeover_ended: 'Communication', +}; + /** * Options for {@link envoyMiddleware}. * @@ -46,20 +105,23 @@ export interface EnvoyLoggerContext { */ export interface EnvoyMiddlewareOptions extends Partial { /** - * If provided, invoked at the start of every request to build a - * {@link StructuredLogger}. The result is attached to `req.logger` so it's - * available for the rest of the middleware chain (including - * `structuredErrorMiddleware`). + * If provided, invoked once per request — after `req.envoy` is initialized + * and immediately before `next()` — to build a {@link StructuredLogger}. + * The result is attached to `req.logger` so it's available to every + * downstream handler and to `structuredErrorMiddleware`. * - * The factory is called *before* the request body is parsed and *before* - * `req.envoy` is set up, so it can only depend on the raw express - * `Request` plus the {@link EnvoyLoggerContext} the middleware can derive - * from it (currently the `?name=` integration name used by Envoy monolith - * integration services). Downstream middleware can replace `req.logger` - * with a richer child logger once more context (install id, company id, - * etc.) is available on `req.envoy.meta`. + * Called with the full {@link EnvoyLoggerContext} extracted from + * `req.query` + `req.envoy.meta` + `req.envoy.payload`, so the factory can + * produce a child logger pre-tagged with `integrationName`, `companyId`, + * `installId`, `event`, etc. without any per-service boilerplate. + * + * Errors thrown by the factory are caught and surfaced via `console.error` + * — they never break the request pipeline. Errors that fire *before* + * `req.envoy` finishes initializing (body parsing, plugin login) won't + * have `req.logger` set; `structuredErrorMiddleware` falls back to + * `console.error` for those, matching today's behavior. */ - loggerFactory?: (req: Request, context: EnvoyLoggerContext) => StructuredLogger; + loggerFactory?: (req: EnvoyRequest, context: EnvoyLoggerContext) => StructuredLogger; } /** @@ -72,6 +134,65 @@ function extractIntegrationName(req: Request): string | undefined { return typeof candidate === 'string' ? candidate : undefined; } +/** + * Builds the full {@link EnvoyLoggerContext} from an Envoy request. Defensive + * against missing fields — every property is optional, so a malformed or + * partial request degrades to a logger with whatever context was available + * rather than throwing. + * + * Exported so that downstream middleware (e.g. a service's own + * `pluginMiddleware`) can rebuild the same context when replacing + * `req.logger` with a richer child logger. + * + * @category Middleware + */ +export function extractLoggerContext(req: EnvoyRequest): EnvoyLoggerContext { + const context: EnvoyLoggerContext = { + integrationName: extractIntegrationName(req), + }; + const envoy = req.envoy as EnvoyPluginSDK | undefined; + if (!envoy) { + return context; + } + // `meta` and `payload` are typed against generics on EnvoyPluginSDK; we treat them + // as the structural minimum we need here so this stays useful for every request + // shape (event, route, validation, etc.). Access is wrapped in try/catch because + // EnvoyPluginSDK's getters throw on unverified requests — a bad signature should + // not cascade into lost log context. + let meta: + | Partial<{ + install_id: string; + location: { id?: string }; + company: { id?: string }; + event: string; + }> + | undefined; + let payload: Partial<{ id: string; type: string }> | undefined; + try { + meta = envoy.meta as typeof meta; + } catch { + // unverified or missing meta — leave undefined + } + try { + payload = envoy.payload as typeof payload; + } catch { + // unverified or missing payload — leave undefined + } + + context.installId = meta?.install_id; + context.locationId = meta?.location?.id; + context.companyId = meta?.company?.id; + context.recordId = payload?.id; + context.recordType = payload?.type; + + if (meta && 'event' in meta && typeof meta.event === 'string') { + context.event = meta.event; + context.category = ENVOY_EVENT_CATEGORIES[meta.event] ?? 'Unrecognized'; + } + + return context; +} + /** * Sets up an {@link EnvoyPluginSDK} object in the path `req.envoy`. * Modifies the `res` object to include Envoy's helpers, per {@link EnvoyResponse}. @@ -80,9 +201,10 @@ function extractIntegrationName(req: Request): string | undefined { * as well as managing the plugin access token lifecycle. * * If a `loggerFactory` is supplied, attaches the produced - * {@link StructuredLogger} to `req.logger` so it's available throughout the - * middleware chain — including any error that fires inside this middleware - * before `req.envoy` finishes initializing. + * {@link StructuredLogger} to `req.logger` once `req.envoy` is initialized, + * passing the factory the full {@link EnvoyLoggerContext} (integration name, + * company id, install id, event, category, …) so downstream handlers and + * `structuredErrorMiddleware` log with the standard Envoy facets baked in. * * @category Middleware */ @@ -97,19 +219,6 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle let threshold = 0; return (req: Request, res: Response, next: NextFunction) => { - if (loggerFactory) { - try { - const context: EnvoyLoggerContext = { - integrationName: extractIntegrationName(req), - }; - (req as Request & { logger?: StructuredLogger }).logger = loggerFactory(req, context); - } catch (factoryErr) { - // A failing loggerFactory must not break the request pipeline — surface - // the error so it's debuggable, then continue without a request logger. - // eslint-disable-next-line no-console - console.error('envoyMiddleware: loggerFactory threw', factoryErr); - } - } json(req, res, async (err) => { if (err) { return next(err); @@ -125,6 +234,17 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle const envoyResponse = res as EnvoyResponse; envoyRequest.envoy = new EnvoyPluginSDK(envoyRequest.body, envoyRequest[VERIFIED], accessToken); + if (loggerFactory) { + try { + envoyRequest.logger = loggerFactory(envoyRequest, extractLoggerContext(envoyRequest)); + } catch (factoryErr) { + // A failing loggerFactory must not break the request pipeline — surface + // the error so it's debuggable, then continue without a request logger. + // eslint-disable-next-line no-console + console.error('envoyMiddleware: loggerFactory threw', factoryErr); + } + } + /** * Respond with "ongoing" for long jobs. */ diff --git a/test/sdk/middleware.test.ts b/test/sdk/middleware.test.ts index 9e0a5a3..ff394e3 100644 --- a/test/sdk/middleware.test.ts +++ b/test/sdk/middleware.test.ts @@ -1,6 +1,8 @@ import type { NextFunction, Request, Response } from 'express'; -import { envoyMiddleware, structuredErrorMiddleware } from '../../src/sdk/middleware'; +import EnvoyPluginAPI from '../../src/sdk/EnvoyPluginAPI'; +import EnvoyRequest, { VERIFIED } from '../../src/sdk/EnvoyRequest'; +import { envoyMiddleware, extractLoggerContext, structuredErrorMiddleware } from '../../src/sdk/middleware'; type MockResponse = { headersSent: boolean; @@ -155,39 +157,50 @@ describe('structuredErrorMiddleware', () => { }); describe('end-to-end with envoyMiddleware loggerFactory', () => { - it('honors a logger attached by envoyMiddleware loggerFactory option', () => { - const loggerError = jest.fn(); - // Build the envoy middleware with a loggerFactory; we only care that - // req.logger is set synchronously, so we don't drive a full request. - const middleware = envoyMiddleware({ - secret: 'test-secret', - algorithm: 'sha256', - encoding: 'base64', - header: 'x-envoy-signature', - loggerFactory: () => ({ error: loggerError }), - }); - - const req = buildReq(); - const res = buildRes(); - const next = jest.fn() as unknown as NextFunction; - - // envoyMiddleware synchronously invokes loggerFactory and attaches req.logger - // before delegating to body-parser. We don't care about what body-parser does - // here — we just verify req.logger is now usable by structuredErrorMiddleware. - middleware(req, res as unknown as Response, next); - - const err = new Error('boom'); - structuredErrorMiddleware()(err, req, res as unknown as Response, next); + let loginSpy: jest.SpyInstance; + + beforeEach(() => { + // envoyMiddleware refreshes its access token via EnvoyPluginAPI.loginAsPlugin + // before initializing req.envoy. Stub it so tests don't hit the network. + loginSpy = jest + .spyOn(EnvoyPluginAPI, 'loginAsPlugin') + .mockResolvedValue({ access_token: 'test-token', expires_in: 3600 } as never); + }); - expect(loggerError).toHaveBeenCalledWith('Unhandled error in request pipeline', err, { - operation: 'structuredErrorMiddleware', - httpMethod: 'POST', - httpUrl: '/some/path', - }); + afterEach(() => { + loginSpy.mockRestore(); }); - it('passes integrationName from req.query.name to the loggerFactory', () => { - const loggerFactory = jest.fn(() => ({ error: jest.fn() })); + // Short-circuit body-parser by marking the body as pre-parsed — body-parser + // skips its stream-reading path and calls our callback directly when it sees + // `req._body === true`, so we can drive envoyMiddleware in a unit test + // without standing up a real HTTP server. We also mark the request as + // VERIFIED, since body-parser's `verify` callback (which would normally set + // it) is bypassed by the short-circuit. + function buildEventReq(overrides: Partial = {}): Request { + return { + method: 'POST', + originalUrl: '/some/path', + headers: {}, + query: { name: 'checkr' }, + _body: true, + [VERIFIED]: true, + body: { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + event: 'entry_sign_in', + }, + payload: { id: 'visitor-1', type: 'visitors' }, + }, + ...overrides, + } as unknown as Request; + } + + it('attaches a logger built from the full Envoy context after req.envoy is initialized', async () => { + const logger = { error: jest.fn() }; + const loggerFactory = jest.fn(() => logger); const middleware = envoyMiddleware({ secret: 'test-secret', algorithm: 'sha256', @@ -196,41 +209,35 @@ describe('structuredErrorMiddleware', () => { loggerFactory, }); - const req = buildReq({ query: { name: 'checkr' } } as Partial); + const req = buildEventReq(); const res = buildRes(); - const next = jest.fn() as unknown as NextFunction; - - middleware(req, res as unknown as Response, next); + // Resolves once envoyMiddleware calls next(), which only happens after the + // async login + EnvoyPluginSDK setup + loggerFactory call. + await new Promise((resolve, reject) => { + middleware( + req, + res as unknown as Response, + ((err?: unknown) => (err ? reject(err) : resolve())) as NextFunction, + ); + }); expect(loggerFactory).toHaveBeenCalledTimes(1); - expect(loggerFactory).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); - }); - - it('passes integrationName: undefined when ?name= is missing or not a string', () => { - const loggerFactory = jest.fn(() => ({ error: jest.fn() })); - const middleware = envoyMiddleware({ - secret: 'test-secret', - algorithm: 'sha256', - encoding: 'base64', - header: 'x-envoy-signature', - loggerFactory, + const [factoryReq, factoryCtx] = loggerFactory.mock.calls[0] as unknown as [EnvoyRequest, unknown]; + expect(factoryReq).toBe(req); + expect(factoryReq.envoy).toBeDefined(); + expect(factoryCtx).toEqual({ + integrationName: 'checkr', + installId: 'install-1', + locationId: 'loc-1', + companyId: 'company-1', + recordId: 'visitor-1', + recordType: 'visitors', + event: 'entry_sign_in', + category: 'Visitor', }); - - const next = jest.fn() as unknown as NextFunction; - - // No query at all. - const reqA = buildReq(); - middleware(reqA, buildRes() as unknown as Response, next); - expect(loggerFactory).toHaveBeenLastCalledWith(reqA, { integrationName: undefined }); - - // Repeated query param (express parses to string[]) — not a single string, - // so we deliberately drop it rather than guess. - const reqB = buildReq({ query: { name: ['a', 'b'] } } as unknown as Partial); - middleware(reqB, buildRes() as unknown as Response, next); - expect(loggerFactory).toHaveBeenLastCalledWith(reqB, { integrationName: undefined }); }); - it('continues without a logger when loggerFactory throws', () => { + it('catches loggerFactory exceptions and leaves req.logger unset', async () => { const middleware = envoyMiddleware({ secret: 'test-secret', algorithm: 'sha256', @@ -241,22 +248,118 @@ describe('structuredErrorMiddleware', () => { }, }); - const req = buildReq(); + const req = buildEventReq(); const res = buildRes(); - const next = jest.fn() as unknown as NextFunction; - - middleware(req, res as unknown as Response, next); + await new Promise((resolve, reject) => { + middleware( + req, + res as unknown as Response, + ((err?: unknown) => (err ? reject(err) : resolve())) as NextFunction, + ); + }); - // Surfaced via console.error, never thrown. expect(consoleErrorSpy).toHaveBeenCalledWith('envoyMiddleware: loggerFactory threw', expect.any(Error)); - // And req.logger should not be set, so the fallback path kicks in downstream. - const err = new Error('boom'); + // structuredErrorMiddleware should fall through to console.error since + // req.logger never got set. consoleErrorSpy.mockClear(); - structuredErrorMiddleware()(err, req, res as unknown as Response, next); + const err = new Error('boom'); + structuredErrorMiddleware()(err, req, res as unknown as Response, jest.fn() as unknown as NextFunction); expect(consoleErrorSpy).toHaveBeenCalledWith(err); }); }); + describe('extractLoggerContext', () => { + function buildEnvoyRequest(envoy: unknown, query: Record = {}): EnvoyRequest { + return { envoy, query } as unknown as EnvoyRequest; + } + + it('pulls every standard Envoy field from an event request', () => { + const req = buildEnvoyRequest( + { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + event: 'invite_created', + }, + payload: { id: 'invite-1', type: 'invites' }, + }, + { name: 'checkr' }, + ); + + expect(extractLoggerContext(req)).toEqual({ + integrationName: 'checkr', + installId: 'install-1', + locationId: 'loc-1', + companyId: 'company-1', + recordId: 'invite-1', + recordType: 'invites', + event: 'invite_created', + category: 'Visitor', + }); + }); + + it('omits event/category for route requests (no `event` on meta)', () => { + const req = buildEnvoyRequest( + { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + route: 'validate', + }, + payload: {}, + }, + { name: 'checkr' }, + ); + + const ctx = extractLoggerContext(req); + expect(ctx.event).toBeUndefined(); + expect(ctx.category).toBeUndefined(); + expect(ctx.installId).toBe('install-1'); + }); + + it('maps unrecognized events to category "Unrecognized"', () => { + const req = buildEnvoyRequest({ + meta: { install_id: 'i', location: { id: 'l' }, company: { id: 'c' }, event: 'mystery_event' }, + payload: {}, + }); + + expect(extractLoggerContext(req)).toMatchObject({ + event: 'mystery_event', + category: 'Unrecognized', + }); + }); + + it('maps workplace / desks / communication events to their categories', () => { + const makeReq = (event: string) => buildEnvoyRequest({ meta: { event }, payload: {} }); + + expect(extractLoggerContext(makeReq('employee_entry_sign_in')).category).toBe('Workplace'); + expect(extractLoggerContext(makeReq('desk_sign_in')).category).toBe('Desks'); + expect(extractLoggerContext(makeReq('takeover_started')).category).toBe('Communication'); + }); + + it('returns just integrationName when req.envoy is missing', () => { + const req = buildEnvoyRequest(undefined, { name: 'checkr' }); + + expect(extractLoggerContext(req)).toEqual({ integrationName: 'checkr' }); + }); + + it('degrades gracefully when meta/payload fields are missing', () => { + const req = buildEnvoyRequest({ meta: {}, payload: undefined }, {}); + + // Every field present in the result is `undefined` — no throw, no missing keys. + expect(extractLoggerContext(req)).toEqual({ + integrationName: undefined, + installId: undefined, + locationId: undefined, + companyId: undefined, + recordId: undefined, + recordType: undefined, + }); + }); + }); + describe('response handling', () => { it('sends a 500 JSON response when headers have not been sent', () => { const req = buildReq(); From 26a5ec8ff7c33eb6d3949ed7f5375675cff9f2af Mon Sep 17 00:00:00 2001 From: Zach Matarasso Date: Tue, 19 May 2026 16:56:15 -0400 Subject: [PATCH 4/5] fix: invoke loggerFactory twice so loginAsPlugin errors keep req.logger MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The post-init-only design lost the original goal of replacing errorMiddleware(console.log): errors that fire before req.envoy is set up (plugin login, EnvoyPluginSDK construction) had no req.logger and fell through to console.error, the same bare-string outcome we're trying to get rid of. Switch to a two-call pattern: 1. **Early pass** runs synchronously at the top of envoyMiddleware, before body parsing. integrationName from req.query.name is the only field available pre-parse, but that's enough to guarantee req.logger exists for any subsequent error (body-parser, loginAsPlugin, EnvoyPluginSDK init). 2. **Enrichment pass** runs after req.envoy is initialized, with the full EnvoyLoggerContext (companyId, installId, event, category, …), and replaces req.logger so route-handler errors carry the standard Envoy facets. If the enrichment pass throws, req.logger is *not* downgraded — the early logger is retained. console.error tells the caller which pass blew up so the failure mode is debuggable. The only error class still served by structuredErrorMiddleware's console.error fallback is malformed-JSON body-parser errors, which have no payload/meta to enrich with regardless. Factory signature loosens back to `(req: Request, ctx: EnvoyLoggerContext) => StructuredLogger` — `req.envoy` is not set on the early call, so typing the arg as EnvoyRequest would be a lie. Tests: 97 passing (added early-pass observation, two-call replacement, enrichment-throws-keeps-early-logger, and early-throws-leaves-logger- undefined cases). Co-Authored-By: Claude Opus 4.7 (1M context) --- src/sdk/middleware.ts | 73 +++++++++++++++++++++-------- test/sdk/middleware.test.ts | 91 ++++++++++++++++++++++++++++--------- 2 files changed, 123 insertions(+), 41 deletions(-) diff --git a/src/sdk/middleware.ts b/src/sdk/middleware.ts index cff330b..cd1d518 100644 --- a/src/sdk/middleware.ts +++ b/src/sdk/middleware.ts @@ -105,23 +105,37 @@ const ENVOY_EVENT_CATEGORIES: Readonly> = { */ export interface EnvoyMiddlewareOptions extends Partial { /** - * If provided, invoked once per request — after `req.envoy` is initialized - * and immediately before `next()` — to build a {@link StructuredLogger}. - * The result is attached to `req.logger` so it's available to every - * downstream handler and to `structuredErrorMiddleware`. + * If provided, invoked **twice** per request to build a + * {@link StructuredLogger} that gets attached to `req.logger` for the rest + * of the chain (including `structuredErrorMiddleware`). * - * Called with the full {@link EnvoyLoggerContext} extracted from - * `req.query` + `req.envoy.meta` + `req.envoy.payload`, so the factory can - * produce a child logger pre-tagged with `integrationName`, `companyId`, - * `installId`, `event`, etc. without any per-service boilerplate. + * 1. **Early call** — synchronously at the top of the handler, *before* + * body parsing and `EnvoyPluginAPI.loginAsPlugin`. The context only + * contains `integrationName` (the one field we can derive from the raw + * request without parsing the body). This guarantees `req.logger` + * exists if body parsing or plugin login fails, so those errors land + * as structured logs instead of stringified `console.log` output. * - * Errors thrown by the factory are caught and surfaced via `console.error` - * — they never break the request pipeline. Errors that fire *before* - * `req.envoy` finishes initializing (body parsing, plugin login) won't - * have `req.logger` set; `structuredErrorMiddleware` falls back to - * `console.error` for those, matching today's behavior. + * 2. **Enrichment call** — after `req.envoy` is initialized, with the + * full {@link EnvoyLoggerContext} (`companyId`, `installId`, `event`, + * `category`, …). The result *replaces* `req.logger`, so every + * downstream handler logs with the standard Envoy facets baked in. + * If the enrichment call throws, the early logger is kept as a + * fallback — `req.logger` never downgrades to `undefined`. + * + * Most factories are a one-liner like + * `(_req, ctx) => rootLogger.child(ctx)`. The double invocation is + * cheap (two child-logger allocations) and produces no observable + * difference at the caller — the second logger supersedes the first. + * + * The only error class still served by the fallback `console.error` path + * in `structuredErrorMiddleware` is malformed-JSON body-parser errors, + * which have no payload/meta to enrich with regardless. + * + * Exceptions thrown by the factory itself are caught and surfaced via + * `console.error` — a buggy factory never breaks the request pipeline. */ - loggerFactory?: (req: EnvoyRequest, context: EnvoyLoggerContext) => StructuredLogger; + loggerFactory?: (req: Request, context: EnvoyLoggerContext) => StructuredLogger; } /** @@ -201,10 +215,12 @@ export function extractLoggerContext(req: EnvoyRequest): EnvoyLoggerContext { * as well as managing the plugin access token lifecycle. * * If a `loggerFactory` is supplied, attaches the produced - * {@link StructuredLogger} to `req.logger` once `req.envoy` is initialized, - * passing the factory the full {@link EnvoyLoggerContext} (integration name, - * company id, install id, event, category, …) so downstream handlers and + * {@link StructuredLogger} to `req.logger` early — first with an + * `integrationName`-only context so body-parser / plugin-login errors are + * still structured, then again after `req.envoy` is initialized with the + * full {@link EnvoyLoggerContext} so downstream handlers and * `structuredErrorMiddleware` log with the standard Envoy facets baked in. + * See `loggerFactory` for the full two-call contract. * * @category Middleware */ @@ -219,6 +235,21 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle let threshold = 0; return (req: Request, res: Response, next: NextFunction) => { + // Early pass: attach a minimal logger so body-parser / loginAsPlugin + // errors are still structured. `integrationName` is the only field we + // can derive from the raw request before body parsing — the enrichment + // pass below adds the rest once `req.envoy` is initialized. + if (loggerFactory) { + try { + const earlyContext: EnvoyLoggerContext = { integrationName: extractIntegrationName(req) }; + (req as Request & { logger?: StructuredLogger }).logger = loggerFactory(req, earlyContext); + } catch (factoryErr) { + // A failing loggerFactory must not break the request pipeline — surface + // the error so it's debuggable, then continue without a request logger. + // eslint-disable-next-line no-console + console.error('envoyMiddleware: loggerFactory (early) threw', factoryErr); + } + } json(req, res, async (err) => { if (err) { return next(err); @@ -234,14 +265,16 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle const envoyResponse = res as EnvoyResponse; envoyRequest.envoy = new EnvoyPluginSDK(envoyRequest.body, envoyRequest[VERIFIED], accessToken); + // Enrichment pass: replace `req.logger` with one that carries the + // full Envoy context now that `req.envoy` exists. If the factory + // throws here, keep the early logger as a fallback — never downgrade + // `req.logger` to `undefined`. if (loggerFactory) { try { envoyRequest.logger = loggerFactory(envoyRequest, extractLoggerContext(envoyRequest)); } catch (factoryErr) { - // A failing loggerFactory must not break the request pipeline — surface - // the error so it's debuggable, then continue without a request logger. // eslint-disable-next-line no-console - console.error('envoyMiddleware: loggerFactory threw', factoryErr); + console.error('envoyMiddleware: loggerFactory (enrichment) threw', factoryErr); } } diff --git a/test/sdk/middleware.test.ts b/test/sdk/middleware.test.ts index ff394e3..2782a4b 100644 --- a/test/sdk/middleware.test.ts +++ b/test/sdk/middleware.test.ts @@ -198,9 +198,36 @@ describe('structuredErrorMiddleware', () => { } as unknown as Request; } - it('attaches a logger built from the full Envoy context after req.envoy is initialized', async () => { - const logger = { error: jest.fn() }; - const loggerFactory = jest.fn(() => logger); + it('attaches an integrationName-only logger synchronously, before body parsing', () => { + // The early pass runs before json() returns, so we can observe req.logger + // synchronously without driving the async login path. + const earlyLogger = { error: jest.fn() }; + const loggerFactory = jest.fn(() => earlyLogger); + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory, + }); + + const req = buildEventReq(); + // We *don't* await — we only want to inspect state immediately after the + // sync portion of envoyMiddleware runs. + middleware(req, buildRes() as unknown as Response, jest.fn() as unknown as NextFunction); + + // First call only sees `integrationName` (no body parsed yet → no meta/payload). + expect(loggerFactory).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); + expect((req as Request & { logger?: unknown }).logger).toBe(earlyLogger); + }); + + it('replaces req.logger with a fully-enriched one after req.envoy is initialized', async () => { + // Distinguish the two factory invocations by returning two different objects. + const earlyLogger = { error: jest.fn() }; + const lateLogger = { error: jest.fn() }; + const loggerFactory = jest.fn(); + loggerFactory.mockReturnValueOnce(earlyLogger).mockReturnValueOnce(lateLogger); + const middleware = envoyMiddleware({ secret: 'test-secret', algorithm: 'sha256', @@ -211,8 +238,6 @@ describe('structuredErrorMiddleware', () => { const req = buildEventReq(); const res = buildRes(); - // Resolves once envoyMiddleware calls next(), which only happens after the - // async login + EnvoyPluginSDK setup + loggerFactory call. await new Promise((resolve, reject) => { middleware( req, @@ -221,11 +246,11 @@ describe('structuredErrorMiddleware', () => { ); }); - expect(loggerFactory).toHaveBeenCalledTimes(1); - const [factoryReq, factoryCtx] = loggerFactory.mock.calls[0] as unknown as [EnvoyRequest, unknown]; - expect(factoryReq).toBe(req); - expect(factoryReq.envoy).toBeDefined(); - expect(factoryCtx).toEqual({ + expect(loggerFactory).toHaveBeenCalledTimes(2); + // Early call: integrationName only. + expect(loggerFactory.mock.calls[0][1]).toEqual({ integrationName: 'checkr' }); + // Enrichment call: full context. + expect(loggerFactory.mock.calls[1][1]).toEqual({ integrationName: 'checkr', installId: 'install-1', locationId: 'loc-1', @@ -235,17 +260,23 @@ describe('structuredErrorMiddleware', () => { event: 'entry_sign_in', category: 'Visitor', }); + // The enriched logger wins. + expect((req as Request & { logger?: unknown }).logger).toBe(lateLogger); }); - it('catches loggerFactory exceptions and leaves req.logger unset', async () => { + it('keeps the early logger when the enrichment pass throws', async () => { + const earlyLogger = { error: jest.fn() }; + const loggerFactory = jest.fn(); + loggerFactory.mockReturnValueOnce(earlyLogger).mockImplementationOnce(() => { + throw new Error('enrichment blew up'); + }); + const middleware = envoyMiddleware({ secret: 'test-secret', algorithm: 'sha256', encoding: 'base64', header: 'x-envoy-signature', - loggerFactory: () => { - throw new Error('factory blew up'); - }, + loggerFactory, }); const req = buildEventReq(); @@ -258,13 +289,31 @@ describe('structuredErrorMiddleware', () => { ); }); - expect(consoleErrorSpy).toHaveBeenCalledWith('envoyMiddleware: loggerFactory threw', expect.any(Error)); - // structuredErrorMiddleware should fall through to console.error since - // req.logger never got set. - consoleErrorSpy.mockClear(); - const err = new Error('boom'); - structuredErrorMiddleware()(err, req, res as unknown as Response, jest.fn() as unknown as NextFunction); - expect(consoleErrorSpy).toHaveBeenCalledWith(err); + expect(consoleErrorSpy).toHaveBeenCalledWith( + 'envoyMiddleware: loggerFactory (enrichment) threw', + expect.any(Error), + ); + // Logger never downgrades to undefined — early logger is retained. + expect((req as Request & { logger?: unknown }).logger).toBe(earlyLogger); + }); + + it('leaves req.logger unset when the early pass throws and surfaces via console.error', () => { + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory: () => { + throw new Error('early factory blew up'); + }, + }); + + const req = buildEventReq(); + // Only inspecting the sync portion — don't drive the async flow. + middleware(req, buildRes() as unknown as Response, jest.fn() as unknown as NextFunction); + + expect(consoleErrorSpy).toHaveBeenCalledWith('envoyMiddleware: loggerFactory (early) threw', expect.any(Error)); + expect((req as Request & { logger?: unknown }).logger).toBeUndefined(); }); }); From d1cea9e8e94245d9a149892eda73c42650a86500 Mon Sep 17 00:00:00 2001 From: Zach Matarasso Date: Tue, 19 May 2026 17:07:12 -0400 Subject: [PATCH 5/5] refactor: single factory + .child() chain via addRequestLoggerContext MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previous design called the loggerFactory twice (once early with integrationName, once after envoy init with the full context) to give loginAsPlugin / EnvoyPluginSDK construction errors a structured logger. Replaces that with a single factory invocation plus a chained .child(context) enrichment pattern that any number of middleware can participate in. New surface in src/sdk/StructuredLogger.ts: - StructuredLogger now requires `child(context): StructuredLogger` alongside `error(...)`. The internal SDK's StructuredLogger and every mainstream logging library (pino, bunyan, winston) already implement this — the SDK just makes it part of the contract. - isRequestWithLogger checks for both methods so a partial logger fails closed (structuredErrorMiddleware → console.error fallback). - addRequestLoggerContext(req, ctx, fallback?) is the new universal helper. If req.logger exists, it's replaced with req.logger.child(ctx); otherwise the optional fallback constructs one from scratch; otherwise no-op. Exceptions from either path are caught and surfaced via console.error — req.logger never downgrades to undefined. envoyMiddleware: - Calls loggerFactory exactly once, synchronously at the top of the handler, with `{ integrationName }`. That guarantees req.logger exists for body-parser / loginAsPlugin / EnvoyPluginSDK errors. - No more post-init enrichment pass. envoyLoggerContextMiddleware (new): - Place after envoyMiddleware so req.envoy is set. - Adds the full EnvoyLoggerContext (companyId, installId, event, category, …) via addRequestLoggerContext — i.e. req.logger.child(...). - Optional `fallback` to construct from scratch if no upstream logger. This is the recommended pattern for every downstream middleware: call addRequestLoggerContext(req, myContext, optionalFallback). pluginMiddleware in screener / pacs / etc. can drop their bespoke "rootLogger.child(...) + try/catch + envoyRequest.logger = logger" boilerplate in favor of one line. Tests: 105 passing (StructuredLogger.test.ts now covers .child contract + addRequestLoggerContext happy/fallback/throw paths; middleware.test.ts covers single factory call, envoyLoggerContextMiddleware replace/fallback/no-op behavior). Co-Authored-By: Claude Opus 4.7 (1M context) --- src/sdk/StructuredLogger.ts | 74 +++- src/sdk/middleware.ts | 131 +++++--- test/sdk/StructuredLogger.test.ts | 103 +++++- test/sdk/middleware.test.ts | 542 +++++++++++++++++------------- 4 files changed, 543 insertions(+), 307 deletions(-) diff --git a/src/sdk/StructuredLogger.ts b/src/sdk/StructuredLogger.ts index 4f1f616..d5b99f1 100644 --- a/src/sdk/StructuredLogger.ts +++ b/src/sdk/StructuredLogger.ts @@ -3,18 +3,25 @@ import { Request } from 'express'; /** * Minimum contract the SDK requires from a logger attached to a request. * - * Any logger that implements this `error` signature — including the - * `StructuredLogger` from `@envoy/envoy-integrations-internal-sdk` — is - * compatible with the SDK middleware (`envoyMiddleware`, `structuredErrorMiddleware`). + * Two methods: + * - `error(...)` — used by `structuredErrorMiddleware` to emit unhandled + * errors as structured log events. + * - `child(context)` — used by `addRequestLoggerContext` so middleware + * downstream from `envoyMiddleware` can enrich the request logger with + * additional context (integration name, install id, route name, …) + * without each middleware re-implementing the "if logger, child; + * else construct" dance. * - * Kept intentionally narrow: callers are free to attach a logger with - * additional methods (`info`, `warn`, `debug`, etc.), but the SDK only - * relies on `error` so it stays decoupled from any specific logging library. + * The `StructuredLogger` from `@envoy/envoy-integrations-internal-sdk` + * already implements both methods, as do most production logging libraries + * (pino, bunyan, winston). Callers are free to attach a logger with extra + * methods (`info`, `warn`, `debug`, …); the SDK just won't call them. * * @category Logger */ export interface StructuredLogger { error(message: string, error: Error, metadata?: Record): void; + child(context: Record): StructuredLogger; } /** @@ -33,9 +40,9 @@ export interface RequestWithLogger extends Request { * Type guard that narrows a request to {@link RequestWithLogger} when a * usable structured logger is present at `req.logger`. * - * Use this instead of an unchecked cast when consuming `req.logger` from - * middleware/handlers — the runtime check ensures that downstream code only - * runs against a logger object that actually implements `error()`. + * Verifies *both* `error` and `child` are functions — anything attached as + * `req.logger` must satisfy the full {@link StructuredLogger} contract for + * the SDK helpers to operate on it. * * @category Logger */ @@ -44,5 +51,52 @@ export function isRequestWithLogger(req: Request): req is RequestWithLogger { if (typeof candidate !== 'object' || candidate === null) { return false; } - return typeof (candidate as { error?: unknown }).error === 'function'; + const logger = candidate as { error?: unknown; child?: unknown }; + return typeof logger.error === 'function' && typeof logger.child === 'function'; +} + +/** + * Adds context to `req.logger` using the pattern recommended for every + * middleware downstream from `envoyMiddleware`: + * + * - **If `req.logger` is already set**, replace it with + * `req.logger.child(additionalContext)` so subsequent middleware / + * handlers see a logger pre-tagged with the accumulated context. + * - **Otherwise**, if a `fallback` factory is provided, call it to + * construct a logger from scratch. Use this in middleware that wants + * to be usable both with and without `envoyMiddleware`'s loggerFactory + * wired up. + * - **Otherwise**, leave `req.logger` undefined — the caller opted out + * of structured logging. + * + * Exceptions thrown by either `req.logger.child(...)` or the fallback + * factory are caught and surfaced via `console.error` so a buggy logger + * never breaks the request pipeline. The previous `req.logger` is + * preserved in that case. + * + * @category Logger + */ +export function addRequestLoggerContext( + req: Request, + additionalContext: Record, + fallback?: (req: Request, context: Record) => StructuredLogger, +): void { + const reqWithLogger = req as Request & { logger?: StructuredLogger }; + if (isRequestWithLogger(req)) { + try { + reqWithLogger.logger = req.logger.child(additionalContext); + } catch (childErr) { + // eslint-disable-next-line no-console + console.error('addRequestLoggerContext: req.logger.child threw', childErr); + } + return; + } + if (fallback) { + try { + reqWithLogger.logger = fallback(req, additionalContext); + } catch (fallbackErr) { + // eslint-disable-next-line no-console + console.error('addRequestLoggerContext: fallback factory threw', fallbackErr); + } + } } diff --git a/src/sdk/middleware.ts b/src/sdk/middleware.ts index cd1d518..4326f32 100644 --- a/src/sdk/middleware.ts +++ b/src/sdk/middleware.ts @@ -8,7 +8,7 @@ import EnvoyResponse from './EnvoyResponse'; import EnvoyPluginJobAttachment, { EnvoyPluginScreenerJobAttachment } from './EnvoyPluginJobAttachment'; import EnvoyPluginSDK from './EnvoyPluginSDK'; import EnvoyPluginAPI from './EnvoyPluginAPI'; -import { StructuredLogger, isRequestWithLogger } from './StructuredLogger'; +import { StructuredLogger, addRequestLoggerContext, isRequestWithLogger } from './StructuredLogger'; /** * Request-scoped context that `envoyMiddleware` makes available to a @@ -105,34 +105,26 @@ const ENVOY_EVENT_CATEGORIES: Readonly> = { */ export interface EnvoyMiddlewareOptions extends Partial { /** - * If provided, invoked **twice** per request to build a - * {@link StructuredLogger} that gets attached to `req.logger` for the rest - * of the chain (including `structuredErrorMiddleware`). + * If provided, invoked once per request, synchronously at the top of the + * handler (*before* body parsing and `EnvoyPluginAPI.loginAsPlugin`), to + * build a base {@link StructuredLogger}. The result is attached to + * `req.logger`. * - * 1. **Early call** — synchronously at the top of the handler, *before* - * body parsing and `EnvoyPluginAPI.loginAsPlugin`. The context only - * contains `integrationName` (the one field we can derive from the raw - * request without parsing the body). This guarantees `req.logger` - * exists if body parsing or plugin login fails, so those errors land - * as structured logs instead of stringified `console.log` output. + * The context only contains `integrationName` — the one field derivable + * from the raw request without parsing the body. Subsequent middleware + * in the chain (`envoyLoggerContextMiddleware`, your own per-service + * middleware, etc.) enriches `req.logger` with additional context via + * {@link addRequestLoggerContext}, which calls `req.logger.child(...)` + * instead of asking the factory to construct a new logger. * - * 2. **Enrichment call** — after `req.envoy` is initialized, with the - * full {@link EnvoyLoggerContext} (`companyId`, `installId`, `event`, - * `category`, …). The result *replaces* `req.logger`, so every - * downstream handler logs with the standard Envoy facets baked in. - * If the enrichment call throws, the early logger is kept as a - * fallback — `req.logger` never downgrades to `undefined`. + * This guarantees `req.logger` exists as early as possible so + * body-parser, plugin-login, and `EnvoyPluginSDK` construction errors + * land as structured logs in `structuredErrorMiddleware` rather than as + * unstructured `console.log` output. * - * Most factories are a one-liner like - * `(_req, ctx) => rootLogger.child(ctx)`. The double invocation is - * cheap (two child-logger allocations) and produces no observable - * difference at the caller — the second logger supersedes the first. + * Most factories are a one-liner: `(_req, ctx) => rootLogger.child(ctx)`. * - * The only error class still served by the fallback `console.error` path - * in `structuredErrorMiddleware` is malformed-JSON body-parser errors, - * which have no payload/meta to enrich with regardless. - * - * Exceptions thrown by the factory itself are caught and surfaced via + * Exceptions thrown by the factory are caught and surfaced via * `console.error` — a buggy factory never breaks the request pipeline. */ loggerFactory?: (req: Request, context: EnvoyLoggerContext) => StructuredLogger; @@ -215,12 +207,12 @@ export function extractLoggerContext(req: EnvoyRequest): EnvoyLoggerContext { * as well as managing the plugin access token lifecycle. * * If a `loggerFactory` is supplied, attaches the produced - * {@link StructuredLogger} to `req.logger` early — first with an - * `integrationName`-only context so body-parser / plugin-login errors are - * still structured, then again after `req.envoy` is initialized with the - * full {@link EnvoyLoggerContext} so downstream handlers and - * `structuredErrorMiddleware` log with the standard Envoy facets baked in. - * See `loggerFactory` for the full two-call contract. + * {@link StructuredLogger} to `req.logger` synchronously at the start of + * the handler with an `integrationName`-only context. Downstream + * middleware adds the rest of the Envoy facets (`companyId`, `installId`, + * `event`, `category`, …) via {@link addRequestLoggerContext} — call + * {@link envoyLoggerContextMiddleware} for the standard enrichment, or use + * the helper directly in your own middleware. * * @category Middleware */ @@ -235,19 +227,19 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle let threshold = 0; return (req: Request, res: Response, next: NextFunction) => { - // Early pass: attach a minimal logger so body-parser / loginAsPlugin - // errors are still structured. `integrationName` is the only field we - // can derive from the raw request before body parsing — the enrichment - // pass below adds the rest once `req.envoy` is initialized. + // Attach a base logger via the factory synchronously. `integrationName` + // is the only context derivable from the raw request before body + // parsing — every downstream middleware extends this base via + // `addRequestLoggerContext` rather than calling the factory again. if (loggerFactory) { try { - const earlyContext: EnvoyLoggerContext = { integrationName: extractIntegrationName(req) }; - (req as Request & { logger?: StructuredLogger }).logger = loggerFactory(req, earlyContext); + const baseContext: EnvoyLoggerContext = { integrationName: extractIntegrationName(req) }; + (req as Request & { logger?: StructuredLogger }).logger = loggerFactory(req, baseContext); } catch (factoryErr) { // A failing loggerFactory must not break the request pipeline — surface // the error so it's debuggable, then continue without a request logger. // eslint-disable-next-line no-console - console.error('envoyMiddleware: loggerFactory (early) threw', factoryErr); + console.error('envoyMiddleware: loggerFactory threw', factoryErr); } } json(req, res, async (err) => { @@ -265,19 +257,6 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle const envoyResponse = res as EnvoyResponse; envoyRequest.envoy = new EnvoyPluginSDK(envoyRequest.body, envoyRequest[VERIFIED], accessToken); - // Enrichment pass: replace `req.logger` with one that carries the - // full Envoy context now that `req.envoy` exists. If the factory - // throws here, keep the early logger as a fallback — never downgrade - // `req.logger` to `undefined`. - if (loggerFactory) { - try { - envoyRequest.logger = loggerFactory(envoyRequest, extractLoggerContext(envoyRequest)); - } catch (factoryErr) { - // eslint-disable-next-line no-console - console.error('envoyMiddleware: loggerFactory (enrichment) threw', factoryErr); - } - } - /** * Respond with "ongoing" for long jobs. */ @@ -333,6 +312,56 @@ export function envoyMiddleware(options?: EnvoyMiddlewareOptions): RequestHandle }; } +/** + * Options for {@link envoyLoggerContextMiddleware}. + * + * @category Middleware + */ +export interface EnvoyLoggerContextMiddlewareOptions { + /** + * If `req.logger` isn't already set (the caller didn't wire + * `envoyMiddleware`'s `loggerFactory`), this factory is used to + * construct one from scratch with the Envoy context. Omit to make this + * middleware a no-op when no upstream logger exists. + */ + fallback?: (req: Request, context: EnvoyLoggerContext) => StructuredLogger; +} + +/** + * Enriches `req.logger` with the standard Envoy logging facets (extracted + * via {@link extractLoggerContext}) using {@link addRequestLoggerContext}. + * Place this after `envoyMiddleware` so `req.envoy` is initialized. + * + * Behavior follows the convention recommended for every middleware + * downstream from `envoyMiddleware`: + * + * - If `req.logger` is set, it's replaced with + * `req.logger.child({ companyId, installId, event, … })`. + * - Otherwise, if a `fallback` factory is provided, it's used to + * construct a logger from scratch. + * - Otherwise, this middleware is a no-op. + * + * Your own per-service middleware can use the same pattern via + * {@link addRequestLoggerContext} to layer in additional context (route + * name, validation step, plugin name, …). + * + * @category Middleware + */ +export function envoyLoggerContextMiddleware(options?: EnvoyLoggerContextMiddlewareOptions): RequestHandler { + const { fallback } = options ?? {}; + // Adapt the typed `fallback(req, EnvoyLoggerContext)` into the generic + // `(req, Record)` shape that addRequestLoggerContext + // expects. `extractLoggerContext` only emits keys from EnvoyLoggerContext + // so the cast back to that type is safe. + const fallbackAdapter = fallback + ? (req: Request, context: Record) => fallback(req, context as EnvoyLoggerContext) + : undefined; + return (req: Request, _res: Response, next: NextFunction) => { + addRequestLoggerContext(req, { ...extractLoggerContext(req as EnvoyRequest) }, fallbackAdapter); + next(); + }; +} + /** * Catches errors and sets the proper status code. * diff --git a/test/sdk/StructuredLogger.test.ts b/test/sdk/StructuredLogger.test.ts index 21bd698..6baf1bc 100644 --- a/test/sdk/StructuredLogger.test.ts +++ b/test/sdk/StructuredLogger.test.ts @@ -1,20 +1,31 @@ import type { Request } from 'express'; -import { isRequestWithLogger } from '../../src/sdk/StructuredLogger'; +import { addRequestLoggerContext, isRequestWithLogger, StructuredLogger } from '../../src/sdk/StructuredLogger'; function reqWith(logger: unknown): Request { return { logger } as unknown as Request; } +function makeLogger(): StructuredLogger { + // Implements the full contract: `error` and `child`. `child` returns + // a fresh logger that also implements the contract, so chained calls + // are well-typed. + return { + error: jest.fn(), + child: jest.fn(() => makeLogger()), + }; +} + describe('isRequestWithLogger', () => { - it('narrows when req.logger has a callable error method', () => { - const req = reqWith({ error: jest.fn() }); + it('narrows when req.logger has callable error AND child methods', () => { + const req = reqWith(makeLogger()); expect(isRequestWithLogger(req)).toBe(true); if (isRequestWithLogger(req)) { // Type guard narrows `req` to RequestWithLogger so this access is well-typed. expect(typeof req.logger.error).toBe('function'); + expect(typeof req.logger.child).toBe('function'); } }); @@ -32,18 +43,88 @@ describe('isRequestWithLogger', () => { }); it('returns false when req.logger.error is not a function', () => { - expect(isRequestWithLogger(reqWith({ error: 'not a fn' }))).toBe(false); - expect(isRequestWithLogger(reqWith({ info: jest.fn() }))).toBe(false); + expect(isRequestWithLogger(reqWith({ error: 'not a fn', child: jest.fn() }))).toBe(false); + expect(isRequestWithLogger(reqWith({ info: jest.fn(), child: jest.fn() }))).toBe(false); + }); + + it('returns false when req.logger.child is not a function', () => { + // Loggers must support .child() so downstream middleware can layer in + // context — a logger without .child can't participate in the contract. + expect(isRequestWithLogger(reqWith({ error: jest.fn() }))).toBe(false); + expect(isRequestWithLogger(reqWith({ error: jest.fn(), child: 'not a fn' }))).toBe(false); + }); +}); + +describe('addRequestLoggerContext', () => { + /* eslint-disable no-console */ + const originalConsoleError = console.error; + let consoleErrorSpy: jest.Mock; + + beforeEach(() => { + consoleErrorSpy = jest.fn(); + console.error = consoleErrorSpy; + }); + + afterEach(() => { + console.error = originalConsoleError; + }); + /* eslint-enable no-console */ + + it('replaces req.logger with the child logger when one is already present', () => { + const childLogger = makeLogger(); + const baseLogger = { error: jest.fn(), child: jest.fn(() => childLogger) }; + const req = reqWith(baseLogger); + + addRequestLoggerContext(req, { installId: 'i-1' }); + + expect(baseLogger.child).toHaveBeenCalledWith({ installId: 'i-1' }); + expect((req as Request & { logger?: unknown }).logger).toBe(childLogger); }); - it('accepts loggers with additional methods beyond error', () => { - const fullLogger = { + it('uses the fallback factory when req.logger is absent', () => { + const constructed = makeLogger(); + const fallback = jest.fn(() => constructed); + const req = {} as Request; + + addRequestLoggerContext(req, { integrationName: 'checkr' }, fallback); + + expect(fallback).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); + expect((req as Request & { logger?: unknown }).logger).toBe(constructed); + }); + + it('is a no-op when req.logger is absent and no fallback is provided', () => { + const req = {} as Request; + + addRequestLoggerContext(req, { installId: 'i-1' }); + + expect((req as Request & { logger?: unknown }).logger).toBeUndefined(); + }); + + it('catches exceptions thrown by req.logger.child and keeps the previous logger', () => { + const baseLogger = { error: jest.fn(), - info: jest.fn(), - warn: jest.fn(), - debug: jest.fn(), + child: jest.fn(() => { + throw new Error('child blew up'); + }), }; + const req = reqWith(baseLogger); + + addRequestLoggerContext(req, { installId: 'i-1' }); + + expect(consoleErrorSpy).toHaveBeenCalledWith('addRequestLoggerContext: req.logger.child threw', expect.any(Error)); + // Previous logger preserved — never downgrades. + expect((req as Request & { logger?: unknown }).logger).toBe(baseLogger); + }); + + it('catches exceptions thrown by the fallback factory', () => { + const fallback = jest.fn(() => { + throw new Error('fallback blew up'); + }); + const req = {} as Request; + + addRequestLoggerContext(req, { installId: 'i-1' }, fallback); - expect(isRequestWithLogger(reqWith(fullLogger))).toBe(true); + expect(consoleErrorSpy).toHaveBeenCalledWith('addRequestLoggerContext: fallback factory threw', expect.any(Error)); + expect((req as Request & { logger?: unknown }).logger).toBeUndefined(); }); }); diff --git a/test/sdk/middleware.test.ts b/test/sdk/middleware.test.ts index 2782a4b..d471f95 100644 --- a/test/sdk/middleware.test.ts +++ b/test/sdk/middleware.test.ts @@ -2,7 +2,13 @@ import type { NextFunction, Request, Response } from 'express'; import EnvoyPluginAPI from '../../src/sdk/EnvoyPluginAPI'; import EnvoyRequest, { VERIFIED } from '../../src/sdk/EnvoyRequest'; -import { envoyMiddleware, extractLoggerContext, structuredErrorMiddleware } from '../../src/sdk/middleware'; +import { + envoyLoggerContextMiddleware, + envoyMiddleware, + extractLoggerContext, + structuredErrorMiddleware, +} from '../../src/sdk/middleware'; +import { StructuredLogger } from '../../src/sdk/StructuredLogger'; type MockResponse = { headersSent: boolean; @@ -11,6 +17,22 @@ type MockResponse = { end: jest.Mock; }; +/** + * A test logger that satisfies the full {@link StructuredLogger} contract: + * `error` records calls; `child(ctx)` returns a new test logger that records + * the context it was built with, so multi-step enrichment chains can be + * inspected. + */ +function buildLogger(): StructuredLogger & { error: jest.Mock; child: jest.Mock } { + const logger = { + error: jest.fn(), + // `child` is set after construction so the recursive type lines up. + child: jest.fn(), + }; + logger.child.mockImplementation(() => buildLogger()); + return logger; +} + function buildReq(overrides: Partial = {}): Request { return { method: 'POST', @@ -46,16 +68,16 @@ describe('structuredErrorMiddleware', () => { describe('default behavior (no onError callback)', () => { it('calls req.logger.error with message, err, and {operation, httpMethod, httpUrl}', () => { - const loggerError = jest.fn(); - const req = buildReq({ logger: { error: loggerError } }); + const logger = buildLogger(); + const req = buildReq({ logger }); const res = buildRes(); const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); structuredErrorMiddleware()(err, req, res as unknown as Response, next); - expect(loggerError).toHaveBeenCalledTimes(1); - expect(loggerError).toHaveBeenCalledWith('Unhandled error in request pipeline', err, { + expect(logger.error).toHaveBeenCalledTimes(1); + expect(logger.error).toHaveBeenCalledWith('Unhandled error in request pipeline', err, { operation: 'structuredErrorMiddleware', httpMethod: 'POST', httpUrl: '/some/path', @@ -76,7 +98,21 @@ describe('structuredErrorMiddleware', () => { }); it('falls back to console.error when req.logger has no error method', () => { - const req = buildReq({ logger: { info: jest.fn() } }); + const req = buildReq({ logger: { info: jest.fn(), child: jest.fn() } }); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); + + structuredErrorMiddleware()(err, req, res as unknown as Response, next); + + expect(consoleErrorSpy).toHaveBeenCalledTimes(1); + expect(consoleErrorSpy).toHaveBeenCalledWith(err); + }); + + it('falls back to console.error when req.logger has no child method', () => { + // .child is required by the StructuredLogger contract — without it the + // logger can't participate in the addRequestLoggerContext pattern. + const req = buildReq({ logger: { error: jest.fn() } }); const res = buildRes(); const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); @@ -100,10 +136,11 @@ describe('structuredErrorMiddleware', () => { }); it('does not propagate exceptions thrown by req.logger.error', () => { - const loggerError = jest.fn(() => { + const logger = buildLogger(); + logger.error.mockImplementation(() => { throw new Error('logger blew up'); }); - const req = buildReq({ logger: { error: loggerError } }); + const req = buildReq({ logger }); const res = buildRes(); const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); @@ -112,8 +149,7 @@ describe('structuredErrorMiddleware', () => { structuredErrorMiddleware()(err, req, res as unknown as Response, next); }).not.toThrow(); - // Original error log was attempted; the logger's throw was caught and surfaced via console. - expect(loggerError).toHaveBeenCalled(); + expect(logger.error).toHaveBeenCalled(); expect(consoleErrorSpy).toHaveBeenCalledWith( 'structuredErrorMiddleware: req.logger.error threw', expect.any(Error), @@ -124,8 +160,8 @@ describe('structuredErrorMiddleware', () => { describe('with onError callback', () => { it('invokes the callback with (err, req) and does not touch req.logger', () => { const onError = jest.fn(); - const loggerError = jest.fn(); - const req = buildReq({ logger: { error: loggerError } }); + const logger = buildLogger(); + const req = buildReq({ logger }); const res = buildRes(); const next = jest.fn() as unknown as NextFunction; const err = new Error('boom'); @@ -134,7 +170,7 @@ describe('structuredErrorMiddleware', () => { expect(onError).toHaveBeenCalledTimes(1); expect(onError).toHaveBeenCalledWith(err, req); - expect(loggerError).not.toHaveBeenCalled(); + expect(logger.error).not.toHaveBeenCalled(); }); it('does not propagate exceptions thrown by the callback', () => { @@ -156,121 +192,94 @@ describe('structuredErrorMiddleware', () => { }); }); - describe('end-to-end with envoyMiddleware loggerFactory', () => { - let loginSpy: jest.SpyInstance; + describe('response handling', () => { + it('sends a 500 JSON response when headers have not been sent', () => { + const req = buildReq(); + const res = buildRes(); + const next = jest.fn() as unknown as NextFunction; + const err = new Error('boom'); - beforeEach(() => { - // envoyMiddleware refreshes its access token via EnvoyPluginAPI.loginAsPlugin - // before initializing req.envoy. Stub it so tests don't hit the network. - loginSpy = jest - .spyOn(EnvoyPluginAPI, 'loginAsPlugin') - .mockResolvedValue({ access_token: 'test-token', expires_in: 3600 } as never); + structuredErrorMiddleware()(err, req, res as unknown as Response, next); + + expect(res.statusCode).toBe(500); + expect(res.setHeader).toHaveBeenCalledWith('Content-Type', 'application/json'); + expect(res.end).toHaveBeenCalledWith(JSON.stringify({ message: 'boom' })); + expect(next).not.toHaveBeenCalled(); }); - afterEach(() => { - loginSpy.mockRestore(); + it('delegates to next(err) when headers have already been sent', () => { + const req = buildReq(); + const res = buildRes(true); + const next = jest.fn(); + const err = new Error('boom'); + + structuredErrorMiddleware()(err, req, res as unknown as Response, next as unknown as NextFunction); + + expect(next).toHaveBeenCalledWith(err); + expect(res.end).not.toHaveBeenCalled(); }); + }); +}); - // Short-circuit body-parser by marking the body as pre-parsed — body-parser - // skips its stream-reading path and calls our callback directly when it sees - // `req._body === true`, so we can drive envoyMiddleware in a unit test - // without standing up a real HTTP server. We also mark the request as - // VERIFIED, since body-parser's `verify` callback (which would normally set - // it) is bypassed by the short-circuit. - function buildEventReq(overrides: Partial = {}): Request { - return { - method: 'POST', - originalUrl: '/some/path', - headers: {}, - query: { name: 'checkr' }, - _body: true, - [VERIFIED]: true, - body: { - meta: { - install_id: 'install-1', - location: { id: 'loc-1' }, - company: { id: 'company-1' }, - event: 'entry_sign_in', - }, - payload: { id: 'visitor-1', type: 'visitors' }, - }, - ...overrides, - } as unknown as Request; - } +describe('envoyMiddleware loggerFactory', () => { + /* eslint-disable no-console */ + const originalConsoleError = console.error; + let consoleErrorSpy: jest.Mock; - it('attaches an integrationName-only logger synchronously, before body parsing', () => { - // The early pass runs before json() returns, so we can observe req.logger - // synchronously without driving the async login path. - const earlyLogger = { error: jest.fn() }; - const loggerFactory = jest.fn(() => earlyLogger); - const middleware = envoyMiddleware({ - secret: 'test-secret', - algorithm: 'sha256', - encoding: 'base64', - header: 'x-envoy-signature', - loggerFactory, - }); + beforeEach(() => { + consoleErrorSpy = jest.fn(); + console.error = consoleErrorSpy; + }); - const req = buildEventReq(); - // We *don't* await — we only want to inspect state immediately after the - // sync portion of envoyMiddleware runs. - middleware(req, buildRes() as unknown as Response, jest.fn() as unknown as NextFunction); + afterEach(() => { + console.error = originalConsoleError; + }); + /* eslint-enable no-console */ - // First call only sees `integrationName` (no body parsed yet → no meta/payload). - expect(loggerFactory).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); - expect((req as Request & { logger?: unknown }).logger).toBe(earlyLogger); + it('attaches a logger synchronously with integrationName-only context, before body parsing', () => { + const logger = buildLogger(); + const loggerFactory = jest.fn(() => logger); + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory, }); - it('replaces req.logger with a fully-enriched one after req.envoy is initialized', async () => { - // Distinguish the two factory invocations by returning two different objects. - const earlyLogger = { error: jest.fn() }; - const lateLogger = { error: jest.fn() }; - const loggerFactory = jest.fn(); - loggerFactory.mockReturnValueOnce(earlyLogger).mockReturnValueOnce(lateLogger); - - const middleware = envoyMiddleware({ - secret: 'test-secret', - algorithm: 'sha256', - encoding: 'base64', - header: 'x-envoy-signature', - loggerFactory, - }); + const req = buildReq({ query: { name: 'checkr' } }); + middleware(req, buildRes() as unknown as Response, jest.fn() as unknown as NextFunction); - const req = buildEventReq(); - const res = buildRes(); - await new Promise((resolve, reject) => { - middleware( - req, - res as unknown as Response, - ((err?: unknown) => (err ? reject(err) : resolve())) as NextFunction, - ); - }); + expect(loggerFactory).toHaveBeenCalledTimes(1); + expect(loggerFactory).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); + expect((req as Request & { logger?: unknown }).logger).toBe(logger); + }); - expect(loggerFactory).toHaveBeenCalledTimes(2); - // Early call: integrationName only. - expect(loggerFactory.mock.calls[0][1]).toEqual({ integrationName: 'checkr' }); - // Enrichment call: full context. - expect(loggerFactory.mock.calls[1][1]).toEqual({ - integrationName: 'checkr', - installId: 'install-1', - locationId: 'loc-1', - companyId: 'company-1', - recordId: 'visitor-1', - recordType: 'visitors', - event: 'entry_sign_in', - category: 'Visitor', - }); - // The enriched logger wins. - expect((req as Request & { logger?: unknown }).logger).toBe(lateLogger); + it('leaves req.logger unset (and console.errors) when the factory throws', () => { + const middleware = envoyMiddleware({ + secret: 'test-secret', + algorithm: 'sha256', + encoding: 'base64', + header: 'x-envoy-signature', + loggerFactory: () => { + throw new Error('factory blew up'); + }, }); - it('keeps the early logger when the enrichment pass throws', async () => { - const earlyLogger = { error: jest.fn() }; - const loggerFactory = jest.fn(); - loggerFactory.mockReturnValueOnce(earlyLogger).mockImplementationOnce(() => { - throw new Error('enrichment blew up'); - }); + const req = buildReq(); + middleware(req, buildRes() as unknown as Response, jest.fn() as unknown as NextFunction); + + expect(consoleErrorSpy).toHaveBeenCalledWith('envoyMiddleware: loggerFactory threw', expect.any(Error)); + expect((req as Request & { logger?: unknown }).logger).toBeUndefined(); + }); + it('does not call the factory again after req.envoy is initialized', async () => { + const loginSpy = jest + .spyOn(EnvoyPluginAPI, 'loginAsPlugin') + .mockResolvedValue({ access_token: 'test-token', expires_in: 3600 } as never); + try { + const logger = buildLogger(); + const loggerFactory = jest.fn(() => logger); const middleware = envoyMiddleware({ secret: 'test-secret', algorithm: 'sha256', @@ -279,161 +288,224 @@ describe('structuredErrorMiddleware', () => { loggerFactory, }); - const req = buildEventReq(); - const res = buildRes(); + // Same body-parser short-circuit / VERIFIED trick as the integration test below. + const req = { + method: 'POST', + originalUrl: '/some/path', + headers: {}, + query: { name: 'checkr' }, + _body: true, + [VERIFIED]: true, + body: { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + event: 'entry_sign_in', + }, + payload: { id: 'visitor-1', type: 'visitors' }, + }, + } as unknown as Request; + await new Promise((resolve, reject) => { middleware( req, - res as unknown as Response, + buildRes() as unknown as Response, ((err?: unknown) => (err ? reject(err) : resolve())) as NextFunction, ); }); - expect(consoleErrorSpy).toHaveBeenCalledWith( - 'envoyMiddleware: loggerFactory (enrichment) threw', - expect.any(Error), - ); - // Logger never downgrades to undefined — early logger is retained. - expect((req as Request & { logger?: unknown }).logger).toBe(earlyLogger); - }); - - it('leaves req.logger unset when the early pass throws and surfaces via console.error', () => { - const middleware = envoyMiddleware({ - secret: 'test-secret', - algorithm: 'sha256', - encoding: 'base64', - header: 'x-envoy-signature', - loggerFactory: () => { - throw new Error('early factory blew up'); - }, - }); + // Factory should be invoked exactly once — enrichment happens via .child() + // downstream, not by re-invoking the factory. + expect(loggerFactory).toHaveBeenCalledTimes(1); + expect(loggerFactory).toHaveBeenCalledWith(req, { integrationName: 'checkr' }); + } finally { + loginSpy.mockRestore(); + } + }); +}); - const req = buildEventReq(); - // Only inspecting the sync portion — don't drive the async flow. - middleware(req, buildRes() as unknown as Response, jest.fn() as unknown as NextFunction); +describe('envoyLoggerContextMiddleware', () => { + /* eslint-disable no-console */ + const originalConsoleError = console.error; + let consoleErrorSpy: jest.Mock; - expect(consoleErrorSpy).toHaveBeenCalledWith('envoyMiddleware: loggerFactory (early) threw', expect.any(Error)); - expect((req as Request & { logger?: unknown }).logger).toBeUndefined(); - }); + beforeEach(() => { + consoleErrorSpy = jest.fn(); + console.error = consoleErrorSpy; }); - describe('extractLoggerContext', () => { - function buildEnvoyRequest(envoy: unknown, query: Record = {}): EnvoyRequest { - return { envoy, query } as unknown as EnvoyRequest; - } + afterEach(() => { + console.error = originalConsoleError; + }); + /* eslint-enable no-console */ - it('pulls every standard Envoy field from an event request', () => { - const req = buildEnvoyRequest( - { - meta: { - install_id: 'install-1', - location: { id: 'loc-1' }, - company: { id: 'company-1' }, - event: 'invite_created', - }, - payload: { id: 'invite-1', type: 'invites' }, + function buildEnvoyReqWithLogger(logger: StructuredLogger | undefined): Request { + return { + method: 'POST', + originalUrl: '/some/path', + headers: {}, + query: { name: 'checkr' }, + envoy: { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + event: 'entry_sign_in', }, - { name: 'checkr' }, - ); - - expect(extractLoggerContext(req)).toEqual({ - integrationName: 'checkr', - installId: 'install-1', - locationId: 'loc-1', - companyId: 'company-1', - recordId: 'invite-1', - recordType: 'invites', - event: 'invite_created', - category: 'Visitor', - }); + payload: { id: 'visitor-1', type: 'visitors' }, + }, + ...(logger ? { logger } : {}), + } as unknown as Request; + } + + it('replaces req.logger with a child carrying the full Envoy context', () => { + const childLogger = buildLogger(); + const baseLogger = buildLogger(); + baseLogger.child.mockReturnValue(childLogger); + + const req = buildEnvoyReqWithLogger(baseLogger); + const next = jest.fn() as unknown as NextFunction; + + envoyLoggerContextMiddleware()(req, buildRes() as unknown as Response, next); + + expect(baseLogger.child).toHaveBeenCalledWith({ + integrationName: 'checkr', + installId: 'install-1', + locationId: 'loc-1', + companyId: 'company-1', + recordId: 'visitor-1', + recordType: 'visitors', + event: 'entry_sign_in', + category: 'Visitor', }); + expect((req as Request & { logger?: unknown }).logger).toBe(childLogger); + expect(next).toHaveBeenCalledTimes(1); + }); - it('omits event/category for route requests (no `event` on meta)', () => { - const req = buildEnvoyRequest( - { - meta: { - install_id: 'install-1', - location: { id: 'loc-1' }, - company: { id: 'company-1' }, - route: 'validate', - }, - payload: {}, - }, - { name: 'checkr' }, - ); - - const ctx = extractLoggerContext(req); - expect(ctx.event).toBeUndefined(); - expect(ctx.category).toBeUndefined(); - expect(ctx.installId).toBe('install-1'); + it('uses the fallback factory when req.logger is absent', () => { + const constructed = buildLogger(); + const fallback = jest.fn(() => constructed); + const req = buildEnvoyReqWithLogger(undefined); + const next = jest.fn() as unknown as NextFunction; + + envoyLoggerContextMiddleware({ fallback })(req, buildRes() as unknown as Response, next); + + expect(fallback).toHaveBeenCalledTimes(1); + const [fallbackReq, fallbackCtx] = fallback.mock.calls[0] as unknown as [Request, unknown]; + expect(fallbackReq).toBe(req); + expect(fallbackCtx).toEqual({ + integrationName: 'checkr', + installId: 'install-1', + locationId: 'loc-1', + companyId: 'company-1', + recordId: 'visitor-1', + recordType: 'visitors', + event: 'entry_sign_in', + category: 'Visitor', }); + expect((req as Request & { logger?: unknown }).logger).toBe(constructed); + expect(next).toHaveBeenCalledTimes(1); + }); - it('maps unrecognized events to category "Unrecognized"', () => { - const req = buildEnvoyRequest({ - meta: { install_id: 'i', location: { id: 'l' }, company: { id: 'c' }, event: 'mystery_event' }, - payload: {}, - }); + it('is a no-op when req.logger is absent and no fallback is provided', () => { + const req = buildEnvoyReqWithLogger(undefined); + const next = jest.fn() as unknown as NextFunction; - expect(extractLoggerContext(req)).toMatchObject({ - event: 'mystery_event', - category: 'Unrecognized', - }); - }); + envoyLoggerContextMiddleware()(req, buildRes() as unknown as Response, next); - it('maps workplace / desks / communication events to their categories', () => { - const makeReq = (event: string) => buildEnvoyRequest({ meta: { event }, payload: {} }); + expect((req as Request & { logger?: unknown }).logger).toBeUndefined(); + expect(next).toHaveBeenCalledTimes(1); + }); +}); - expect(extractLoggerContext(makeReq('employee_entry_sign_in')).category).toBe('Workplace'); - expect(extractLoggerContext(makeReq('desk_sign_in')).category).toBe('Desks'); - expect(extractLoggerContext(makeReq('takeover_started')).category).toBe('Communication'); +describe('extractLoggerContext', () => { + function buildEnvoyRequest(envoy: unknown, query: Record = {}): EnvoyRequest { + return { envoy, query } as unknown as EnvoyRequest; + } + + it('pulls every standard Envoy field from an event request', () => { + const req = buildEnvoyRequest( + { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + event: 'invite_created', + }, + payload: { id: 'invite-1', type: 'invites' }, + }, + { name: 'checkr' }, + ); + + expect(extractLoggerContext(req)).toEqual({ + integrationName: 'checkr', + installId: 'install-1', + locationId: 'loc-1', + companyId: 'company-1', + recordId: 'invite-1', + recordType: 'invites', + event: 'invite_created', + category: 'Visitor', }); + }); - it('returns just integrationName when req.envoy is missing', () => { - const req = buildEnvoyRequest(undefined, { name: 'checkr' }); + it('omits event/category for route requests (no `event` on meta)', () => { + const req = buildEnvoyRequest( + { + meta: { + install_id: 'install-1', + location: { id: 'loc-1' }, + company: { id: 'company-1' }, + route: 'validate', + }, + payload: {}, + }, + { name: 'checkr' }, + ); + + const ctx = extractLoggerContext(req); + expect(ctx.event).toBeUndefined(); + expect(ctx.category).toBeUndefined(); + expect(ctx.installId).toBe('install-1'); + }); - expect(extractLoggerContext(req)).toEqual({ integrationName: 'checkr' }); + it('maps unrecognized events to category "Unrecognized"', () => { + const req = buildEnvoyRequest({ + meta: { install_id: 'i', location: { id: 'l' }, company: { id: 'c' }, event: 'mystery_event' }, + payload: {}, }); - it('degrades gracefully when meta/payload fields are missing', () => { - const req = buildEnvoyRequest({ meta: {}, payload: undefined }, {}); - - // Every field present in the result is `undefined` — no throw, no missing keys. - expect(extractLoggerContext(req)).toEqual({ - integrationName: undefined, - installId: undefined, - locationId: undefined, - companyId: undefined, - recordId: undefined, - recordType: undefined, - }); + expect(extractLoggerContext(req)).toMatchObject({ + event: 'mystery_event', + category: 'Unrecognized', }); }); - describe('response handling', () => { - it('sends a 500 JSON response when headers have not been sent', () => { - const req = buildReq(); - const res = buildRes(); - const next = jest.fn() as unknown as NextFunction; - const err = new Error('boom'); + it('maps workplace / desks / communication events to their categories', () => { + const makeReq = (event: string) => buildEnvoyRequest({ meta: { event }, payload: {} }); - structuredErrorMiddleware()(err, req, res as unknown as Response, next); + expect(extractLoggerContext(makeReq('employee_entry_sign_in')).category).toBe('Workplace'); + expect(extractLoggerContext(makeReq('desk_sign_in')).category).toBe('Desks'); + expect(extractLoggerContext(makeReq('takeover_started')).category).toBe('Communication'); + }); - expect(res.statusCode).toBe(500); - expect(res.setHeader).toHaveBeenCalledWith('Content-Type', 'application/json'); - expect(res.end).toHaveBeenCalledWith(JSON.stringify({ message: 'boom' })); - expect(next).not.toHaveBeenCalled(); - }); + it('returns just integrationName when req.envoy is missing', () => { + const req = buildEnvoyRequest(undefined, { name: 'checkr' }); - it('delegates to next(err) when headers have already been sent', () => { - const req = buildReq(); - const res = buildRes(true); - const next = jest.fn(); - const err = new Error('boom'); + expect(extractLoggerContext(req)).toEqual({ integrationName: 'checkr' }); + }); - structuredErrorMiddleware()(err, req, res as unknown as Response, next as unknown as NextFunction); + it('degrades gracefully when meta/payload fields are missing', () => { + const req = buildEnvoyRequest({ meta: {}, payload: undefined }, {}); - expect(next).toHaveBeenCalledWith(err); - expect(res.end).not.toHaveBeenCalled(); + expect(extractLoggerContext(req)).toEqual({ + integrationName: undefined, + installId: undefined, + locationId: undefined, + companyId: undefined, + recordId: undefined, + recordType: undefined, }); }); });