diff --git a/libraries/validation-tools/parseReq.js b/libraries/validation-tools/parseReq.js index 21f4059440..911aa3cb8e 100644 --- a/libraries/validation-tools/parseReq.js +++ b/libraries/validation-tools/parseReq.js @@ -20,18 +20,24 @@ const { */ /** - * Log-only rollout options for parseReq(), see REQ_VALIDATION_MODE below. + * Rollout options for parseReq(), see REQ_VALIDATION_MODE below. Passing opts + * marks a call site as instrumented: in REQ_VALIDATION_MODE=log they change + * what a schema failure does, in REQ_VALIDATION_MODE=enforce-log they only + * add the failure log, and in REQ_VALIDATION_MODE=enforce they are inert. * * @typedef {object} ParseReqOptions * @property {boolean} [logOnly] - In REQ_VALIDATION_MODE=log, a primary * schema failure (with no passing fallbackSchema) logs once and returns - * the raw, un-coerced request input instead of throwing. + * the raw, un-coerced request input instead of throwing. It never + * suppresses the throw in enforce-log mode. * @property {ZodType} [fallbackSchema] - In REQ_VALIDATION_MODE=log, a * primary schema failure is re-parsed against this looser/pre-refinement * schema. If it passes, its output is returned (and the primary schema's * issues are logged). If it also fails, behavior falls back to logOnly * above, classifying/throwing from the fallback's ZodError when logOnly - * is not set. + * is not set. In enforce-log mode it never changes the outcome (the + * request is rejected either way) and is only re-parsed to tag the log + * entry with whether the looser schema would have accepted the request. * @property {string[]} [logFields] - Dotted field paths (e.g. 'body.zipUrl') * whose raw input values are resolved and included in the schema-failure * log entry. Values are only resolved on failure; strings are truncated @@ -63,30 +69,41 @@ function schemaInput(req) { } /* - * Rollout mode for parseReq's log-only instrumentation, controlled by the - * REQ_VALIDATION_MODE env var. Default (unset or any invalid value) is + * Rollout mode for parseReq's schema-failure instrumentation, controlled by + * the REQ_VALIDATION_MODE env var. Default (unset or any invalid value) is * 'log' -- deliberately not coupled to NODE_ENV, nothing automatic. * * - 'log': a schema failure at an instrumented call site (one that passes * opts) logs instead of throwing, see parseReq() below. Call sites that * don't pass opts are unaffected and always throw. + * - 'enforce-log': throw+log. Failures are rejected exactly as in 'enforce' + * -- opts change nothing about the outcome -- but an instrumented call + * site logs the failure first, so the visibility built for the 'log' + * rollout (sanitized issues, caller trace, opts.logFields values, deduped + * per schema and signature) survives the move out of 'log' mode. This is + * the mode to move a service to once its schemas look clean in 'log' + * mode, and to stay in while the instrumentation is still in the code. * - 'enforce': opts are inert, every call site always throws on failure, * exactly as if parseReq() had no third parameter at all. */ +/** + * @typedef {'log' | 'enforce-log' | 'enforce'} ReqValidationMode + */ + /** * @param {string | null | undefined} m - * @returns {m is 'log' | 'enforce'} + * @returns {m is ReqValidationMode} */ function isValidReqValidationMode(m) { - return m === 'log' || m === 'enforce' + return m === 'log' || m === 'enforce-log' || m === 'enforce' } -/** @type {'log' | 'enforce' | null} */ +/** @type {ReqValidationMode | null} */ let cachedMode = null /** - * @returns {'log' | 'enforce'} + * @returns {ReqValidationMode} */ function mode() { if (cachedMode == null) { @@ -98,8 +115,9 @@ function mode() { /** * Override the mode for tests. Pass null to clear the cache and force a - * re-read of REQ_VALIDATION_MODE on the next access; pass 'log'/'enforce'/ - * anything else to force that value (coerced the same way mode() would). + * re-read of REQ_VALIDATION_MODE on the next access; pass 'log'/'enforce-log' + * /'enforce'/anything else to force that value (coerced the same way mode() + * would). * * Exported from index.js -- unlike testUtils.js's stateless assertion * helpers, this mutates module state that must be visible to the exact @@ -197,13 +215,39 @@ function sanitizeIssues(issues, depth = 0) { }) } +/** + * What happened to the request the log entry describes: the first two kinds + * are the 'log' mode outcomes (the request was let through), the last two the + * 'enforce-log' ones (the request was rejected, and 'enforced-fallback- + * passed' marks a rejection the looser fallbackSchema would have avoided -- + * i.e. one the tightened schema newly introduces, the interesting signal). + * + * @typedef {'log-only' | 'fallback-passed' | 'enforced' | 'enforced-fallback-passed'} LogKind + */ + +/** + * The log message per kind. The 'log' rollout's wording is kept verbatim for + * its two kinds so existing log queries keep matching, with a distinct + * message for the throw+log kinds; the `kind` field separates all four. + * + * @type {Record} + */ +const LOG_MESSAGES = { + 'log-only': 'req-validation: request failed schema in log-only rollout', + 'fallback-passed': + 'req-validation: request failed schema in log-only rollout', + enforced: 'req-validation: request failed schema and was rejected', + 'enforced-fallback-passed': + 'req-validation: request failed schema and was rejected', +} + /** * Log a schema failure once per unique (kind, sanitized issues) signature * for the given primary schema. No-op if no logger has been injected. * * @param {Request} req * @param {ZodType} schema - the primary schema; the dedup key. - * @param {'log-only' | 'fallback-passed'} kind + * @param {LogKind} kind * @param {readonly ZodIssue[]} issues * @param {Request} input - the (possibly lockdown-unwrapped) request input * @param {string[]} [logFields] - dotted paths to resolve from input @@ -258,7 +302,7 @@ function logSchemaFailure(req, schema, kind, issues, input, logFields) { req, ...(resolvedFields && { failingValues: resolvedFields }), }, - 'req-validation: request failed schema in log-only rollout' + LOG_MESSAGES[kind] ) } @@ -284,14 +328,16 @@ function throwClassified(error) { * @template {ZodType} T * @param {Request} req - The Express request object * @param {T} schema - The Zod schema to validate against - * @param {ParseReqOptions} [opts] - Log-only rollout options. Untouched call - * sites that omit opts always enforce (throw on failure), in every mode -- - * opts only matter when REQ_VALIDATION_MODE=log. + * @param {ParseReqOptions} [opts] - Rollout options. Untouched call sites + * that omit opts always enforce (throw on failure) and log nothing, in + * every mode -- opts change the outcome only when REQ_VALIDATION_MODE=log, + * and only add the failure log when REQ_VALIDATION_MODE=enforce-log. * @returns {output} The validated request object. Note: in * REQ_VALIDATION_MODE=log, a failing parse at an instrumented call site * (opts set) does not necessarily produce T -- it may instead return * opts.fallbackSchema's output, or the raw, un-coerced request input, per - * the opts handling documented above. + * the opts handling documented above. In enforce-log and enforce mode a + * failing parse always throws, so the return value really is T. */ function parseReq(req, schema, opts) { const input = schemaInput(req) @@ -347,6 +393,24 @@ function parseReq(req, schema, opts) { } // opts present but neither field set: nothing to do in log mode, // fall through to throwing as normal. + } else if (opts && mode() === 'enforce-log') { + // Throw+log: the outcome is 'enforce's -- classified from the primary + // schema's error, whatever opts say, since the primary schema is the one + // being enforced -- but the failure is logged first, so an instrumented + // call site keeps reporting what is failing after the service moves out + // of 'log' mode. A fallbackSchema only picks the kind here; it is parsed + // on the failure path only, so this costs nothing on healthy traffic. + const fallbackPassed = Boolean( + opts.fallbackSchema && opts.fallbackSchema.safeParse(input).success + ) + logSchemaFailure( + req, + schema, + fallbackPassed ? 'enforced-fallback-passed' : 'enforced', + parsed.error.issues, + input, + opts.logFields + ) } throwClassified(parsed.error) diff --git a/libraries/validation-tools/test/unit/src/parseReqLogOnlyRollout.test.ts b/libraries/validation-tools/test/unit/src/parseReqLogOnlyRollout.test.ts index aadae02c8c..0a74cd5904 100644 --- a/libraries/validation-tools/test/unit/src/parseReqLogOnlyRollout.test.ts +++ b/libraries/validation-tools/test/unit/src/parseReqLogOnlyRollout.test.ts @@ -102,6 +102,16 @@ describe('parseReq log-only rollout', () => { }).not.toThrow() expect(result).toEqual({ body: { name: 1234 } }) }) + + it('is a no-op in enforce-log mode too: the failure still throws', () => { + setReqValidationModeForTests('enforce-log') + const req = { body: { name: 1234 } } as Request + const schema = z.object({ body: z.object({ name: z.string() }) }) + + expect(() => parseReq(req, schema, { logOnly: true })).toThrowError( + expect.objectContaining({ name: 'InvalidRequestError' }) + ) + }) }) describe('with an injected logger', () => { @@ -145,6 +155,158 @@ describe('parseReq log-only rollout', () => { }) }) + describe('enforce-log mode (throw+log)', () => { + beforeEach(() => { + setReqValidationModeForTests('enforce-log') + }) + + it('logs the failure and then throws, with logOnly set', () => { + const req = { body: { name: 1234 } } as Request + const schema = z.object({ body: z.object({ name: z.string() }) }) + + expect(() => parseReq(req, schema, { logOnly: true })).toThrowError( + expect.objectContaining({ name: 'InvalidRequestError' }) + ) + expect(warnMock).toHaveBeenCalledTimes(1) + const [ctx, msg] = warnMock.mock.calls[0] as WarnCall + expect(ctx.kind).toBe('enforced') + expect(msg).toBe( + 'req-validation: request failed schema and was rejected' + ) + expect(ctx.issues).toEqual( + expect.arrayContaining([ + expect.objectContaining({ path: 'body.name' }), + ]) + ) + }) + + it('logs and then throws InvalidParamsError for a params failure', () => { + const req = { params: { id: 'nope' } } as Request<{ id: string }> + const schema = z.object({ + params: z.object({ id: z.string().regex(/^[0-9]+$/) }), + }) + + expect(() => parseReq(req, schema, { logOnly: true })).toThrowError( + expect.objectContaining({ name: 'InvalidParamsError' }) + ) + expect(warnMock).toHaveBeenCalledTimes(1) + const [ctx] = warnMock.mock.calls[0] as WarnCall + expect(ctx.kind).toBe('enforced') + }) + + it('logs nothing and throws when no opts are passed', () => { + const req = { body: { name: 1234 } } as Request + const schema = z.object({ body: z.object({ name: z.string() }) }) + + expect(() => parseReq(req, schema)).toThrowError( + expect.objectContaining({ name: 'InvalidRequestError' }) + ) + expect(warnMock).not.toHaveBeenCalled() + }) + + it('returns the parsed data and logs nothing on success', () => { + const req = { body: { name: 'ok' } } as Request + const schema = z.object({ body: z.object({ name: z.string() }) }) + + const result = parseReq(req, schema, { + logOnly: true, + fallbackSchema: z.any(), + }) + + expect(result).toEqual({ body: { name: 'ok' } }) + expect(warnMock).not.toHaveBeenCalled() + }) + + it('logs enforced-fallback-passed but still throws when the fallback would have passed', () => { + const req = { body: { count: '5' } } as Request + const primary = z.object({ body: z.object({ count: z.number() }) }) + const fallback = z.object({ + body: z.object({ count: z.coerce.number().default(0) }), + }) + + expect(() => + parseReq(req, primary, { fallbackSchema: fallback }) + ).toThrowError(expect.objectContaining({ name: 'InvalidRequestError' })) + expect(warnMock).toHaveBeenCalledTimes(1) + const [ctx] = warnMock.mock.calls[0] as WarnCall + expect(ctx.kind).toBe('enforced-fallback-passed') + }) + + it('classifies from the primary error, not the fallback error, when both fail', () => { + const req = { + params: { id: 'not-a-number' }, + body: { name: 'ok' }, + } as Request<{ id: string }, any, { name: string }> + // Fails on body (name is a string, not a number). + const primary = z.object({ + params: z.object({ id: z.string() }), + body: z.object({ name: z.number() }), + }) + // Fails on params (id is a string, not a number). + const fallback = z.object({ + params: z.object({ id: z.number() }), + body: z.object({ name: z.string() }), + }) + + // Log mode throws InvalidParamsError here, from the fallback's error. + expect(() => + parseReq(req, primary, { fallbackSchema: fallback, logOnly: true }) + ).toThrowError(expect.objectContaining({ name: 'InvalidRequestError' })) + const [ctx] = warnMock.mock.calls[0] as WarnCall + expect(ctx.kind).toBe('enforced') + }) + + it('resolves logFields into failingValues', () => { + const req = { body: { zipUrl: '/bad/path' } } as Request + const schema = z.object({ + body: z.object({ zipUrl: z.string().url() }), + }) + + expect(() => + parseReq(req, schema, { logOnly: true, logFields: ['body.zipUrl'] }) + ).toThrow() + + const [ctx] = warnMock.mock.calls[0] as WarnCall + expect(ctx.failingValues).toEqual({ 'body.zipUrl': '/bad/path' }) + }) + + it('never leaks a sentinel value present in the request', () => { + const req = { body: { name: 'SECRET_VALUE_123' } } as Request + const schema = z.object({ body: z.object({ name: z.number() }) }) + + expect(() => parseReq(req, schema, { logOnly: true })).toThrow() + + expect(serializedLogOutput(warnMock.mock.calls)).not.toContain( + 'SECRET_VALUE_123' + ) + }) + + it('logs exactly once for a repeated identical failure against the same schema', () => { + const schema = z.strictObject({ + body: z.strictObject({ name: z.string() }), + }) + const req = { body: { name: 1234 } } as Request + + expect(() => parseReq(req, schema, { logOnly: true })).toThrow() + expect(() => parseReq(req, schema, { logOnly: true })).toThrow() + + expect(warnMock).toHaveBeenCalledTimes(1) + }) + + it('logs again when the same schema fails a different way', () => { + const schema = z.strictObject({ + body: z.strictObject({ name: z.string() }), + }) + const req1 = { body: { name: 1234 } } as Request + const req2 = { body: { name: 'ok', extra: true } } as Request + + expect(() => parseReq(req1, schema, { logOnly: true })).toThrow() + expect(() => parseReq(req2, schema, { logOnly: true })).toThrow() + + expect(warnMock).toHaveBeenCalledTimes(2) + }) + }) + // NOTE: the task description's spec text says "Default (unset OR any // invalid value) is 'log'" for REQ_VALIDATION_MODE (repeated for // setReqValidationModeForTests: "coerced the same way the real getter