Repository navigation
The Azure per-database split is stamped on the fault path but only printed on the success path #2896
Description
Split out of #2855 rather than forced into it, because fixing it means picking between two shapes and neither belongs in the change that added the split.
#2855 gave the Azure per-database branch a connect: + open: + drain: + other: split, with every stamp and the PerDatabasePhasesMeasured flag set from a finally. So a database whose connect times out, or whose read is cut by the per-database wall-clock budget, does stamp its phases and does declare itself measured — the #2854 discipline holds.
It just never prints them. The log site sits on the success path of the per-database try, after the flush:
if (context.PerDatabasePhasesFrom(dbSqlMs) is { } dbPhases)
{
_logger?.LogInformation(
" [{Server}] {Collector} [{Database}] sql:{SqlMs}ms = connect:{ConnectMs}ms + open:{OpenMs}ms + drain:{DrainMs}ms + other:{OtherMs}ms ({Rows} rows, pg:{PgMs}ms)",
...);
}A fault reaches one of the three catch arms instead — the budget arm's WARNING, or the generic arm's Skipping database '{Database}' for {Collector}: {Error} at Debug — and neither carries a phase. So the case the split exists to attribute, "this database is bound by connect", is the one case that still logs nothing but an error string.
Why it was not just added to the catch arms
The line decomposes dbSqlMs, and that parent is out of scope in the catch: sqlSlice is declared inside the try, below the watermark read and BuildQuery. Hoisting it above them would silently widen dbSqlMs, and dbSqlMs is not a log-only number — it feeds sqlMs, fanout.Observe(...), and collection_log.sql_duration_ms. Widening a persisted metric to make a log line reachable is the wrong trade.
The two options, and the thing that should decide
- A second stopwatch, started beside
connectWatchand hoisted above thetry, measuring the same intervalsqlSlicedoes. The catch arms then print the same line shape with a real parent. Cost: two stopwatches over one interval, and a reader has to be told why. - A second, parentless line shape from the catch arms —
connect:Nms + open:Nms + drain:Nms, nosql:N =prefix, noother:. Honest (the parent genuinely did not complete) and needs nothing hoisted. Cost: a second shape for the log parsers outside this repo to learn, which is the objection query_store: plan_fetch and text_fetch are whole methods spanning two databases, timed as one number #2811/Phase split (wm/open/drain) is not emitted for server-scoped collectors, so the largest collector on the fleet cannot be attributed #2851 kept deferring to.
What should decide it is how often the fault path is actually taken. If per-database failures on this branch are rare, option 2's parser cost buys little and option 1's second stopwatch is over-engineering for a line nobody reads. If they are routine — an offline database, a mid-restore one, a genuinely slow login on a large Azure database — then this is the common case rather than the edge, and option 1 is worth it. That is answerable from collection_log on a store that monitors Azure targets, by counting the notes the per-database partial-failure path composes (N of M database(s) failed) against total runs for the collectors that take this branch. Worth measuring before choosing.
Note also that the generic arm is Debug, so on a default log level a per-database failure is invisible whatever is added to it. Whether that arm should stay Debug is part of the same question — one database failing is genuinely routine, which is why it is Debug, but "routine and therefore silent" is how a database that has been failing every cycle for a week goes unnoticed.
Not this issue
Persisting the split is separate and already open as #2860 (N:1 against collection_log). This one is only about whether the fault path prints what it already measured.
Activity
Point #2855's pin file at #2896's, instead of claiming there is no fa…
Merge pull request #2922 from erikdarlingdata/fix/2896-azure-fault-pa…
erikdarlingdata commentedon Sep 4, 2026
Fixed by #2922, merged to
dev.This issue's title understates its reach, and that changes the priority. The branch is not Azure-only:
RunsPerDatabaseis engine-unconditional (=> true;) for seven PostgreSQL collectors —pg_index_bloat,pg_index_usage_stats,pg_table_bloat_stats,pg_autovacuum_stats,pg_column_stats,pg_predicate_stats,pg_extension_availability. They reach this identical loop, with the same three catch arms and the same stamps, on every PostgreSQL target, every cycle. One connection per database per cycle is exactly whatconnect:exists to name.The Azure arm itself has run zero times: all 84 SQL Server targets are RDS, and RDS does not host Azure SQL DB — confirmed on probed members as
engine_edition = 3withservice_objectiveNULL, which is the shipped collector's own witness sinceServerPropertiesCollectorpopulates that column onlyWHEN EngineEdition = 5. So the fault-path frequency is zero on the SQL Server fleet by construction rather than by sampling, and unmeasured on the PostgreSQL fleet.The obvious fix was unsound, not merely expensive
A second stopwatch started above the
trymeasures a wider interval thansqlSlice— andPerDatabaseOtherMsFrom's own contract states the watermark read andBuildQuerysit outside the parent. So itsother:would mean something different from the success line's, under the same name. That is worse than the cost objection it was raised to avoid.What shipped is a third option: only the declaration moved above the
try; the start stays on the same statement. Same interval, one stopwatch, anddbSqlMsis byte-identical — verified as exactly onesqlMs += dbSqlMsand onefanout.Observe(databaseName, dbSqlMs + dbStorageMs), both on the success path past the flush, each pinned at 1 with a positive control. Nothing persisted was widened to satisfy a log requirement.A latent hazard nobody asked about
#2855's per-iteration clear sat below the stopwatch. A fault in the watermark read, the adaptive-shrink store write, or
BuildQueryreaches the catch arms without passing it — holding the previous database's flag and stamps. Reading the split there would have attributed one database'sconnect:to another. Moved to the top of thetry, which also makes the flag a sufficient gate rather than a necessary one.The review found a real defect that was missed
sqlSlicewas never stopped. It kept accruing past thedbSqlMscapture throughWriteBatchAsync— which runs oncancellationTokenand therefore can throw into these arms. A flush-time fault would print asql:larger than thedbSqlMsalready folded intosqlMsandfanout.Observe, with the entire difference landing inother:, because connect/open/drain are fixed by theirfinallyblocks. That is storage latency reported as SQL-side residual — precisely the mis-attribution this instrumentation exists to prevent. Fixed withsqlSlice.Stop()before the read, and pinned three further ways.The
Debuglevel stays, and the reasoning is the useful partRaising it would add no signal that is not already persisted.
BuildPartialFailureNoteis what makes a week-long failure visible — it lands "N of M database(s) failed" plus three names and the first error intocollection_log.error_message, surfaced byget_collection_healthaslast_note/note_count. A total loss is already Warning plus rethrow, reaching Capture Down. Raising this arm would emit one Warning per database per cycle per collector, which is the flood #1875's one-capped-burst rule exists to stop. The split rides its arm instead: Warning beside the budget arm, Debug beside the skip.Verification
Twelve mutations red, each failing a different assertion, each with its anchor count asserted at 1 before the result was trusted — and a thirteenth attempt is deliberately not counted because it failed to compile: a mutation that does not build proves nothing.
3,938 string literals across
Darling.TestsandLite.Teststhat matched the pre-change runner were checked against the post-change tree: zero disarmed, with a positive control proving the comparison detects a removal.CollectorContext.csis untouched, soServerScopePhaseSplitTests' derived set is byte-identical and neitherMinimumPhaseStamps = 16norMinimumMeasuredFlags = 2needed raising. Test count in Windows CI moved by exactly 13, matching the thirteen facts.Not measured
The PostgreSQL fault-path rate. The Aurora store was unreachable from the working session, so how often these arms are actually taken in production is open — and given the branch runs every cycle there, that is the number that would size this. No live target has exercised the emission: the Azure arm has never run, and the PostgreSQL arm's line shape in production is unverified.
Emit the per-database phase split on the fault path (erikdarlingdata#…
CHANGELOG for erikdarlingdata#2896