The first thing most pipelines do with user input is interpolate it into a debug log. If validation sits one line below that, your "guard" runs after the crash — and everything that doesn't crash goes into the logs unvalidated.

Last tested: August 2026, Node 22 / TypeScript. See Changelog at the bottom.

If this saves you a confusing stack trace, follow @renezander030 — production notes on agent pipelines, retrieval and approval gates.

Real-world fix using this pattern: tetherto/qvac#3729, merged into Tether's QVAC RAG package.

Three questions, asked of the first function user input reaches:

1. What is the first expression that dereferences the input? Not the first "use" — the first expression. logger.debug(`query "${query.substring(0, 50)}"`) dereferences it during template evaluation, before the logger, its level filter, or its transport ever run.
2. Is validation above that expression? If not, you have two behaviours: invalid-but-dereferenceable input (' ', 42, a 2MB string) gets logged and then rejected — or not rejected at all; non-dereferenceable input (null, undefined) crashes with an error that names your logger instead of your validator.
3. Does a test pin the ordering? instanceof MyValidationError assertions don't — they pass whether the guard sits above or below the log line, as long as something eventually throws. Ordering needs its own test, and that test has a trap (below).

Threshold worth remembering: nothing about the input may be assumed before the guard — including that it can survive a template literal.

The broken shape, condensed from real code:

// retrieval.ts — BROKEN: the log line is the crash site
async search(query: string, topK = 5) {
  this.logger.debug(`Searching "${query.substring(0, 50)}" topK=${topK}`) // ← throws on null
  if (!query || query.trim().length === 0) {
    throw new RAGError('INVALID_QUERY', 'query must be a non-empty string')
  }
  return this.retriever.search(query, topK)
}

search(null) never reaches the guard — the template literal throws TypeError: Cannot read properties of null (reading 'substring'). search(' ') sails past the dereference, gets logged, and is rejected one line later — the log now contains input the function itself considers invalid.

The fixed shape:

// retrieval.ts — guard first, then a capped preview
async search(query: string, topK = 5) {
  if (typeof query !== 'string' || query.trim().length === 0) {
    throw new RAGError('INVALID_QUERY', 'query must be a non-empty string')
  }
  this.logger.debug(`Searching "${preview(query)}" topK=${topK}`)
  return this.retriever.search(query, topK)
}

// One place decides what user input looks like in a log line:
// single line, bounded length, marked when truncated.
const preview = (s: string, n = 50) =>
  s.replace(/\s+/g, ' ').slice(0, n) + (s.length > n ? '…' : '')

Two things moved, not one: the guard went above the log line, and the raw input stopped being loggable at all — only preview() output is. That closes the ordering bug and the log-hygiene hole in the same edit.

Pipelines log at each layer (infer() logs, then delegates to search(), which logs again). Guarding only the inner function still lets the outer log line run on unvalidated input. Either guard at every public entry point, or make the outer layers pass through without touching the input — what you cannot have is a layer that logs above the layer that validates.

The headline case. The stack trace points at the logging line, so the natural diagnosis is "logger bug" — it isn't; the logger never ran. Any dereference inside the interpolation (.substring, .slice, .length, .toLowerCase) produces the same shape. undefined gives the twin: Cannot read properties of undefined.

The same bug in Python pipelines: logger.debug(f"query {query.strip()[:50]}") above the guard. Same fix, same ordering rule — f-string evaluation is a dereference.

The dangerous variant. ' ', '\n\n', or a pasted 500KB document all survive substring. They get logged raw, hit the embedder, cost real money, and return junk or a provider-side error later — attributed to retrieval, not to the missing guard. If your retrieval logs show quoted whitespace, the guard is below the log line or missing.

The natural test for "we no longer log before validating" is a logger spy plus null:

// VACUOUS: passes on the broken code too
it('does not log invalid queries', async () => {
  await expect(rag.search(null)).rejects.toThrow(RAGError)
  expect(logSpy.calls.length).toBe(0)   // also true when the template literal crashed!
})

On the broken code, search(null) throws inside the template literal before logger.debug executes — so calls.length === 0 holds there as well. The assertion guards nothing; the test only goes red via the rejects.toThrow(RAGError) half, which any guard position satisfies. (It fails for the wrong reason too — a TypeError, not your RAGError — which happens to fail the assertion, until someone "fixes" the test by loosening it to .rejects.toThrow().)

The input that actually pins the ordering is one that is invalid but dereferenceable:

// PINS THE ORDERING: '   ' survives substring, so broken code logs it
it('rejects whitespace queries without logging them', async () => {
  await expect(rag.search('   ')).rejects.toThrow(RAGError)
  expect(logSpy.calls.length).toBe(0)   // broken code: 1 (or 2, one per layer)
})

On the broken code this records one log call per layer that logs above its guard — the assertion fails, and the failure count even tells you how many layers are wrong. On the fixed code, zero. Keep the null case as a separate test for the guard itself; it just cannot carry the ordering assertion.

1. Stack trace names a logging line? The crash is in the interpolation, not the logger. Look one screen down for the guard that never ran.
2. Which inputs crash vs. slip through? null/undefined crash at the dereference; whitespace, numbers and oversized strings pass it. Two symptom classes, one cause.
3. Grep the logs for quoted whitespace or truncated garbage. Every hit is an unvalidated input that reached the log — an inventory of how long the ordering has been wrong.
4. More than one layer logging? Count log lines per bad request. Two lines means two layers log above their guard, and fixing the inner one only halves the problem.
5. Tests green the whole time? Check what input the ordering test uses. If it's null, it was vacuous (see above).

• Log-then-validate as a "debugging aid." The log line exists to see what came in — but below the guard it documents input your own function rejects, and above null it doesn't run at all. You get the worst of both.
• Preview logic inlined at each call site. Five hand-rolled substring(0, 50)s are five dereference points to keep in order. One preview() helper is one.
• Validation split across layers by convention ("the caller checks that"). Conventions don't survive new call sites. The function that logs the input owns the guard for it.
• Loosening a failing test to .rejects.toThrow(). That converts the one signal you had — wrong error type — into silence.
• Logging the full query "because we need it for support." Cap it and keep the full text where it belongs (the request store, the audit trail), not in every debug line. Logs are the widest-read, longest-retained copy of your users' input.

node --experimental-strip-types -e "
import('./retrieval.ts').then(async ({ RAG }) => {
  const calls = [];
  const rag = new RAG({ logger: { debug: (m) => calls.push(m) } });
  for (const input of [null, undefined, '   ', 42]) {
    const before = calls.length;
    const err = await rag.search(input).then(() => 'NO-THROW', e => e.constructor.name);
    console.log(JSON.stringify({ input: String(input), err, logged: calls.length - before }));
  }
})"

{"input":"null","err":"RAGError","logged":0}
{"input":"undefined","err":"RAGError","logged":0}
{"input":"   ","err":"RAGError","logged":0}
{"input":"42","err":"RAGError","logged":0}

Pass criteria: every line shows your typed error (never TypeError) and logged: 0. A TypeError means a dereference still sits above the guard; logged: 1 means a log line does.

import { z } from 'zod'

// The schema is the guard, the cap, and the documentation in one place.
export const Query = z
  .string({ invalid_type_error: 'query must be a string' })
  .trim()
  .min(1, 'query must be a non-empty string')
  .max(4096, 'query exceeds maximum length')   // also caps embed cost & log size upstream

async search(rawQuery: unknown, topK = 5) {
  const query = Query.parse(rawQuery)   // throws ZodError before anything touches input
  this.logger.debug(`Searching "${preview(query)}" topK=${topK}`)
  ...
}

The .max() is not decoration: it is the line that turns "someone pasted a book" from an embedding bill into a 400.

• Inputs produced by your own typed code paths, where the compiler already proves non-null and non-empty — the ordering rule still costs nothing, but the test scaffolding can stay home.
• Batch pipelines over trusted fixtures. This pattern earns its keep at boundaries where a human, an HTTP handler, or another model supplies the value.
• Languages/loggers with lazy structured logging (logger.debug("q=%s", query) deferred until the level is enabled) — the crash moves, but the log-hygiene half of the rule still applies unchanged.

This is Production AI Automation Notes #17. Related entries:

• #6: Prompt-injection defense — the same boundary, defending the prompt instead of the log
• #15: AI action audit trail — where full request text belongs instead of debug logs
• #16: Agent memory that degrades instead of failing — retrieval branch of the same RAG stack

Real-world fix: tetherto/qvac#3729 (merged 2026-08-21) — this exact ordering bug in a production RAG package, guard moved above the log lines in two services, pinned by a whitespace-input ordering test. Follow @renezander030 for new entries.

• tetherto/qvac #3729, fixing #3727 — the merged fix and the review thread where the vacuous-test trap surfaced
• CWE-117: Improper Output Neutralization for Logs — why raw user input in log files is its own vulnerability class
• OWASP, Log Injection — newline-smuggled fake log entries, the attack the preview() helper's \s+ collapse blocks

Comment with your version of this bug:

• The expression that crashed (template literal, f-string, + concatenation) and what the stack trace blamed
• Whether whitespace-only input reached your provider, and what it cost before you noticed
• Your ordering test's input — and whether it turned out to be vacuous

• Initial publication.
• Deliberate gate skips: hardware matrix (not hardware-bound), companion-repo creation (the reference fix lives upstream in qvac and is linked rather than scaffolded).