pg_deadlocks RDS log route: engines counted 6 new deadlocks post-cutover; zero rows ever stored across 85,549 SUCCESS runs

The pg_deadlocks collector's RDS log route has stored zero rows since its cutover, while the monitored engines' own pg_stat_database.deadlocks counters advanced six times in the same window. The collector reported SUCCESS on every one of 85,549 runs while capturing none of the events it exists to capture.

Measured, store-side, 2026-09-05 ~15:07Z (read-only queries against the production store monitoring an Aurora PostgreSQL fleet)

Collector timeline (collect.collection_log, collector_name = 'pg_deadlocks'):

status	first_run	last_run	runs
PERMISSIONS	2026-08-27 12:04:07	2026-08-30 15:09:38	26,014
SUCCESS	2026-08-30 15:10:52	2026-09-05 15:07:25	85,549
ERROR	2026-08-31	2026-09-04	2

The PERMISSIONS era is the pre-cutover pg_read_file denial already documented on the #2994/#3010 trail; the 2026-08-30 15:10:52 boundary is the switch to the RDS log API route, SUCCESS ever since.

Stored deadlock reports: SELECT count(*) FROM collect.pg_deadlocks → 0. Zero rows ever, any era.

Engine-side ground truth: per-(server, database) deltas of the cumulative deadlocks counter across collected pg_database_stats history, aggregated per day (lag() over daily max; a stats reset makes a delta negative and is filtered, so every positive step is a genuinely new deadlock):

day	target	new deadlocks
2026-08-29	target-a, target-b (×2), target-c, target-d	5
2026-08-30	target-e	1
2026-09-01	target-b, target-f	2
2026-09-02	target-b, target-g	2
2026-09-03	target-b	1
2026-09-04	target-c	1

The 08-29/08-30 events fall in (or straddle) the denied era — losses already implied by the PERMISSIONS record. The four post-cutover days are the finding: six deadlocks across four targets on 09-01…09-04, all inside the SUCCESS era, none stored. Day-granularity sampling means an individual step can sit anywhere inside its 24 h bucket, but 09-02/09-03/09-04 are unambiguously post-cutover regardless of intra-day position.

What this is and is not

Not A deadlock report cut at an RDS chunk boundary is lost or stored incomplete — the parser's "the window overlaps" is false for the consume-once route #3009's truncation shapes. Both of those need a report reaching the parser to be cut; here nothing is stored at all. Say which transport recovers a truncated deadlock report, and pin what the other loses (#3009) #3028's doc corrections stand on their own; the frequency question that PR could not measure is now answered — fleet base rate ≈ 1.2 deadlocks/day, capture rate on the RDS route 0 % over five-plus days.
Not honest-empty. The empty table would be the correct answer for a fleet that does not deadlock. The engines say this fleet does.
Not the stale-last_error class (last_error keeps a fault from a code path the collector no longer takes, with no timestamp to date it #3010) — that was a reporting artifact; this is the collection itself.

Candidate causes, for whoever picks it up

The deadlock ERROR (with its DETAIL: Process … waits for … graph) never reaches the log stream the RDS route reads — cluster-parameter suppression (log_min_messages, error verbosity) or the report landing in a stream the reader does not request.
The report is present but the parser misses it wholesale — the managed engine's log_line_prefix differing from the shapes PgDeadlockLogParser's block regex was built against, or the resume-window semantics skipping it. (A deadlock report cut at an RDS chunk boundary is lost or stored incomplete — the parser's "the window overlaps" is false for the consume-once route #3009's analysis of the block regex is the starting point; note the parser was verified against self-hosted 17.x fixtures.)
The route reads the right stream with the right parser but a filter upstream of FromBlock (timezone gate, marker placement) drops the block before parsing.

A useful first probe: fetch one raw log window covering a known counter step (09-02 or 09-03 on target-b, the repeat offender) through the same RDS API the product uses, and diff what the log actually contains against what the parser expects. That distinguishes cause 1 from causes 2/3 in one read.

Reproduction of the measurement (synthetic names; run read-only against the store)

-- collector timeline
SELECT cl.status, min(cl.collection_time), max(cl.collection_time), count(*)
FROM collect.collection_log AS cl
WHERE cl.collector_name = 'pg_deadlocks'
GROUP BY cl.status;

-- stored reports
SELECT count(*) FROM collect.pg_deadlocks;

-- engine ground truth: positive daily steps of the cumulative counter
WITH d AS (
    SELECT s.server_name, s.database_name, s.collection_time::date AS day, max(s.deadlocks) AS dmax
    FROM collect.pg_database_stats AS s
    GROUP BY s.server_name, s.database_name, s.collection_time::date
)
SELECT x.day, x.server_name, x.inc
FROM (
    SELECT d.server_name, d.database_name, d.day,
           d.dmax - lag(d.dmax) OVER (PARTITION BY d.server_name, d.database_name ORDER BY d.day) AS inc
    FROM d
) AS x
WHERE x.inc > 0
ORDER BY x.day;

Claude posting for Erik Darling

Cause 2 is confirmed, and it is confirmed without needing the store: the managed engine's log_line_prefix cannot match PgDeadlockLogParser's block regex on any line, ever. Causes 1 and 3 are excluded.

What the parser requires

s_deadlockBlock anchors at line start on:

^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) (?<zone>[^ \n]+) \[(?<pid>\d+)\][^\n]*ERROR:  deadlock detected

Two of those requirements are load bearing and separable:

H1 — fractional seconds. \.\d+ is mandatory. Only %m renders them; %t does not.
H2 — a space before the bracketed pid. The pattern spells <zone> [<pid>], so whatever precedes [ must be a space.

Both are satisfied by PostgreSQL's own default, log_line_prefix = '%m [%p] ', which renders 2026-08-26 22:25:24.100 UTC [1549] . That is the shape every fixture in this repo is built on.

What the fleet actually emits

log_line_prefix is %t:%r:%u@%d:[%p]: — the AWS system default — on 51 of 51 Aurora PostgreSQL cluster parameter groups and 51 of 51 instance-level parameter groups, with Source = system at both levels, i.e. never overridden anywhere. It renders:

<stamp> UTC:<client>(<port>):<user>@<db>:[1549]:ERROR:  deadlock detected

That fails both halves at once: no fractional seconds, and a colon rather than a space before [1549].

Measured on real production log text from all 43 monitored targets, fetched through DownloadDBLogFilePortion — the same API and the same error/postgresql.log.* file the route reads. All 43 returned non-empty text, so this is a measurement of the population and not of a failed fetch:


bytes of real log text measured	10,978,198
timestamped lines (population control)	9,567
lines matching the parser's required prefix	0
fractional-second stamps anywhere	0
`ERROR:` lines	3,672
`DETAIL:` lines	165
tab-indented continuation lines	89,276
`PgDeadlockLogParser.Extract()` reports	0

Every severity token in that sample is followed by exactly two spaces, matching the parser's literals. The prefix before every one of them is <stamp> UTC:<client>(<port>):<user>@<db>:[<pid>]:, plus 14 lines where %r rendered empty (<stamp> UTC::@:[<pid>]:) — which still carries no fractional seconds and still ends ]:, so it cannot match either. The zone token renders UTC on all 9,567 stamped lines, so IsZeroOffsetLogZone would accept every line in the fleet.

Why each half is independently fatal

The real parser, compiled from source, over one report body rendered under four prefix regimes:

regime	fractional seconds	space before `[pid]`	reports
A `%m [%p]` (self-hosted default)	present	present	1
B `%t:%r:%u@%d:[%p]:` (the fleet)	absent	absent	0
C H2 only — fraction restored, colon kept	present	absent	0
D H1 only — space restored, fraction absent	absent	present	0

A is the control: the same body parses, so the body is well formed and only the prefix differs. C and D each revert one half and each still yields zero, so neither half is the sole cause and fixing only one would not recover a single report.

Cause 1 excluded

Nothing on this fleet suppresses the report or diverts it from the stream the route reads. Across all 51 cluster parameter groups: log_destination = stderr (system), and log_min_messages, log_error_verbosity, log_min_error_statement, log_statement and deadlock_timeout are all at engine default — so ERROR passes the severity floor and DETAIL is not suppressed the way terse would suppress it. Empirically, the 43-target sample carries 3,672 ERROR: lines, 165 DETAIL: lines and 89,276 tab-indented continuation lines, all in the shapes the parser's literals and its (?:\t[^\n]*\n)* group expect. Every constituent of a deadlock report demonstrably reaches this log; only the prefix disagrees.

No whole deadlock detected line appears in that sample, and it should not be read as evidence either way: 344 hourly windows across 43 targets is roughly a third of a fleet-day, and at ≈1.2 deadlocks/day the expected count is under one.

Separately, CloudTrail shows the monitoring host's instance role calling DownloadDBLogFilePortion continuously — 42 of the 50 most recent such calls in the account, against 43 distinct target instances, all for error/postgresql.log.<stamp>. So SourceReached is true on this fleet as a matter of AWS's own record: the route reaches the log every cycle and reads it. A zero-row cycle here is not "we did not look."

Cause 3 excluded, but not by the SUCCESS record

Worth stating precisely, because the intuition runs the wrong way. The timezone gate sits downstream of the block match, not upstream of it. IsZeroOffsetLogZone is called from FromBlock, and Extract only calls FromBlock once per matched block. With zero matches the gate is never reached, so PgLogTimezoneUnsupportedException cannot be thrown no matter what the zone is. A SUCCESS record is therefore equally consistent with "the zone was fine" and with "the gate was unreachable" — it does not discriminate, and the classified PERMISSIONS arm does not help here.

What does exclude the timezone arm is independent: log_timezone = UTC (system) on all 51 groups, and the fetched log renders the zone token UTC on all 9,567 stamped lines across all 43 targets, which IsZeroOffsetLogZone accepts. The marker arm is excluded too — since the marker moves only after StoreAsync returns, and StoreAsync returns 0 rather than throwing, the marker advances normally every cycle. Marker placement is not skipping the block; the block is being read and discarded.

Where the SUCCESS comes from, and the note that is actively wrong

StoreAsync gets the text, Extract returns an empty list, StoreAsync returns 0, and RdsIngestOutcome.Read(0) records SourceReached = true with zero rows. RdsIngestNote then stamps the cycle:

no new deadlocks in the RDS log window

That sentence is a claim about the log's contents, and it is false on the days the engine counters stepped. SourceReached distinguishes "did not look" from "looked" but cannot distinguish "looked" from "looked and could not read a word of it" — which is the third kind of nothing, arriving after #2633 and #3017 each fixed one of the first two.

The loss is permanent, not deferred: the marker commits on that zero, so the window is consumed and the text is never offered again.

Why it shipped green

Every log fixture in the repo carries the self-hosted prefix, and none carries the managed one. Swept over 2,339 files with the self-hosted pattern as a firing positive control:

self-hosted prefix: Lite.Tests/PgDeadlockLogParserTests.cs (12), Darling/Darling.Tests/RdsDeadlockIngestorTests.cs (5), Darling/Darling.Tests/Fixtures/auto_explain_real_block.txt (4), Lite.Tests/PgPlanCaptureCollectorDefinitionTests.cs (4), Darling/Darling.Tests/RdsPlanIngestorTests.cs (2)
managed prefix, strict or loose: none, anywhere

RdsDeadlockIngestorTests is the suite that exercises the managed transport specifically, and its DeadlockText is captured self-hosted output. So the transport's own tests proved the plumbing while feeding it text no managed target emits. The suite's positive control was the easy shape.

Related, and not the same severity

PgPlanLogParser.s_planBlock requires \[\d+\] — a space after the bracketed pid — and the managed prefix renders ]:, so the plan route has the same defect by the same root cause. It is inert on this fleet today: shared_preload_libraries is pg_stat_statements on all 51 groups with auto_explain absent everywhere (swept with pg_stat_statements as a positive control, 51/51), so no managed target emits a plan at all and collect.pg_plans being empty is honest. It becomes live the moment anyone preloads auto_explain on a managed target.

Also worth correcting while it is in view: PgDeadlocksCollector's and PgDeadlockLogParser's summaries both state that "there is no setting that suppresses a deadlock report." log_error_verbosity = terse suppresses the DETAIL: block, which is the entire graph, and log_min_messages above error suppresses the line. Neither is set on this fleet, so neither is the cause — but the claim is what made the prefix worth not checking.

Claude posting for Erik Darling

Two corrections to the brief that produced the finding above, both mine, and the second is a reasoning error worth recording because it would have closed off the right answer.

1. The RDS probe was reachable and I predicted it was not. I briefed the investigation on the assumption that this issue's own "useful first probe" — fetch a raw log window through the RDS API — was out of reach, because every lane needing the managed store today found it unreachable. That was true of the store and false of AWS: SSO is live, and rds describe-*, rds download-db-log-file-portion and cloudtrail lookup-events all work. Only ssm send-command is blocked. So the probe ran, and 10.98 MB of real log text across all 43 targets is the result.

The lesson is one this queue keeps relearning: a capability claim is also just a claim, and "no lane could reach X" is not the same fact as "X is unreachable." I generalised from other lanes' walls to this lane's.

2. I said the SUCCESS record excludes cause 3. It does not, and the reason inverts my reasoning.

I argued that #3001 added PgLogTimezoneUnsupportedException, so a timezone the gate refuses would throw rather than silently return nothing — and therefore a collector reporting SUCCESS could not be failing at the timezone gate.

The gate is downstream of the block match, not upstream. IsZeroOffsetLogZone is called from FromBlock, and Extract calls FromBlock only per matched block. Zero matches means the gate is never reached and cannot throw whatever the zone is. So SUCCESS is equally consistent with "the zone is fine" and "the gate was never reached," and it discriminates nothing.

That mattered: I offered it to the lane as a way to narrow the search, and narrowing on it would have pointed away from the prefix. The lane checked the call order instead of accepting it, which is why the answer is right.

A third thing the investigation surfaced that neither the issue nor I had: both PgDeadlocksCollector and PgDeadlockLogParser state that "there is no setting that suppresses a deadlock report." That is false — log_error_verbosity = terse suppresses the DETAIL graph. It is not set on this fleet, so it is not the cause here, but a comment asserting that no setting can suppress the report is plausibly why nobody went looking at the log's rendering settings in the first place. A false reassurance in a comment steering an investigation away from the actual cause is the same class of defect as #3009's false recovery guarantee, one level up.

Stop claiming nothing can suppress a deadlock report

Claude posting for Erik Darling

Store-side confirmation, run against the production store after the fleet-side analysis above: over the last 24 hours the pg_deadlocks collector logged 14,291 SUCCESS runs and every one of them carries the note "no new deadlocks in the RDS log window" — the only distinct note value, across all 50 monitored servers, with the oldest such note dated 2026-08-30, the cutover day. collect.pg_deadlocks remains at zero rows at query time. The plan-capture table on the same transport also holds zero rows, which is the honest-empty expected while auto_explain is absent from every cluster parameter group — consistent with the "same defect, currently inert" classification of the plan parser rather than a second live outage. Together with the parameter-group census and the CloudTrail fetch records: the route reaches the log on every cycle, the parser matches nothing the managed prefix emits, and the resume marker consumes each window on the way out.

Two corrections to the Part B specification, recorded so nobody re-runs it as written:

collection_log has no notes column. Notes ride in error_message on SUCCESS rows — which is how last_note is aggregated in the health reader. As specified, the query errors to stderr and, through the SSM path, returns an empty-looking success. That is the failed-fetch-reads-as-clean shape, caught before the run rather than after it. Corrected form: filter status = 'SUCCESS' and read error_message.
The plan-capture table is collect.pg_plan_capture. The specification's pg_plans does not exist.

Both matter beyond this issue: a spec that returns empty because it named a column wrong is indistinguishable from a spec that returns empty because the finding is false.

Say which transport recovers a truncated deadlock report, and pin wha…

Read the log prefix a managed PostgreSQL target renders, and test bot…

Claude posting for Erik Darling

The fix is merged (#3037) and this issue stays OPEN deliberately, because its own claim is a production measurement that is not yet true.

Why not close on merge

Every other issue closed today was closed on merge, because its defect was structural and its fix was verified by tests. This one is different in kind: the finding is "zero rows stored across 85,549 SUCCESS runs while the engines counted six deadlocks." That number is still zero right now — the fix is on dev and has not deployed.

And there is a specific reason not to assume: no live managed target has been through the fixed parser. The managed fixture is synthesised from the measured prefix shape, and every numeric-zone-under-colon result — including the IPv6 case that drove the final correction — is synthetic, because no fleet target renders one. If the managed prefix has a further variation nobody has seen, capture stays at 0% and a closed issue hides it.

Closing condition: the first row ever in collect.pg_deadlocks. The monitoring passes are watching for it.

What merged

Both prefix families are now alternatives rather than one pattern — the space family character-for-character the original, the colon family excluding : from the zone. 22/22 verdicts correct against the built assembly.

The single-pattern shape that was tried first, and that I specified in the brief, was a wrong answer rather than an incomplete one: a [ :] class needs the zone to be an abbreviation-or-offset alternation, and a numeric offset carries its own colons, so on +00:2001:db8::1(52345):… the zone captures as +00:2001, IsZeroOffsetLogZone refuses it, and a target that genuinely is UTC abandons every window, every cycle, complaining about a setting that is already correct. The review found it by hand; the review's own suggested fix ((?::\d{2})*) is also insufficient, because 0020 renders as 20.

The plan parser is fixed in the same PR, and its real problem is not bracket spacing: the managed system default has no %Q at all, and %Q is the only place auto_explain exposes a query id, so that prefix yields zero plans regardless.

The fixture, which is the part that closes the class

RdsDeadlockIngestorTests now drives a %t:%r:%u@%d:[%p]: report through the real ingestor. Pre-fix it failed with Assert.ThrowsAny: No exception was thrown — the production shape exactly: no error, no rows, a SUCCESS that captured nothing.

That matters because the original defect was undetectable for a reason beyond the regex: a sweep of 2,339 files found every log fixture in the tree carried the self-hosted prefix and none carried the managed one, while RdsDeadlockIngestorTests is the managed-transport suite. The transport suite was proving the plumbing on text no managed target emits.

Self-hosted still parses: 45 pre-existing tests unchanged and green. Lite 63/63, Darling 109/109, 0 skipped.

Left narrow deliberately

Four pattern sites, not two — both parsers have a SQL twin in the pg_read_file collectors. Untouched: a self-hosted-only route, the rig prefix satisfies them, positional captures would shift, and no PostgreSQL was available to verify. Both parsers now say so rather than implying parity.

Also remaining: the plan pattern still requires a space between the query id and LOG:, so a %Q:-terminated prefix would not match.

The two side findings, for the record

The plan parser's identical defect was inert rather than live — auto_explain absent on 51/51 cluster parameter groups, with pg_stat_statements as a firing control at 51/51, so collect.pg_plan_capture was honestly empty. It becomes live the moment anyone preloads the extension.

And the false claim that steered the original investigation away from the cause — "there is no setting that suppresses a deadlock report" — was corrected across four sites in #3028, after a sweep showed log_error_verbosity and log_min_messages appeared zero times across all 2,688 tracked files. The product had no written awareness of the parameter that suppresses its own capture.

Refuse a field name hiding inside an all-caps token, and record a tic…

Collect the store's own PostgreSQL log as a self-monitoring census (#…

Claude posting for Erik Darling

Closing: the production measurement this issue was filed on is no longer true. It was held open deliberately after #3037 merged, because the finding was "zero rows stored across 85,549 SUCCESS runs" and the specific gap was that no live managed target had been through the fixed parser. One has now.

Measured read-only against the production store, 2026-09-07:

occurred_at         | 2026-09-06 15:47:08
collection_time     | 2026-09-06 15:50:48.714816
victim_pid          | 83671
participant_count   | 2
deadlock_hash       | 32 chars
lock_modes          |  9 chars
resources           | 42 chars
victim_statement    | 127 chars
graph_text          | 1022 chars

collect.pg_deadlocks holds 1 row, from a monitored Aurora PostgreSQL target.

Why this is the parser working rather than a row arriving by some other route, which is the distinction the hold was about: every field populated, including a 1,022-character graph text and a 127-character victim statement. The block regex matched, the participant graph parsed, and the hash computed. A partial or fallback path would leave the graph or the statement empty. collection_time trails occurred_at by 3m40s, consistent with the collector's window rather than a backfill.

And the build is the fixed one. Installed service DLL is 3.6.0.0, written 2026-09-06T06:27:08Z; #3037 merged 2026-09-05T18:23:50Z. The deadlock occurred roughly 9.3 hours after that build went on. So the event passed through the fixed parser and not an older one.

Closing by hand — closing keywords do not fire here, since merges land on dev while the default branch is main.

Let a zero-output collector's own notes answer for its zero, instead …

Tell a permissions fault from a missing log file, and logging_collect…

Navigation Menu

Repository navigation

pg_deadlocks RDS log route: engines counted 6 new deadlocks post-cutover; zero rows ever stored across 85,549 SUCCESS runs #3030

Measured, store-side, 2026-09-05 ~15:07Z (read-only queries against the production store monitoring an Aurora PostgreSQL fleet)

What this is and is not

Candidate causes, for whoever picks it up

Reproduction of the measurement (synthetic names; run read-only against the store)

What the parser requires

What the fleet actually emits

Why each half is independently fatal

Cause 1 excluded

Cause 3 excluded, but not by the SUCCESS record

Where the SUCCESS comes from, and the note that is actively wrong

Why it shipped green

Related, and not the same severity

Why not close on merge

What merged

The fixture, which is the part that closes the class

Left narrow deliberately

The two side findings, for the record

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

pg_deadlocks RDS log route: engines counted 6 new deadlocks post-cutover; zero rows ever stored across 85,549 SUCCESS runs #3030

Description

Measured, store-side, 2026-09-05 ~15:07Z (read-only queries against the production store monitoring an Aurora PostgreSQL fleet)

What this is and is not

Candidate causes, for whoever picks it up

Reproduction of the measurement (synthetic names; run read-only against the store)

Activity

erikdarlingdata commented on Sep 5, 2026

What the parser requires

What the fleet actually emits

Why each half is independently fatal

Cause 1 excluded

Cause 3 excluded, but not by the SUCCESS record

Where the SUCCESS comes from, and the note that is actively wrong

Why it shipped green

Related, and not the same severity

erikdarlingdata commented on Sep 5, 2026

erikdarlingdata commented on Sep 5, 2026

erikdarlingdata commented on Sep 5, 2026

Why not close on merge

What merged

The fixture, which is the part that closes the class

Left narrow deliberately

The two side findings, for the record

erikdarlingdata commented on Sep 7, 2026

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions