The pooler that turned my writes read-only
Half my writes failed with a read-only error, on a database that was never read-only.
By Andrew Pyle
It took two and a half weeks and a withdrawn theory to stop a setting I never wrote from breaking my writes.
01The error
Cannot execute SELECT FOR UPDATE
cannot execute SELECT FOR UPDATE in a read-only transaction. That was the line in the log on September 27, and it reached the outside as a 500 from the API that creates and updates my tasks. While it was happening, a live update failed eight times out of eight. Then the flare cleared, and the same update succeeded on the first try.
django.db.utils.InternalError: cannot execute SELECT FOR UPDATE in a read-only transactionThe failing statement was in the step that hands out the next task number. It opens a transaction, locks the counter row with select_for_update, and increments it. The lock is the first thing it does, so it was the first thing to fail. Other writes did better by luck. Creating a record with no counter sometimes slipped through, and one had succeeded earlier in the same session. My estimate of the blast radius was all writes, with about half of them or more at risk. Reads worked the whole time.
The database was the primary: pg_is_in_recovery was false, the database default for read-only transactions was off, and it was not in the read-only mode a full disk can force. Something was making my transactions read-only while the database itself was fine.
02Why the checks lied
Half the backends were poisoned
My app sits behind a connection pooler in transaction mode. Every transaction borrows a backend connection from the pool, and I do not choose which one. To see what I was getting, I looped twelve transactions, each running SHOW transaction_read_only. Six came back read-only. Six came back read-write.
-- run inside each of twelve transactions, one after another
SHOW transaction_read_only;
-- 6 came back on, 6 came back offThat split explained why every quick check gave me a false all-clear. Outside a transaction, the connection reports read-only as off. The next transaction can then begin on a different pooled backend that is read-only. A direct save from a shell runs in autocommit, can land on a clean backend, and works. The write works once, so it looks fixed. To reproduce the failure I had to send a request through the real API view, the path the web traffic takes.
03The wrong theory
I blamed a read-only role first
My first explanation was a read-only database role, one with read-only set as its default, leaking in from replica activity. It seemed to fit the numbers. With no replicas and none of those connections active, the pool sampled zero percent read-only. During a flare it sampled somewhere between fifty and a hundred percent.
On October 13 I withdrew it. The pooler pools per user. A backend poisoned for my database user had to be poisoned by a client logged in as that same user, so a different role could not be the source. I ruled out two other suspects because they talk to different databases. What would fit is one of my own clients opening a session with readonly set, which in psycopg2 sends a session-level SET default_transaction_read_only TO on. That is an example of the shape I am looking for. I have not caught it happening.
04Guard one, then all
The first guard covered a few doors
Guarding the call sites
The first guard shipped the day the error appeared. A helper issues SET LOCAL transaction_read_only = off as the first statement of a write transaction, and I applied it to the task and ticket number allocators and to the task API's create, update and delete paths. On the real database, a simulated poisoned transaction failed on select_for_update, and the same transaction with the guard succeeded. The next day I added an hourly probe that samples fresh transactions and raises an alert at fifteen percent read-only or more. It pings an outside dead-man check on every run, so the alarm never shares a queue with what it watches. Its first reading was zero of sixteen.
The guard worked where I put it, and only there. In the seven days to October 13, my run log held fifty background job failures with the same read-only error, spread across a handful of scheduled jobs the guard never touched. The flares came on October 9, October 10, and twice on October 13, once from 11 PM to midnight CDT and again from 8 to 9 AM CDT. The probe had run 353 times and had four flare alerts open.
Guarding the engine
So the second fix went into the database engine instead of the call sites. It is a thin subclass of Django's PostgreSQL wrapper. When a connection leaves autocommit, it sets the psycopg2 connection's readonly to False, which goes out as BEGIN READ WRITE on the next statement. When it returns to autocommit, it resets readonly to None, so it never sends a session-level SET of its own.
# when a connection leaves autocommit
connection.readonly = False # goes out as BEGIN READ WRITE
# when it returns to autocommit
connection.readonly = None # never a session-level SETWrites outside a transaction, such as a plain save or a queryset update, have no BEGIN to amend, so an outer execute wrapper runs an autocommit INSERT, UPDATE, DELETE or MERGE inside a one-statement atomic block. Reads and DDL are left alone, because some DDL must not run in a transaction. The cost is one extra round trip per autocommit write. On the primary it is always safe, and on a real replica the write would have failed anyway.
05Still open
I fixed the symptom and kept the alarm
The engine fix had a side effect. With it in place, SHOW transaction_read_only always reads off, which would have blinded the probe. So the probe now reads default_transaction_read_only instead, and when it finds poisoned backends it records up to five of them with the setting's source, the process id, and when each backend started. A source of session would mean a client ran a session SET. That is the clue I am waiting for.
I tested it with 23 unit tests and four proofs against a local Postgres session I poisoned on purpose. Create, save, update, a locked update, bulk create and delete all succeeded while the session stayed poisoned. The stock engine failed the same create with cannot execute INSERT in a read-only transaction. Removing the readonly line fails four tests, and removing the wrapper fails two. When I wrote the fix the pool was clean, forty of forty read-write, so I could not watch it work against a live flare. The first flare after the deploy is the real test.
My own plan for this fix wrote down its main risk in two sentences, before any of it shipped.
It hides the symptom; the leaking client still exists. The probe keeps alerting, because it samples raw backends.
Both sentences still hold. My writes are protected, and the probe will keep alerting until I find the client that sets the flag. A shared connection carries state from whoever held it last, and one clean write only tells me which backend I drew.
Related
writing
A limit that was never enforced
Eighty of my scheduled tasks ran on a time limit different from the one they declared, because the loader quietly threw it away, and the first plan I built on those numbers was wrong.
writing
A deploy should drain, not kill
A routine deploy quietly ate a day of work, and the monitor that was supposed to notice reported nothing wrong.
writing
A cold cache is not free
My feature-flags page felt instant once I cached it, and the first request to each fresh worker after a deploy still paid about fifteen seconds.
writing
A 200 is not the same as access
My leak probe failed with seventeen leaks on its first real run. Every one of them was the same page that was never a leak.
writing
The list that shipped the whole record
A decisions list took almost eight seconds to show 117 rows, because it was sending the entire record for a view that only renders a line.