DEV Community: bitpage

Gmail bounced everything the relay sent: three broken auth mechanisms and a silent OpenDKIM

bitpage — Sun, 06 Sep 2026 05:11:15 +0000

Short answer: Three independent mechanisms were broken at once, and fixing any one of them changed nothing visible. The domain had no v=spf1 record (only a dead SenderID one), the PTR resolved forward to a different server, and OpenDKIM was signing nothing because KeyTable and SigningTable were attached as refile: while their contents were in plain two-column format. That last one cost the most time: when OpenDKIM can't find a key it logs absolutely nothing, so the daemon reads active, the config parses, the key is readable, and mail still leaves unsigned.

The server is an outgoing relay for transactional mail from a couple of dozen application hosts: password resets, notifications, alerts. Inbound mail for the domain goes elsewhere, to Google Workspace as MX. Postfix on a legacy container with more than two years of uptime, OpenDKIM 2.10.3, no Ansible, edits by hand only. The daily log summary read a four-digit bounced against a single-digit sent: thousands of rejections, a handful of deliveries. Password reset mail was among the casualties, so people could not get back into their accounts. Nobody had changed anything on this box in years, which turned out to be the whole story.

TL;DR

Root cause (DKIM): KeyTable/SigningTable mounted as refile: while the entries were plain example.org mail._domainkey.example.org lines. Under refile: the key is a regex matched against the whole From: address, so example.org never matches noreply@example.org. Changing one word per line to file: fixed it.
Also broken: InternalHosts listed fewer than ten addresses against a Postfix mynetworks two to three times longer. Mail from the app hosts was being verified instead of signed.
Also broken: the only SPF-shaped TXT record was spf2.0/mfrom,pra SenderID. RFC 7208 discards anything that doesn't begin with v=spf1, so the domain effectively had no SPF record.
Also broken: the PTR pointed at a hostname whose A record led to a different machine. Forward-confirmed reverse DNS failed.
Trap: grep -c DKIM-Signature /var/log/mail.log returns 0 whether signing works or not. Postfix does not write message headers to the log.
Trap: testing with sendmail from the mail server itself passes, because 127.0.0.1 was in InternalHosts. Real traffic from other hosts kept going out bare.

Why a server nobody touched stopped being deliverable

The requirements moved while the configuration stood still. Gmail began requiring authentication from bulk senders in February 2024 and has been ramping enforcement since, and a config that predated those rules simply stopped qualifying (Email sender guidelines). There was no change window to roll back to, no deploy to blame. The rejection came back verbatim as:

550-5.7.26 Your email has been blocked because the sender is unauthenticated.
550-5.7.26 Gmail requires all senders to authenticate with either SPF or DKIM.
550-5.7.26  Authentication results:
550-5.7.26  DKIM = did not pass
550-5.7.26  SPF [example.org] with ip: [203.0.113.51] = did not pass

Both named mechanisms failing at once should have been the tell that this was not one bug. I read it as one bug anyway and spent the next hour paying for it.

Three of the four facts in my own notes were wrong

I started from a ticket written a day earlier that already contained a diagnosis, and rechecking it by hand killed three of its four claims. The notes said: PTR is fine and forward and reverse match; DNS is hosted on Cloudflare; DMARC is absent.

The PTR pointed at legacy.example.org, whose A record led to 198.51.100.216, a different server entirely. dig NS returned ns-*.awsdns-*, so DNS was on Route 53, not Cloudflare. DMARC was present and had been all along, v=DMARC1; p=none. One claim out of four survived. These were my own notes, from the previous day.

The other rejection message had been telling me about the PTR the whole time:

550-5.7.25 [203.0.113.51] The IP address sending this message does not have a PTR
550-5.7.25 record setup, or the corresponding forward DNS entry does not match the sending IP

The operative half is the second clause. Not "you have no PTR record" but "the forward entry doesn't match". I had read to the first familiar phrase, seen a PTR existed, and moved on. RFC 1912 §2.1 states the rule plainly: "Make sure your PTR and A records match. For every IP address, there should be a matching PTR record in the in-addr.arpa domain" (RFC 1912). The same section warns that getting this wrong "can cause loss of Internet services similar to not being registered in the DNS at all", which is a fair description of a bounce column four digits wide.

The fix had two possible shapes. Editing the A record of legacy.example.org to point here would have satisfied the check, but that hostname is live and fronts an unrelated service, so the blast radius covered somebody else's system. Repointing the PTR to mail.example.org, whose A record already resolved to the sending IP, changed nothing outside this server. I also set Postfix myhostname to mail.example.org so the HELO name matches the PTR.

Why the SPF record that existed didn't count

There was a TXT record on the domain, and it was worth exactly nothing, because it was a SenderID record rather than an SPF one. It began spf2.0/mfrom,pra. RFC 7208 §4.5 is unambiguous about what a verifier does with that: "Starting with the set of records that were returned by the lookup, discard records that do not begin with a version section of exactly 'v=spf1'" (RFC 7208).

Discarded means the domain had no SPF record at all as far as Gmail was concerned, which is precisely what SPF [example.org] ... = did not pass was reporting. A record that looks like SPF to a human and is invisible to every verifier is worse than an empty zone, because it stops anyone from looking further. Published in its place:

v=spf1 ip4:203.0.113.51 include:_spf.google.com include:spf.example.net ~all

Why grepping the mail log for DKIM-Signature proves nothing

Postfix does not write message headers to its log, so the count is zero whether signing works or not. My first check was grep -c "DKIM-Signature" /var/log/mail.log, which returned 0, and I took that as evidence that nothing was being signed. It wasn't evidence of anything. The method cannot distinguish a broken signer from a working one, and I used it as the basis for the next hour of work.

The check that does work is to send a message to a local mailbox and read the headers of the delivered file, /var/mail/nobody. That shows the actual DKIM-Signature header or its absence, with no inference in between. Building that first would have made every subsequent change a one-minute yes or no. I built it fourth.

OpenDKIM reports active, parses clean, and signs nothing

OpenDKIM writes no log line when it fails to find a signing key for a message, so systemctl is-active returning active alongside a clean startup is zero evidence that signing happens. I found and fixed two genuine defects on the strength of that assumption, and neither produced a signature.

The first was the config itself. /etc/opendkim.conf had been truncated to four lines, with no Mode, no KeyTable, no SigningTable. The fingerprints of a package upgrade were right there: /etc/opendkim/ had been touched recently while the files inside it were years older. I restored the missing directives and restarted. Clean start, no errors, no signature.

The second was key ownership. The private key belonged to _apt:uuidd with mode 0600, and the daemon runs as opendkim. Checking as the service user rather than as root is the only way to see this:

su -s /bin/sh opendkim -c "head -c 20 /etc/opendkim/default/mail.private"
head: cannot open '/etc/opendkim/default/mail.private' for reading: Permission denied

A real defect, and chown opendkim:opendkim is mandatory. The key became readable. Still no signature. Two genuine bugs repaired, both necessary, neither sufficient, and my supply of hypotheses was gone.

The actual root cause was one word, and it was in the man page

The tables were attached as refile: while their contents were in plain two-column format, and under refile: the lookup key is treated as a regex matched against the entire From: address. I stopped guessing and opened man opendkim.conf on the server itself, same 2.10.3 as the running binary, which is more authoritative than whatever version the web is serving. The answer sits in one paragraph about dataset types:

"If this table specifies a regular expression file ("refile"), then the keys are wildcard patterns that are matched against the address found in the From: header field. For all other database types, the full user@host is checked first, then simply host, then user@.domain (with all superdomains checked in sequence…)"

The tables held lines like this:

example.org  mail._domainkey.example.org

Under refile:, the pattern example.org is matched against noreply@example.org and does not match, so no key is found and the message leaves unsigned without a single log line. Under file:, the lookup falls through to the second step, "then simply host", where example.org matches exactly. The fix was one word in two lines:

-KeyTable                refile:/etc/opendkim/KeyTable
-SigningTable            refile:/etc/opendkim/SigningTable
+KeyTable                file:/etc/opendkim/KeyTable
+SigningTable            file:/etc/opendkim/SigningTable

The other direction works too: rewrite every table entry to *@example.org and keep refile:. I rejected it because the tables covered several domains, and rewriting every line of data is a wider edit than changing the dataset type to the one that already matches the format on disk.

The second half of the same bug: InternalHosts was a fraction of mynetworks

OpenDKIM only signs mail arriving from hosts in InternalHosts; everything else it verifies instead, so any app server missing from that list was sending bare mail by design. The man page states the whole behaviour in one line, describing the option as identifying "a set internal hosts whose mail should be signed rather than verified" (typo included, as printed in 2.10.3).

InternalHosts pointed at TrustedHosts, which listed fewer than ten addresses. Postfix mynetworks listed two to three times as many. Syncing the short list against the long one tripled it, finally covering the application hosts that had been relaying through a server which was, on paper, configured to sign their mail. The two files are not required to match exactly, since they answer different questions, but a host that can relay and cannot be signed is almost always an oversight rather than a decision.

This is also why my manual test had lied to me earlier. Mail sent with sendmail from the relay itself originates from 127.0.0.1, which was in the list, so a signature appeared and I briefly thought the job was done. The traffic that actually mattered came from the application hosts, none of them in the file. Test along the path production traffic takes, not the path that is convenient from an SSH session.

The four defects and the check that actually proves each one

Broken	Symptom you see	Check that settles it
No `v=spf1` record, SenderID only	`SPF … = did not pass`	`dig +short TXT example.org` — the string must begin `v=spf1`
PTR forward mismatch	`550-5.7.25 … forward DNS entry does not match`	`dig -x <ip>`, then resolve that name's A record back — it must return `<ip>`
`refile:` on plain-format tables	Nothing. No log line at all.	Read the `DKIM-Signature` header of a delivered message
`InternalHosts` narrower than `mynetworks`	Signs locally, unsigned from apps	Send from a real application host, not from the relay

The third row is the one worth internalising. Three of these four failures announce themselves somewhere. The dataset-type bug produces no error, no warning, and a healthy-looking service, and the only way to observe it is to inspect the output rather than the process.

Step by step

Build the verification path before touching anything: send to a local mailbox and read the delivered headers. Every later change then gives an immediate yes or no.
Recheck every fact you were handed, including notes you wrote yourself yesterday.
Read the whole SMTP rejection. 5.7.25 and 5.7.26 name different failures, and in both the specificity lives in the second clause of the sentence.
Resolve the sending IP with dig -x, then resolve the answer forward. Both directions, or it doesn't count.
Confirm the TXT record begins with v=spf1 rather than merely mentioning SPF.
For DKIM: confirm the dataset type matches the table format, confirm the service user can read the key with su -s /bin/sh opendkim -c "…", and confirm InternalHosts covers every host in mynetworks.
Send the final test from a host that is not the mail server.

The end state was DKIM-Signature: v=1; a=rsa-sha256; d=example.org; s=mail in the delivered headers, spf=pass, dmarc=pass, and 250 2.0.0 OK from Gmail. Total time was about an hour and a half, most of it spent on the silent one.

What authentication didn't fix: six messages in ten still bounce

Passing SPF and DKIM gets mail accepted, not trusted, and this domain's reputation problem survived every fix above untouched. A full day of counters after the fix still showed more rejections than deliveries — roughly six messages in ten going nowhere — and among them close to a hundred a day addressed to @iclaud.com, a typo of @icloud.com that the application has been faithfully retrying for years. Bounce rate is not the metric Google publishes a threshold for; that one is spam rate, which bulk senders are asked to keep under 0.30% in Postmaster Tools. They are different numbers, but they feed the same reputation ledger, and 0.30% is a useful sense of the scale a receiver considers acceptable. Mail with flawless authentication still lands in the spam folder if the domain spends years hammering addresses that don't exist.

The reason nobody knew is that the feedback loop had been cut at both ends. The server delivered non-delivery reports to the sender address, whose domain it considered local via mydestination, and no local user by that name existed, so the reports were discarded on arrival. That was hundreds of destroyed reports a day. The application mails a dead address, the report about it is deleted by the same server, nobody finds out, and the application keeps mailing.

What I deliberately did not do was tighten DMARC past p=none. Moving to quarantine before the statistics are clean would route legitimate mail to spam by my own hand, and there is no rush. Still outstanding: the envelope sender equals the From: address, where a dedicated bounce address with VERP belongs; certbot 0.12.0 is dead on this box, still calling the retired acme-v01 endpoint, with a certificate that expired years ago. And every change here was made by hand on a container that lives outside Ansible, so none of it exists in any repository. The next person to open this server will find no trace of why it works.

Bottom line

When a daemon reports active and does not do its job while logging nothing, stop repairing hypotheses and go read the man page for the semantics of the specific option you are relying on. Silence is not the absence of a fault. It is its own class of behaviour, and it is always described somewhere in the documentation, usually in a sentence about how lookups are performed.

The process mistake was ordering. I fixed three genuine defects (truncated config, key ownership, then the host list) before finding the one that actually mattered, and each time I expected the next test to pass. A reliable check built at minute one, reading the headers of a delivered message, would have turned each of those into a one-minute negative result instead of an hour of accumulating false hope. Build the instrument before you start turning things.

Originally published at bitpage.me — BitPage, a technical blog on backend, databases, infrastructure and incident post-mortems.

PostgreSQL conflict with recovery: why both standard fixes make it worse under Patroni

bitpage — Sun, 09 Aug 2026 05:21:01 +0000

Short answer: Both top search results for canceling statement due to conflict with recovery are wrong on a Patroni cluster with replication slots and one replica. hot_standby_feedback=on parks the xmin horizon inside the slot, where it survives the replica's death and bloats the primary; raising max_standby_streaming_delay converts held-back replay into the exact lag your load balancer ejects the replica for. What I shipped instead was removing on-marked-down shutdown-sessions from the read backend, after measuring that replica lag runs in single-digit milliseconds at the median against a health-check threshold of 10 MB.

The cluster: one primary and one replica under Patroni 3.0.2 with etcd, PostgreSQL 15, synchronous replication, use_slots: true. Web requests from PHP-FPM read through HAProxy 2.4.30 against the replica; CLI work (queues, scheduler) goes to the primary. Once every quarter hour a cron job wipes and rebuilds a large table in full, and it belongs to someone else's business logic, so it is not negotiable. The application was catching SQLSTATE[40001], and a developer had already written an interceptor at the PostgresConnection level that retries the cancelled read on the primary. The question I was handed was whether he'd done it right. That took a day to answer and turned out to be about something else entirely.

TL;DR

Fix: drop on-marked-down shutdown-sessions from the read backend — it was killing dozens of live sessions per ejection, and the application does not see 40001 for those, it sees a dead socket.
Don't: hot_standby_feedback=on with replication slots and a single replica — the xmin outlives the replica, so the failure mode moves from "a report dies" to "the primary fills its disk."
Don't: raise max_standby_streaming_delay when the load balancer health-checks replayed position — you pay for it with fan-out read outages instead of a couple of dozen cancelled queries a day.
Measure: replay_lag sampled from the primary once a second for twenty minutes. Median in single-digit milliseconds, p95 in tens, worst case a couple of seconds — against a byte threshold that a ~170 MB burst clears in a few seconds.
Trap: Patroni's lag= parameter is bytes-only. A requirement stated in seconds cannot be expressed in it at all.

Why hot_standby_feedback is the wrong first move with replication slots

Replication slots change what hot_standby_feedback=on costs you, because the xmin stops being tied to a live connection. The PostgreSQL 15 documentation is upfront about the general risk: the parameter "can be used to eliminate query cancels caused by cleanup records, but can cause database bloat on the primary for some workloads" (runtime-config-replication). That sentence is what every answer on the internet is implicitly waving away when it recommends the setting.

The part that applies specifically here is one section over, in the description of slots: "Replication slots provide an automated way to ensure that the primary does not remove WAL segments until they have been received by all standbys, and that the primary does not remove rows which could cause a recovery conflict even when the standby is disconnected" (warm-standby).

Read that as an operator rather than as a feature description. Without slots, feedback xmin lives as long as the session does; kill the replica and the primary is free again. With slots, the xmin settles into pg_replication_slots.xmin and stays there while the replica is gone. There's one replica in this cluster and no spare. Turning the setting on would mean any replica outage becomes unbounded bloat on the primary, and I'd have traded a couple of dozen cancelled read queries a day for a way to take down the whole database. That one didn't need a benchmark to reject.

Why raising max_standby_streaming_delay feeds the flap

Delaying WAL replay is only free if nothing downstream measures replay position, and on this cluster the load balancer does exactly that. max_standby_streaming_delay is the second-most-popular answer, and on paper it is the polite one: instead of killing the query, hold back the apply. The docs describe it as "the maximum total time allowed to apply WAL data once it has been received from the primary server," defaulting to 30 seconds (runtime-config-replication). The cost stays on the replica, which is what makes it look safe.

It isn't safe here. HAProxy's health check calls Patroni's /replica?lag=, and Patroni computes lag from the replayed position. Held-back replay is, by definition, replay lag. Push the parameter from 30 s to 300 s and every conflict-heavy moment turns into a five-minute-wide window where the balancer can decide the replica is stale and pull it from rotation. The outcome would have been strictly worse than the problem: instead of a couple of dozen cancelled queries per day, fan-out outages across all reads.

The full set of candidates, and why each one died:

Candidate	Where the cost lands	Why it was rejected
`hot_standby_feedback=on`	Primary (bloat)	With slots, xmin survives replica downtime; single replica, no spare
`max_standby_streaming_delay` 30s → 300s	Replica (replay lag)	Replay lag is what the health check ejects on; amplifies flapping
Health-check threshold 10 MB → 512 MB	Nothing measurable	The requirement was stated in seconds; any byte value is a guess at time
HAProxy `agent-check` on wall-clock lag	New moving part	Correct, but a new component in the infrastructure; deferred until measured
Drop `on-marked-down shutdown-sessions`	Nothing	Shipped

The third row is the one I would have gotten wrong on my own. I proposed raising the byte threshold, and the customer rejected it with a better argument than mine: the requirement was written in time ("a second of staleness is fine, half a minute is not"), and a byte threshold answers a different question. On steady write load the two are nearly interchangeable. On batch write load they diverge by orders of magnitude, which is the whole story of this cluster.

Two problems that looked like one

Conflicts and replica ejections clustered in the same minutes because they share a cause, not because one causes the other; barely one conflict in twenty lines up with an ejection. There were two symptom streams. One in the PostgreSQL log — a couple of hundred cancelled queries over a week and a half:

ERROR:  canceling statement due to conflict with recovery
DETAIL:  User query might have needed to see row versions that must be removed.

FATAL:  terminating connection due to conflict with recovery

And one in the HAProxy log (N here is the live session count at the moment of the ejection — dozens, in this cluster):

Server slave/pg_replica is DOWN, reason: Layer7 wrong status, code: 503,
info: "Service Unavailable", check duration: 4ms. 0 active and 0 backup
servers left. N sessions active, 0 requeued, 0 remaining in queue.

Both landed in the same handful of minutes each hour. The connection seemed too obvious to check, which is precisely why it deserved checking.

Before I got there I burned time on two hypotheses that a timestamp comparison would have killed in a minute each:

Checkpoints. With checkpoint_timeout=15min the primary logs a checkpoint every quarter hour. The ejections land on entirely different minutes. No overlap at all.
The backup window. The backup script raises max_standby_streaming_delay to 3600 s for the duration of pg_dump, which looked like an excellent suspect. Every single ejection lasted between 6 and 27 seconds. There is not a single hour-long window in the data.

Then I lined up the two event streams properly (the logs are in different timezones, so this needs converting to one scale first) and compared: about a third of the replica ejections and barely a twentieth of the conflict events fall in shared windows. Two independent symptoms driven by the same cron job, not a chain.

I should have run that correlation first. It cost one command, and it invalidated a morning's worth of theories I'd been carefully stacking on top of each other.

What the lag actually was, in bytes and in seconds

The replica was never slow at applying WAL; it was slow at receiving it, and the difference decides which knob is even relevant. I sampled pg_stat_replication from the primary once per second:

SELECT now()::time(0),
       pg_wal_lsn_diff(pg_current_wal_lsn(), replay_lsn) AS replay_bytes,
       pg_wal_lsn_diff(pg_current_wal_lsn(), flush_lsn)  AS flush_bytes
FROM pg_stat_replication;

Put on a relative time scale, with the figures rounded off, a single burst looks like this:

T+0 s     replay=  0 MB   flush=  0 MB
T+1 s     replay=150 MB   flush=150 MB   ← cron batch starts
T+2 s     replay=170 MB   flush=170 MB
T+3 s     replay= 90 MB   flush= 90 MB
T+5 s     replay=  0 MB   flush=  0 MB   ← caught up

flush tracks replay to within a fraction of a percent. Nothing is queued waiting to be applied, so the lag is purely transport: the primary generated WAL faster than the link carried it. At rest the replica sits tens of kilobytes behind. The health-check threshold is 10 MB. A burst of ~170 MB clears that threshold by a factor of 17 and is gone within a few seconds.

Then the measurement that actually settled the argument, using the *_lag interval columns, sampled once a second over twenty minutes:

Metric	`replay_lag`
Median	single-digit milliseconds
p95	tens of milliseconds
Worst sample seen	a couple of seconds
Samples above 5 s	none
Samples above 30 s	none

The stated requirement was "a second is acceptable, half a minute is not." The replica never came within three orders of magnitude of unacceptable. And the nature of the lag is confirmed again by subtracting one column from the other at the peaks — the three largest samples in the window, figures rounded:

peak 1   ~160 MB | flush 1.0 s | replay 1.0 s | delta: fractions of a millisecond
peak 2   ~100 MB | flush 0.7 s | replay 0.7 s | delta: fractions of a millisecond
peak 3    ~95 MB | flush 1.7 s | replay 1.7 s | delta: fractions of a millisecond

Applying WAL adds fractions of a millisecond. The two cron runs caught in that window sit exactly a quarter of an hour apart, which is the cron job signing its work.

What lag= in the Patroni health check actually guards

The lag= parameter covers exactly one scenario, "replica alive but behind," because role and state are checked independently of it. The source is more useful than the documentation here: the docs describe what the endpoint is for, the code describes what it does. From patroni/api.py in v3.0.2:

max_replica_lag = parse_int(self.path_query.get('lag', [sys.maxsize])[0], 'B')
if max_replica_lag is None:
    max_replica_lag = sys.maxsize
is_lagging = leader_optime and leader_optime > replayed_location + max_replica_lag

replica_status_code = 200 if not patroni.noloadbalance and not is_lagging and \
    response.get('role') == 'replica' and response.get('state') == 'running' else 503

Two things fall out of those few lines. First, parse_int(..., 'B'): the threshold is bytes, full stop. There's no time-based variant of this endpoint, so the entire discussion about "what number should we put there" was unanswerable until somebody said the units out loud. Second, is_lagging sits in a chain with role and state, each able to produce a 503 on its own. A genuinely broken replica gets caught by state/role anyway: when streaming breaks, the row just vanishes from pg_stat_replication and there's no byte figure left to compute.

There's a third detail that makes the threshold shakier than it looks. leader_optime is read from etcd, refreshed once per loop_wait — 10 seconds by default (Patroni settings) — so the byte figure being compared can be up to a loop_wait stale before you even pick a number to compare it against. Against bursts that come and go in a few seconds, the measurement interval is longer than the event.

Prometheus history sizes the one scenario the threshold does cover (pg_replication_lag_seconds, 15 s scrape). Over a month, lag exceeded one minute exactly once: the single real failure in that window ran for hours, when the replica's VM came back from a hypervisor reboot without network.

A couple of seconds in the worst normal case against hours for a real failure. Nearly four orders of magnitude between them, and the threshold was sitting right up against the lower bound. A threshold that far from the signal it's supposed to catch isn't "tuned strictly," it's tuned arbitrarily. The group_vars file even carries a comment from whoever raised it earlier, explaining that the bump was meant to avoid false DOWNs during checkpoint and autovacuum. Against a ~170 MB burst, no value in the tens of megabytes was ever going to work.

Why pg_replication_lag_seconds lies when nobody is writing

On a replica, postgres_exporter computes this metric as now() - pg_last_xact_replay_timestamp(), so during write silence it grows on its own without the replica being behind by anything. Its p99 over the month runs to tens of seconds, and reading that as "the replica served data tens of seconds stale" is wrong: it means the last transaction it replayed was that old, because no newer transaction existed. On the primary the same metric is flat zero. Only direct replay_lag sampling from the primary is trustworthy.

The second limitation is resolution. At a 15-second scrape interval, a burst that lasts a few seconds is invisible by construction. For short events the instrument is the HAProxy log, not the dashboard.

Reading burst length out of the HAProxy log

When monitoring resolution is too coarse, the health check itself is a measuring instrument with known timing. With inter 3s fall 3 rise 2:

DOWN is declared after fall 3 × inter 3s = 9 seconds above threshold.
UP returns after rise 2 × inter 3s = 6 seconds below it.
Therefore burst length ≈ DOWN duration + 3 s.

Applied to thirty-odd ejections over a bit more than a week:

DOWN lasted	Share of ejections	Burst was	Survives `fall 5`?
6 s	about two thirds	~9 s	no — eliminated
9 s	a couple of cases	~12 s	no — eliminated
18 s	a couple of cases	~21 s	yes
21 s	roughly a fifth	~24 s	yes
27 s	one case	~30 s	yes

Two thirds of them lasted the minimum possible DOWN, meaning the burst barely crossed the threshold and was already over. Raising fall 3 → fall 5 requires 15 consecutive seconds above threshold and removes around 70% of the ejections, with no staleness risk given the numbers above. The remaining third ran 21–30 seconds and would still eject.

To be clear about status: that change is argued for with the numbers above and agreed in principle, but it is not applied. It sits behind the same sign-off as anything else touching the balancer, and the residual third of the ejections needs either a higher byte threshold or the time-based check I keep coming back to.

That arithmetic required no new tooling, no sampling, and no agreement from anyone. The data had been in the balancer log the whole time.

What I shipped, and how the rollout went sideways

One line removed from the read backend, leaving the failover-critical backends untouched:

 backend slave
     option httpchk GET /replica?lag=10485760 ...
     http-check expect status 200
-    default-server inter 3s fall 3 rise 2 on-marked-down shutdown-sessions
+    default-server inter 3s fall 3 rise 2

The HAProxy 2.4 manual describes the option plainly: with shutdown-sessions, "all connections to the server are immediately terminated when the server goes down" (configuration manual, §5.2). On a read backend fronting a replica that comes back within seconds, that is damage with no upside. In the logs it killed dozens of sessions at once. The application does not see 40001 for those connections, it sees a severed socket, which the developer's interceptor never catches. The replica can still be ejected during a burst; live reads now finish, and new connections fall through to use_backend master if { nbsrv(slave) eq 0 }. The option stays in the master and long_queries backends, where killing sessions during failover is the point.

Three things about the rollout worth stealing:

--check --diff on the whole playbook, not just my part. Someone had added weight 80 / weight 20 by hand on the server and never put them in the template. A normal run would have silently erased them. I pulled the repository up to the server's actual state first, then applied my change on top.
A group_vars file turned out to be a hardlink shared by several inventories. One edit, every environment changed.
I rolled it out with a restart instead of a reload. In master-worker mode kill -USR2 to the master reloads without dropping anything: the master holds the sockets, the port never closes, and the old worker drains its sessions. A restart dropped every connection at once — which is precisely the damage this change exists to prevent. Shipping a fix for connection drops by dropping every connection is the kind of thing you only do once.

Why Patroni ignores the log settings in your playbook

Anything under bootstrap.dcs is applied once, at cluster initialization, and edits to it afterwards do nothing. I found this while looking for something else entirely: pg_log had never rotated. Tens of gigabytes on the primary, single-digit gigabytes on the replica, files that had been piling up for years, on a cluster whose Ansible template configures rotation perfectly well.

Nobody had edited anything by hand this time. The Patroni documentation states the rule with unusual force: "Once Patroni has initialized the cluster for the first time and settings have been stored in the DCS, all future changes to the bootstrap.dcs section of the YAML configuration will not take any effect!" (YAML configuration). The section "will be written into /<namespace>/<scope>/config of the given configuration store after initializing the new cluster," and from that moment the copy in etcd is the one that counts.

Changing those values later goes through patronictl edit-config or the REST API, not the file (dynamic configuration). Which means a Patroni cluster has a whole class of settings where the playbook is documentation rather than configuration, and --check --diff will never tell you, because the file on disk matches the template exactly. It is right and the cluster still ignores it.

What the application layer got wrong

The interceptor I was asked to review was correct; the defects were around it. Findings handed back to the developers:

ERROR and FATAL are different events. ERROR: canceling statement due to conflict with recovery cancels the statement and leaves the connection usable. FATAL: terminating connection due to conflict with recovery does not. Over the week and a half of logs, nearly all the events were ERROR and a handful were FATAL. One retry strategy cannot serve both.
The retry loop was unreachable past its first iteration, so it retried once regardless of configuration.
The application under-reports by half. Over two weeks the database logged roughly twice as many conflict events as the application reported through its single Log::warning. That gap is why nobody knew the size of the problem.
application_name is empty in every event, so a conflict cannot be attributed to a service from the database logs — only to a database user.
A pre-existing lazy-connection bug in the Laravel wrapper. bindValues() opens with $this->getPdo()->getAttribute(...), and getPdo() resolves the lazy closure and opens a connection to the primary. Every query with bindings calls it, read-only ones included, so the read/write split silently leaks connections to the primary on any parameterised read.

Half of my initial review comments on the interceptor did not survive my own re-checking. Separating "I would have written this differently" from "this is a defect" is most of what code review is, and I am not always good at it.

Step by step

Count the events before theorizing: split ERROR from FATAL in the PostgreSQL log and get the rate per day.
Correlate every symptom stream by timestamp on one timezone scale, first, before building any causal story.
Sample pg_stat_replication from the primary once per second; compare replay_lsn against flush_lsn to separate transport lag from apply lag.
Sample the *_lag interval columns to get lag in seconds, which is the unit your requirement is almost certainly written in.
Read your health-check endpoint's source for the units it actually accepts before negotiating a threshold value.
Derive burst duration from the balancer's own inter/fall/rise timing when scrape intervals are too coarse.
Check whether hot_standby_feedback is safe for your topology: with slots and one replica, it is not.
Run --check --diff across the whole playbook before applying, and reload rather than restart.
For anything Patroni owns, read the live values with patronictl show-config rather than trusting the YAML in your repository.

Bottom line

Neither of the two canonical answers to conflict with recovery was usable on this cluster, and both failures were topology-specific rather than wrong in general. hot_standby_feedback assumes you have no slots or a spare replica; raising the streaming delay assumes nothing downstream measures replay position. Check those assumptions against your own cluster before pasting either one into postgresql.conf.

The larger lesson is about units. The health check measured "how much WAL has not arrived" in bytes while the business requirement said "how stale is the data I am serving" in seconds. Every discussion about the right threshold was unanswerable until somebody wrote both sentences down next to each other. The measured answer was single-digit milliseconds at the median against a real failure measured in hours — and the deferred work, an agent-check agent reporting up/down from now() - pg_last_xact_replay_timestamp(), is now a decision that can be made with numbers instead of a guess.

Originally published at bitpage.me — BitPage, a technical blog on backend, databases, infrastructure and incident post-mortems.