DEV Community

Remdore
Remdore

Posted on AI-assisted

Your audit log is probably lying to you. Postgres 18 fixes it in one statement.

Concurrently logged ghosts hide lost transactions

I've written this more times than I'd like, in four or five languages by now:

SELECT balance FROM accounts WHERE id = 1;
-- application does the arithmetic
UPDATE accounts SET balance = $new WHERE id = 1;
INSERT INTO audit_log (account_id, old_balance, new_balance) VALUES (1, $old, $new);
Enter fullscreen mode Exit fullscreen mode

Read it, do the sum, write it back. Log what happened. Nothing about that raises an eyebrow in review, and it falls apart the second two people hit it together. The annoying part is that the audit log, which you added to catch this sort of thing, is what buries it.

Postgres 18 turns the whole thing into one statement. Before that, though, the bug is worth a proper look, because it did more damage than I expected when I finally ran it.

Reproducing it

One account starting at 100. Ten workers, each taking out 10. What should happen is obvious enough: you end on zero, and the audit log walks down in steps, 100 to 90, then 90 to 80, and so on.

Each worker does the read-then-write thing from above. I put a 50 ms gap in the middle so the timing lands the same way every run:

final balance                      | 90
audit rows                         | 10
distinct old_balance values logged | 1
Enter fullscreen mode Exit fullscreen mode
 old_balance | new_balance | times_logged
-------------+-------------+--------------
         100 |          90 |           10
Enter fullscreen mode Exit fullscreen mode

Ninety. Nine withdrawals gone. All ten workers read the same 100, wrote back the same 90, and each one logged itself as the one that did it.

That last part is the bit I'd want someone to notice. It isn't only that money went missing. The audit log agrees with itself. Ten neat rows, every one internally consistent, no gaps, no nulls, nothing a validator would flag. Hand me that table during an incident and I'd conclude the same withdrawal got retried ten times, then go and read the retry logic, which is fine.

Take the sleep out and it stops being deterministic. It doesn't stop happening. Three runs back to back:

final balance 50, distinct old values logged 5
final balance 40, distinct old values logged 6
final balance 60, distinct old values logged 4
Enter fullscreen mode Exit fullscreen mode

Between 4 and 6 writes lost out of 10, on this machine, with nothing slowing anything down. You don't need a debugger and a following wind to hit that. It's roughly a coin flip.

The one-statement version

Postgres 18 lets you name the row before and after the change directly in RETURNING:

UPDATE accounts SET balance = balance - 10 WHERE id = 1
RETURNING old.balance AS was, new.balance AS now;
Enter fullscreen mode Exit fullscreen mode
 was | now
-----+-----
 100 |  90
Enter fullscreen mode Exit fullscreen mode

There are two changes in there, and the interesting one isn't the new syntax.

Doing balance - 10 inside the statement means the read and the write happen together, so there's no gap for anyone to slip into. That has been possible forever, and it's the bit that stops the lost update.

What Postgres 18 adds is that you also get told what the value was, from the same statement that replaced it. Not what it was when you last looked. The value this particular UPDATE actually overwrote. So the audit row can be written from the same operation:

WITH moved AS (
  UPDATE accounts SET balance = balance - 10 WHERE id = 1
  RETURNING old.balance AS was, new.balance AS now
)
INSERT INTO audit_log (account_id, old_balance, new_balance)
SELECT 1, was, now FROM moved;
Enter fullscreen mode Exit fullscreen mode

Same ten concurrent workers:

final balance                      | 0
audit rows                         | 10
distinct old_balance values logged | 10
Enter fullscreen mode Exit fullscreen mode
 old_balance | new_balance
-------------+-------------
         100 |          90
          90 |          80
          80 |          70
          70 |          60
          60 |          50
          50 |          40
          40 |          30
          30 |          20
          20 |          10
          10 |           0
Enter fullscreen mode Exit fullscreen mode

Zero, and the staircase survived. Ten workers went at it simultaneously and the log still came out in order, because every row was written by the statement doing the work instead of by an application repeating what it had been told a moment earlier.

Before 18 you could get this, but you needed a trigger with OLD and NEW, which means the audit logic lives somewhere a reader of the application code will never look.

The bit that will save you the most time

RETURNING old gives you something else for free. On an INSERT there is no old row, so old is null. Which means an upsert can finally tell you which branch it took:

INSERT INTO accounts VALUES (3, 10)
ON CONFLICT (id) DO UPDATE SET balance = EXCLUDED.balance
RETURNING old.id IS NULL AS was_inserted, old.balance, new.balance;
Enter fullscreen mode Exit fullscreen mode

First run, no existing row:

 was_inserted | balance | balance
--------------+---------+---------
 t            |         |      10
Enter fullscreen mode Exit fullscreen mode

Run it again against the row that now exists:

 was_inserted | balance | balance
--------------+---------+---------
 f            |      10 |      20
Enter fullscreen mode Exit fullscreen mode

If you have written Postgres for a while you will recognise what this replaces. The old trick was:

RETURNING (xmax::text::bigint <> 0) AS was_update
Enter fullscreen mode Exit fullscreen mode

Reading a system column, casting it to text, casting that to a bigint, and comparing it to zero, to find out whether your own statement inserted or updated. It works, and it's all over older codebases. It also requires you to know what xmax is, and to anyone who doesn't, it looks like a bug.

old.id IS NULL doesn't need a footnote.

Three things I got wrong on the first pass

On INSERT everything under old is null, and on DELETE everything under
new is null.
Obvious once you say it out loud, easy to miss when you've written one audit helper and pointed every statement at it. Log old.balance from an INSERT and you get a null, silently, forever.

I assumed a table with a column named old would break. It does not.
Bare old still resolves to your column, so existing queries keep working:

UPDATE legacy SET old = 'CHANGED2' WHERE id = 1 RETURNING old;
-- returns CHANGED2, the column, not the pre-update row
Enter fullscreen mode Exit fullscreen mode

The old. and new. prefixes are what activate the aliases. If you need both in one statement, rename them:

RETURNING WITH (OLD AS prev, NEW AS cur) prev.old, cur.old
Enter fullscreen mode Exit fullscreen mode

It is 18 only. On 17 you get an error that does not obviously point at
a version problem:

ERROR:  missing FROM-clause entry for table "old"
Enter fullscreen mode Exit fullscreen mode

I ran that against postgres:17 to check, and if you land here from searching that string, this is your answer.

Run it yourself

Everything above came from postgres:18 in Docker, version 18.6, on a laptop. No cloud account, nothing to sign up for:

docker run -d --name pg18 -e POSTGRES_PASSWORD=demo -e POSTGRES_DB=demo postgres:18
docker exec -it pg18 psql -U postgres -d demo
Enter fullscreen mode Exit fullscreen mode
CREATE TABLE accounts (id int PRIMARY KEY, balance numeric NOT NULL);
INSERT INTO accounts VALUES (1, 100);

UPDATE accounts SET balance = balance - 10 WHERE id = 1
RETURNING old.balance AS was, new.balance AS now;
Enter fullscreen mode Exit fullscreen mode

Your concurrency numbers won't match mine, which is rather the point of a race. Run the naive version a few times and watch the final balance land somewhere different each go.

What I would take from this

The feature itself is small. One line describes it: RETURNING now understands old and new.

What made it worth an evening was what it exposed on the way. I've written the read-then-write pattern for years, and I've added audit tables to catch exactly the class of problem that pattern creates, without ever noticing that the audit table inherits the same race and so can't see it. Ten rows, perfectly consistent, all wrong.

If you have that pattern in a codebase somewhere, the arithmetic-in-SQL half is the urgent fix and it works on any version. The old/new half is what lets you delete the trigger you wrote to work around not having it.

Top comments (6)

Collapse
 
vinhnguyenthanhdn profile image
Vinh Nguyen

The balance = balance - 10 half is doing more isolation-level-specific work than the post gives it credit for, and the direction is the counterintuitive part. Under READ COMMITTED that statement is safe because when it meets a row another transaction is updating, it blocks, and once that transaction commits it re-reads the row and re-evaluates the expression against the new value. That re-read is the entire reason balance - 10 composes while read-then-write does not. Under REPEATABLE READ or SERIALIZABLE there is no re-read: the same statement aborts with 40001, could not serialize access due to concurrent update.

That matters more than usual here because of the CTE. Folding the audit INSERT into the same statement makes the audit row atomic with the balance change, which is exactly the property you want, but it also means an abort takes the audit row with it. So the ten-worker run at REPEATABLE READ gives you a correct final balance and fewer than ten audit rows, which on inspection reads like the audit log dropping writes rather than like transactions retrying. Whichever retry loop wraps this is now load-bearing for audit completeness and not only for the money.

Declaring the boundary on that: it is read out of the concurrency docs rather than run. I do not have 18 here, so I have reproduced neither your staircase nor the abort.

Collapse
 
remdore profile image
Remdore

You've read it right, and I've now run it, so here are the numbers. Same ten workers, same CTE, each one takes its snapshot before a short sleep so they all overlap:

READ COMMITTED    balance 0    10 audit rows   0 errors
REPEATABLE READ   balance 90    1 audit row    9 x 40001
SERIALIZABLE      balance 90    1 audit row    9 x 40001
Enter fullscreen mode Exit fullscreen mode

One worker wins, nine abort, and the abort takes the audit row with it, exactly as you said.

The one I hadn't expected is the autocommit case. No BEGIN anywhere, just default_transaction_isolation set to repeatable read, and the bare statement still fails for six of the ten. Final balance 60, four audit rows. That's the version that would catch someone, because nothing in the code looks like a transaction.

With a retry loop around it the balance comes back to 0 and all ten rows land, though it took 45 aborts to get there, because every retry collides with the other retries and each round only lets one through.

Your last paragraph is the one I'd underline. Under repeatable read the audit log is only as complete as the retry loop, and a log with four rows and a balance of 60 is internally consistent again. Different bug, same shape.

Postgres 18.6, standalone binary rather than Docker this time, ten threads through psycopg.

Collapse
 
yune120 profile image
Yunetzi

Sure, one-line fix is neat, but the twist isn't 'the log lies'β€”it's 'we trust logs more than the reality they recorded.' Maybe Postgres 18 teaches us to read logs critically, not worship the one-liner.

Collapse
 
remdore profile image
Remdore

I'd go one further. There was nothing in that log to read critically. Ten rows, all consistent, no contradiction for a sceptical reader to catch. The only way to see it was to put the log next to the balance and notice they told different stories.

That's the bit I'd want people to take away. A log the application writes after the fact can't be checked against itself. It has to be checked against the thing it claims to describe.

Collapse
 
mickyarun profile image
arun rajkumar

The line worth pulling out is that all ten rows are internally consistent. That is what lets it survive review. Nobody reading the log finds a contradiction, because there isn't one. It is a faithful record of ten processes that each believed they were alone.

We are in regulated payments, so the audit trail isn't a debugging aid, it's the artefact somebody else reads to decide whether we did the right thing. The rule we landed on: the row recording the change and the change itself have to be the same statement. Anything where the application writes the log afterwards is a log about the application's intent, not about what the database did.

Collapse
 
remdore profile image
Remdore

That rule is the whole post in one line, and it's a better line than mine.

One thing I'd add for your setting. The CTE version depends on every code path remembering to write the audit row. A trigger with OLD and NEW can't be forgotten. So I'd be wary of ripping a trigger out of a payments system just because 18 makes the application-side version prettier. Where the trigger loses is that a reader of the application code never sees it, and for a debugging aid that's a fair trade. For something a regulator reads, I'd probably keep the trigger and let RETURNING old sit alongside it, so the application can still see what it overwrote without being the thing that records it.

Which way did you go?