[validation-tools] add a throw+log mode to parseReq (#36821)

REQ_VALIDATION_MODE=enforce-log rejects schema failures exactly as 'enforce'
does, but logs them first at instrumented call sites, so the visibility built
for the 'log' rollout (sanitized issues, caller trace, logFields values, per
schema/signature dedup) survives moving out of 'log' mode.

opts no longer change the outcome in this mode: logOnly does not suppress the
throw, the error is classified from the primary schema (not the fallback), and
fallbackSchema is only re-parsed to tag the log entry -- 'enforced-fallback-
passed' marks a rejection the looser pre-refinement schema would have avoided,
i.e. one the tightened schema newly introduces.

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
GitOrigin-RevId: 0743322990e6c570ffbae166b4586285a18221df

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<LogKind, string>}
+ */
+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<T>} 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)

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