The Audit Trail Went Silent for Four Days and Nothing Alerted

TL;DR — A migration rewrote a stored procedure and added an idempotency guard to the top of it. The guard selected a column whose name matched one of the procedure’s own output parameters, which PL/pgSQL refuses to disambiguate — error 42702. Because the guard sat on the happy path, every real call failed from the moment the migration landed. Because the caller treated an audit-write failure as non-fatal, every order still succeeded. The audit trail wrote nothing for about four days and no alert fired, because nothing was watching for writes that stopped happening. The one-alias fix is the least interesting part of this.

Key takeaways

• RETURNS TABLE (...) implicitly declares output parameters. They collide with column names exactly like a DECLAREd variable would, and they are not in the DECLARE block you scan for collisions.
• A bug in an idempotency guard is a bug on the happy path. It fails every call, not the rare one — which should make it the loudest possible failure and instead made this one total.
• try { audit() } catch { log() } around an audit write is a defensible trade that converts a loud failure into a quiet one. Taking that trade without a monitor is half a decision.
• You cannot alert on an exception nobody raises. Alert on the invariant — state changes with no matching audit row — or on the absence of writes in a window where zero is never right.
• Fixing one instance of a name-shadowing bug and leaving the class alone gets you the same bug again, in the same function, from a later edit. It did here.

Three things had to be true

None of them was fatal alone.

  1. a guard on the happy path            every call fails, from the first one
                    │
  2. caller swallows audit failures       every order still succeeds
                    │
  3. nothing watches the audit table      nobody finds out for four days
                    ▼
        an audit trail with a hole in it and no record of why

The feature was a pre-paid corporate wallet: an employer funds a balance, and each subsidised order debits it. The first migration rewrote an existing stored function — the one that writes the per-order subsidy audit row — to strip out bookkeeping it should no longer own, and added an idempotency guard on the way in. That rewrite is where the bug went in.

The honest framing, before anything else: this module is on a staging branch, not carrying live traffic. The outage happened in the environment it runs in, against real rows, over roughly four days — the window is recorded in the fix migration because the backfill is written against it. I do not have a count of affected rows and I am not going to estimate one. What is fully transferable is the shape, because the swallowed-audit-write pattern in the middle of it is everywhere, including in code of mine that is in production.

What error 42702 actually is

PL/pgSQL substitutes its own variables into SQL statements before the statement is planned. When a name in a statement could refer to either a variable or a column of a table in that statement, it refuses to guess and raises ambiguous_column, SQLSTATE 42702. That behaviour is the factory default, and the alternatives are documented under variable substitution.

The trap is which names count as variables:

-- Illustrative. The audit row writer, reduced to the shape that matters.
CREATE OR REPLACE FUNCTION record_subsidy(p_order_id uuid, p_amount numeric)
RETURNS TABLE (audit_id uuid, ok boolean, error_code text)
LANGUAGE plpgsql AS $$
DECLARE
  v_existing uuid;
BEGIN
  -- BROKEN. `audit_id` is a column of order_audit *and* an output parameter
  -- declared by RETURNS TABLE above, so PL/pgSQL raises 42702 and never runs.
  SELECT audit_id INTO v_existing
    FROM order_audit
   WHERE order_id = p_order_id;

  IF v_existing IS NOT NULL THEN
    RETURN QUERY SELECT v_existing, true, NULL::text;   -- already recorded
    RETURN;
  END IF;
  -- … insert the audit row …
END $$;

Nothing in the DECLARE block collides with anything. That is the whole problem. The columns listed in RETURNS TABLE (...) are output parameters, and they are in scope for the entire body with the same precedence as a declared variable — but they are written where you read a signature, not where you read locals. Reviewing the DECLARE block for shadowing finds nothing wrong. An OUT parameter in the argument list behaves identically.

The fix is one alias:

  -- FIXED. Alias the table, qualify the column, and the name can only mean
  -- one thing. The INSERT further down the same function already did this.
  SELECT a.audit_id INTO v_existing
    FROM order_audit a
   WHERE a.order_id = p_order_id;

There are two other levers, and both are worse as a first resort. #variable_conflict use_column at the top of the body tells PL/pgSQL to resolve ambiguity in favour of the column, which fixes this statement and silently changes the meaning of every other ambiguous name in the function. Setting it globally does the same thing to every function in the database. Qualification is local, explicit, and cannot be undone by somebody editing a different line.

What I would actually adopt as a rule: prefix every local and every parameter, and never name an output parameter after a column. v_ for locals, p_ for inputs. It is a naming convention doing the work of a static check, which is not elegant, but the class of bug it removes is one that no amount of careful reading reliably catches.

Why it failed on every call, not one in a thousand

The broken statement was an idempotency guard: has this order already been recorded? It ran first, before the insert, on every invocation.

That inverts the usual arithmetic of a migration bug. Most defects introduced by a rewrite sit in a branch — the conflict path, the retry, the already-exists case — and they wait months for the input that reaches them. This one was on the path that every single call takes, so it failed 100% of the time starting with the first order after deploy.

Which should have been the best possible outcome. A defect that fails everything immediately is a defect you find in minutes, as long as anything downstream of it is willing to complain.

   bug in a rare branch    →  fails 1 call in 10,000  →  found in a month, by a user
   bug in a guard          →  fails 10,000 calls      →  found in four days, by me,
                                                          because nothing complained

Why nobody heard it

The caller, which the migration did not touch, and which is not unreasonable:

// Illustrative. The audit write must not fail the order — so it can't fail anything.
const { error } = await db.rpc('record_subsidy', { p_order_id: orderId, p_amount: subsidy });
if (error) {
  logger.error('subsidy audit write failed (non-fatal)', { orderId, code: error.code });
  // …and continue.
}

I still think the trade is right. An order that the customer has paid for, that the kitchen is already preparing, should not be rolled back because an audit insert failed. Refusing to complete a paid order because a reporting row would not write is a worse outcome than the missing row.

But look at what the trade actually purchased and what it cost:

The third row is the one I would build now, and it is the same transactional outbox I have written about for delivering events — an audit row is just an event whose consumer is a table. The audit write becomes an insert into a queue in the same transaction as the status change, which cannot half-happen, and the actual formatting and enrichment moves to a worker whose failures are visible because a queue with a growing backlog is something you can see.

Same-call is not same-transaction. I wrote almost exactly that sentence in the three-party workflow piece about a different audit write, in a different module, and then noted that I had carried the pattern forward from an earlier feature where the trail went quiet. This is that earlier feature. I understood the trade well enough to describe it in public and still had not closed it.

You cannot alert on an exception nobody raises

This is the part that generalises, and the part I have not finished.

The error was in the logs the whole time, at error level, with a message containing the words “audit” and “failed”. Nothing consumed it. There was no alert on the log line, and more importantly there was no alert on the outcome — the audit table simply stopped growing, which is the one signal that was unambiguous and the one nobody had asked a question about.

Three mechanisms, cheapest first.

1. Alert on the swallowed log line. If you deliberately swallow an error, the swallow is the exact place where an alert belongs, because that is the last point at which the failure still exists as information. One rule matching the log message you already write costs nothing and would have paged in minutes here. Do this one first, always.

2. Assert the invariant on a schedule. The claim “every subsidised order has an audit row” is checkable in one query:

-- Illustrative. Orders that should have an audit row and don't. The two-minute
-- lag excludes in-flight writes, so a busy moment doesn't page anybody.
SELECT count(*) AS missing
  FROM orders o
  LEFT JOIN order_audit a ON a.order_id = o.id
 WHERE o.subsidy_amount > 0
   AND o.created_at < now() - interval '2 minutes'
   AND o.created_at > now() - interval '1 hour'
   AND a.order_id IS NULL;

Run it every few minutes, alert on non-zero. This is the same reconciliation sweep I use against a payment gateway, pointed inward at my own database instead of outward at somebody else’s: two things that should agree, a scheduled question about whether they do, and an alarm on the delta. The sweep is also the backfill — the query that finds the gap is the query that tells you what to repair.

3. Alert on absence. A counter of audit rows written, and a rule that fires when it stops moving during a window in which zero is never legitimate. Prometheus has absent_over_time for exactly this, and the Google SRE book’s chapter on monitoring distributed systems is where the reasoning is laid out properly. The catch is that you have to know your own quiet hours: a food platform legitimately writes nothing at 4am, so a naive deadman on this table pages the on-call every night until they mute it, and a muted alert is worse than no alert because it looks like coverage.

Two of these three watch the effect rather than the code, which is why they would have caught a bug that no test covered. I had none of them.

The same defect, twice, in the same function

The part that stings. This exact ambiguity had been fixed once before in this same function, on a different statement, by an earlier migration. A later edit — mine — reintroduced it a few lines away.

That is the difference between fixing an instance and fixing a class. The earlier fix qualified one column and moved on. It did not rename the locals, did not add #variable_conflict, did not leave a comment saying this function has output parameters that collide with its own table’s column names, qualify everything. So the function stayed exactly as easy to break as it had been, and the next person to touch it broke it the same way. The next person was me, four months later, with no memory of the first fix.

Two things came out of that:

1. The fix migration carries a comment saying this is the second occurrence, naming the pattern rather than the line. A comment that describes the class is a cheap static check with a human as the runtime.
2. It is the argument for a smoke test that actually calls the procedure. The offline suite for this module covers arithmetic and validators and never touches a database, so a procedure that raises on its first statement passes every test. One test that calls the function once, against a scratch database, in CI, would have failed on the migration that introduced this. That is what I did on the module I built afterwards, and the reason I did it is this bug.

Backfilling what you can reconstruct

The audit rows were recoverable, and that was luck rather than design. Everything the missing rows needed — the order, the amount, the program, the timestamp — was still sitting in the order table, so the backfill was a single insert-select over the outage window, guarded by the same idempotency check that had been broken in the first place.

Worth being precise about what that restores. The rows now exist and the reports reconcile. What does not exist is the record of the write having happened when it happened: every backfilled row was created days after the event it describes, and anyone reading the trail closely can see it. For a financial audit trail that distinction can matter, which is the argument for a recorded_at alongside occurred_at rather than one timestamp doing both jobs.

And the general case is worse. An audit trail is reconstructable only to the extent that its content is derivable from state that survived. Amounts and references usually survive. Intermediate states do not — if a record moved from A to B to C and only C survives, the B is gone. Neither does anything about the actor: which admin clicked, from which session, after seeing which screen. Those are observations, not derivations, and a gap in them is permanent. Which means the value of an audit trail is inversely proportional to how reconstructable it is, and the trails most worth monitoring are the ones you could never rebuild.

What I got wrong beyond the bug

I rewrote a shared stored function with no test that called it. The signature was kept identical on purpose, precisely so existing callers would keep working — a good decision that also meant nothing in the deploy exercised the new body. Signature compatibility is not behaviour compatibility, and the confidence the unchanged signature gave me was the confidence that stopped me writing the one-line smoke test.

I treated an earlier fix as done rather than as evidence. A defect that has appeared once in a function is a fact about that function, not about that line. I had the evidence in the migration history and did not go looking for it.

The monitor still is not built. The alias is fixed, the backfill ran, the comment is in the file. The thing that would have turned four days into four minutes is on a list, which is where it was before this happened. I would rather say that plainly than let the write-up imply an incident review that ended in a dashboard.

FAQ

What causes Postgres error 42702? A name in a SQL statement inside a PL/pgSQL function that could refer to either a variable or a column of a table in that statement. PostgreSQL refuses to guess and raises ambiguous_column. The usual cause is a declared variable, an OUT parameter, or a column listed in RETURNS TABLE sharing a name with a real column.

Do RETURNS TABLE columns really shadow column names? Yes. They are implicitly declared output parameters, in scope for the whole function body, with the same precedence as a variable you declared yourself. They are easy to miss because you read them as part of the signature rather than as locals.

How should I fix an ambiguous column reference in PL/pgSQL? Alias the table and qualify the column — SELECT a.audit_id FROM order_audit a — so the name can only mean one thing. Prefer that over #variable_conflict use_column, which resolves every ambiguity in the function in one direction and will eventually pick the wrong one for some statement you did not have in mind.

Should an audit write be allowed to fail the operation it records? Usually not, and that is exactly why it needs a monitor. A best-effort audit write keeps a reporting failure from rejecting a paid order, at the price of making the failure invisible. Writing the audit row to an outbox inside the same transaction gets you both: the row commits atomically and the slow work happens afterwards.

How do you monitor something that stopped happening? Watch the effect rather than the code. Alert on the log line at the point where you swallow the error; run a scheduled query for state changes with no matching audit row; and count audit writes so an alert can fire when the count stops moving during hours when zero is never correct. The middle one is the most robust because it checks the invariant itself.

Why did the bug affect every call instead of a few? Because it was in an idempotency guard, which runs on every invocation before the real work. A defect in a rare branch fails rarely. A defect in a guard fails universally and immediately, which makes it trivially findable — provided something downstream is willing to report it.

Can a missing audit trail be backfilled? Only the part that is derivable from state that survived. Amounts, references and timestamps of the underlying records usually are. Intermediate states, actor identity and anything about the session are observations that no longer exist anywhere, so those gaps are permanent. Keep recorded_at separate from occurred_at so a backfilled row is honest about what it is.

What is the cheapest thing that would have caught this? An alert on the error log line that the caller already wrote. It costs one rule, needs no new instrumentation, and fires within minutes. The invariant sweep is more robust and catches failure modes that never log anything, but if you are only going to do one thing, alert where you swallow.

What I’d still improve

• Build the invariant sweep, on a schedule, alerting on non-zero — and reuse it as the backfill query, so the thing that detects the gap is the thing that repairs it.
• Alert on the swallowed log line today, as the ten-minute version of the above.
• Move the audit write into an outbox row committed with the state change, so the invariant stops depending on a best-effort call succeeding at all.
• One smoke test per stored procedure, against a scratch database in CI. Not a property test of the concurrency guarantees, which is a bigger job — just proof that the function runs.
• Rename every local and parameter with a prefix in the procedures that have output parameters, so the collision this post is about becomes unrepresentable rather than avoided by care.

The one idea to take away

If you decide a write is allowed to fail quietly, you have just taken responsibility for noticing when it does.

The trade itself is fine — audit and reporting machinery should not be able to reject work a customer has paid for. What is not fine is taking the trade and then monitoring the same things you monitored before, all of which watch for errors that something is now catching on your behalf. Every catch that logs and continues is a small hole cut in your error reporting, and the only thing that covers it is a question asked on a schedule about whether the write actually happened. Ask it about your audit tables first. They are the ones nobody notices are empty.

---

I write about backend reliability, Postgres data modelling and production failure modes from work on food-tech and healthcare platforms. More on what I build and how I work, the hospital meal system whose backend I own, and the companion piece on why same-call is not same-transaction. If you have an audit trail nobody is watching, that is the cheapest alert you will add this quarter.