Repository navigation
Commit the RDS resume marker after the write, not inside the fetch (#3008) - #3015
Conversation
…3008) RdsLogSource recorded the marker as a side effect of DownloadDBLogFilePortion, before the caller had parsed or stored anything. The transport is consume-once and the marker is per-process, so any failure between the fetch and a committed COPY consumed a window nobody stored: a parse fault, a COPY past its deadline, a dropped store connection and a cancelled cycle each lost every report in that window with no error naming the loss. ReadNewestAsync now returns the candidate marker with the chunk, and both ingestors commit it once the rows are durable. The commit sits at one point per ingestor, after a StoreAsync that either stores everything the chunk held or throws, so the marker cannot advance over a partial result. Applied to the plan route as well as the deadlock route: both call ReadNewestAsync, each holds its own RdsLogSource, and the defect was identical in both.
…after-write # Conflicts: # Darling/PerformanceMonitor.Darling.Service/Targets/RdsDeadlockIngestor.cs
ReviewScoped, well-targeted fix for the #3008 ordering defect: the resume marker in Verified by tracing both call sites:
One finding posted inline: |
RdsPlanIngestor got the identical #3008 fix but had no test reaching IngestAsync: RdsPlanIngestionFromRealLogTests only exercises PgPlanLogParser. The two ingestors hold separate RdsLogSource instances and separate copies of the read-store-commit sequence, so the ordering can regress in one while the other's suite stays green - and folding the two StoreAsync copies into a shared helper is the edit most likely to do it. Mirrors the deadlock suite's shape rather than transcribing it: failed store write, cancellation, and the quiet-cycle control that a never-firing commit would fail. Uses the real auto_explain capture the plan parser's own suite reads.
|
Reviewed the diff (RdsLogSource/RdsDeadlockIngestor/RdsPlanIngestor + the two new test suites and the RdsLogSourceTests changes). Scope check: this is Darling-only — Correctness:
No SQL touched by this PR (T-SQL style / Nothing else stood out as a bug or parity risk. Looks good to me. |
Closes #3008 only. #3009 stays open — it is a separate defect this does not address; see the last section.
Fixes the ordering defect in #3008:
RdsLogSourcerecorded the RDS resume marker as a side effect ofDownloadDBLogFilePortion, before the caller had parsed or stored anything.The transport is consume-once and the marker is per-process, so any failure between the fetch and a committed COPY consumed a window nobody stored.
DownloadDBLogFilePortiondoes not hand the same bytes out twice, and there is no overlapping re-read to fall back on the way thepg_read_fileroute has — so every deadlock (or plan) in that window was gone, with no error naming the loss.The change
ReadNewestAsyncreturns the candidate marker on the chunk instead of recording it.CommitResumeadvances it, and each ingestor calls that once, after the rows are durable.Both ingestors, because both call
ReadNewestAsyncand the defect was identical in each. Both are covered:RdsDeadlockIngestorTests.csandRdsPlanIngestorTests.csare new, the latter added after review pointed out that the plan half had the fix but no test reachingIngestAsync. They hold separateRdsLogSourceinstances precisely because the marker is consumed per read, so this was never a shared-cursor problem — it was the same bug twice.Each
IngestAsyncnow reads:StoreAsyncexists to give the commit exactly one predecessor with one rule: every way it can decline to store rows is a legitimate zero that loses nothing (empty text, a slab with no reports in it), and every way it can fail leaves via an exception. So the marker cannot advance over a partial result, and it still advances on a quiet cycle — which matters, because withholding it there would send a quiet target back for the same bounded 10,000-line tail every cycle forever.Scope of the protection
Not one exception type. Anything thrown between the fetch and the committed write leaves the marker where it was:
importer.Timeout(ServiceCommandDeadlines.CollectionSweepSeconds)That generality is the argument for fixing it at the marker rather than at any one throw. The timezone refusal is what exposed it; it is not what it is about.
What this trades
The transport goes from at-most-once with silent loss to at-least-once: a chunk can be re-stored if the process dies between a committed COPY and the marker moving. That is not a new property of the system. The marker is in memory, so a restart already re-reads a bounded tail, and
RdsLogSource's doc comment already records re-reading as the accepted trade — plan rows dedup on(queryid, plan_hash). What changes is that the in-process behaviour now matches the across-restart behaviour that was already chosen, instead of being strictly worse than it.Worth stating plainly: neither
collect.pg_deadlocksnorcollect.pg_plan_capturehas a unique constraint, so that dedup is read-side, not enforced by the store. A re-store after a mid-commit process death would land duplicate rows. Losing the window is worse, and the pre-existing restart behaviour already accepts this, but it is a real consequence rather than a free one.One existing test changed semantics
RdsLogSourceTests.FirstReadIsBounded_ThenItResumesFromTheMarkerread twice and expected the second read to resume. It now commits between the two reads. Against the fix, its previous form fails withExpected: "MARKER-1", Actual: null— verified by compilingdev's copy of that file against this branch. That is the contract change, deliberate and visible, not an incidental edit.It is paired with
TheMarkerDoesNotAdvanceUntilTheChunkIsCommittedso the two are each other's control: one shows the marker still advances when the caller commits, the other that it does not when the caller doesn't. A fix that broke either would pass the other.Merge note
origin/devmoved under this branch mid-work: #3001 merged, soPgLogTimezoneUnsupportedExceptionnow exists and the parse-throw path this defect was reported through is live rather than latent. #3001 touchedRdsDeadlockIngestor.csand conflicted; resolved keeping both its<exception>doc onIngestAsyncand its "not inside the tolerant catch" comment, the latter relocated with theExtractcall intoStoreAsyncand its cross-reference corrected.ARefusedLogTimezoneDoesNotAdvanceTheMarkerthen tests the real thing through the real parser and the real exception, rather than a stand-in.Also post-#3002:
RdsLogSource.cs's current copy is the one with named per-branch messages for an omitted AWS response collection.NewestLogFileAsyncstays total — no null path was reintroduced, and its?? throwis untouched.Verification
Darling.Testsisnet10.0-windowsand cannot run on macOS, so the real test files were compiled into a throwawaynet10.0xunit v3 host staged outside the repo tree,<Compile Include>-ing the repo paths with<AssemblyName>Darling.Tests</AssemblyName>forInternalsVisibleTo. 31 tests, 0 failed, 0 errors, 0 skipped, 0 not run. Full solution builds with 0 errors.In CI,
Darling.Testsgoes fromTotal: 7521ondev(406d6446) toTotal: 7535here —+14, matching the 14 tests added, withFailed: 0, Not Run: 0and none of them in the skip list (that list is entirely live-Postgres tests). Thebuildjob ran 495s, so it is not a no-op green.Red-first, one mutation at a time, restored byte-identical after each (source hash
42c7f89b…before and after both):Assert.Null(client.Downloads[1].Marker)→"MARKER-1"; and the refused-timezone test's text assertion returns the NEXT window instead of the lost oneCommitResumemade a no-opAssert.Equal("MARKER-1", client.Downloads[1].Marker)→nullRdsPlanIngestorcommits BEFOREStoreAsync(the shape a shared-helper refactor would produce)The two mutations kill disjoint sets of tests, which is the evidence the "did not advance" guards are not passing against a do-nothing implementation.
Not covered
Darling PostgreSQL testsjob is the arbiter for the live-store path.Two branches review might expect to be dead, and are not
NewestLogFileAsyncbecame total in #3002, so "RDS listed no PostgreSQL log file" now raises rather than returning a quiet empty chunk. That does not make either early return here unreachable, because they are about different things:chunk is nullis the non-RDS host case —RdsEndpoint.TryParsereturned null and no AWS call was made. Covered byANonRdsHostIsSkipped.string.IsNullOrEmpty(text)is an empty download response —DownloadDBLogFilePortionanswering a resumed read of a file with nothing appended. That is the ordinary quiet cycle, and it is the pathAQuietCycleAdvancesTheMarkerdepends on.Neither is the "no log file to open" case, and no null path was reintroduced in
NewestLogFileAsync.This PR touches no classification arm and no timing capture, so it adds no instance of the
0, 0, 0timing-field pattern in #3011.CHANGELOG entry text (not committed — for the coordinator to assemble)