Repository navigation
4053 part b2: pg_plan_capture reads csvlog when it's on (self-hosted) - #4137
Merged
Merged
Conversation
erikdarlingdata
force-pushed
the
fix/4053-csvlog-plan-capture
branch
from
September 24, 2026 05:25
70b78f6 to
6cb4a12
Compare
This was referenced Sep 24, 2026
Adds the csvlog branch to PgPlanCaptureCollector: BuildQuery sends the csv statement pair (PgServerLogTail.TailCsvCteSql/TailCsvCteBinarySql) when context.PgLogUsesCsvlog is set, and ReadAsync dispatches to a new ReadCsvAsync that runs PgServerLogCsvParser.Parse on the raw body and keeps only records whose Message is an auto_explain duration-plan message. The stderr statements are untouched.
…measurement-label gate reads
… the log format for it and its no-file fault can invalidate the verdict
… count a plan-less duration record as forged
erikdarlingdata
force-pushed
the
fix/4053-csvlog-plan-capture
branch
from
September 24, 2026 05:44
7481f10 to
e1f5263
Compare
erikdarlingdata
marked this pull request as ready for review
September 24, 2026 05:44
erikdarlingdata
enabled auto-merge (squash)
September 24, 2026 05:44
erikdarlingdata
added a commit
that referenced
this pull request
Sep 24, 2026
…ut was missed #4137 (pg_plan_capture reads csvlog) merged at 05:57Z with a CHANGELOG entry section in its body. It was neither spliced nor listed as needing no entry. Its entry goes under Fixed, right after #4136's, and #4136's last sentence now points to it instead of saying plan capture is unchanged. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01NUU29PuGg9TUFBsACgZg2K
erikdarlingdata
added a commit
that referenced
this pull request
Sep 24, 2026
* Add 48 buffered CHANGELOG entries in one splice Adds 48 entries and 48 link refs (#4057, #4077, #4079, #4081, #4082, #4083, #4084, #4085, #4086, #4087, #4088, #4089, #4090, #4091, #4092, #4093, #4095, #4096, #4099, #4100, #4101, #4103, #4105, #4106, #4107, #4108, #4109, #4110, #4111, #4113, #4114, #4115, #4116, #4117, #4118, #4119, #4120, #4121, #4122, #4123, #4124, #4125, #4126, #4127, #4131, #4133, #4136, #4141). Each PR's entry was buffered, and this lands every entry whose PR was merged on origin/dev when it ran. Entries found under a bare section line (none unless the old script ran again) move into the matching ### section, below the new entries. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01QQh8LczP1HGLXQYAx4oTZC * Changelog splice: add #4137's entry, which merged before the splice but was missed #4137 (pg_plan_capture reads csvlog) merged at 05:57Z with a CHANGELOG entry section in its body. It was neither spliced nor listed as needing no entry. Its entry goes under Fixed, right after #4136's, and #4136's last sentence now points to it instead of saying plan capture is unchanged. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01NUU29PuGg9TUFBsACgZg2K --------- Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
erikdarlingdata
added a commit
that referenced
this pull request
Sep 24, 2026
…ql innermost-frame parse - CollectorMeasurementSeamTests: add PgDeadlocksCollector.RaiseShapedDeadlocksSkippedMeasurement to the fixed label list (review round 1, critical item). - PgPlanCaptureCollector.PlanRowsFromCsvEntries: move the RAISE-shaped provenance guard BELOW the no-plan-text (msIndex < 0) skip, so a genuine log_min_duration_statement/log_duration record under verbose logging is skipped uncounted rather than counted as forged (review round 1 of #4137's ruling). Add a unit test for that ordering. - ForgedCaptureNote: name RAISE-shaped captures explicitly. - PgLogEntryProvenance.RaisedByPlpgsql: replace the first-physical-line " at RAISE" suffix test with a quote-aware parse of the innermost Context frame (function signature or inline_code_block, then " line N at KIND"), closing the bypass where a quoted function name containing a newline or " line 1 at SQL statement"-shaped text could defeat the old first-line split. Part of #4058.
erikdarlingdata
added a commit
that referenced
this pull request
Sep 24, 2026
…#4153) * PgLogEntry: carry the reporting function Location (#4058 plumbing) * 4058 r2: PgLogEntryProvenance, the RAISE-shaped/reported-by-other check * 4058 r2: IsRaiseShaped guards for deadlocks and plan captures * 4058 r2: RDS deadlock ingestor counts and skips RAISE-shaped entries * 4058 r3: PgLogEntryProvenanceTests (RaisedByPlpgsql/ReportedByOther units) * 4058 r3: FromEntry/IsRaiseShaped units + csvlog raise-shaped-skipped test * 4058 r3: PlanRowsFromCsvEntries raise-shaped-vs-real unit tests * 4058 r3: RDS deadlock ingestor raise-shaped-skipped unit test * 4058 live: RAISE-shaped deadlock and plan-capture records are not stored Adds Darling/Darling.Tests/PgRaiseShapedRecordsLiveTests.cs, gated on DARLING_TEST_PG_CSVLOG, proving against the collectors' own csv statement plus ReadAsync: 1. A PL/pgSQL RAISE EXCEPTION shaped as a deadlock (message, DETAIL, ERRCODE 40P01) is skipped by PgDeadlocksCollector and counted under raise_shaped_deadlocks_skipped. 2. A REAL deadlock inside a function frame still comes out, matched to the victim's own pg_backend_pid(). 3. A PL/pgSQL RAISE LOG shaped as an auto_explain plan capture is skipped by PgPlanCaptureCollector and counted under forged_captures_skipped. * 4058 review round 1: seam list, provenance-guard order, RaisedByPlpgsql innermost-frame parse - CollectorMeasurementSeamTests: add PgDeadlocksCollector.RaiseShapedDeadlocksSkippedMeasurement to the fixed label list (review round 1, critical item). - PgPlanCaptureCollector.PlanRowsFromCsvEntries: move the RAISE-shaped provenance guard BELOW the no-plan-text (msIndex < 0) skip, so a genuine log_min_duration_statement/log_duration record under verbose logging is skipped uncounted rather than counted as forged (review round 1 of #4137's ruling). Add a unit test for that ordering. - ForgedCaptureNote: name RAISE-shaped captures explicitly. - PgLogEntryProvenance.RaisedByPlpgsql: replace the first-physical-line " at RAISE" suffix test with a quote-aware parse of the innermost Context frame (function signature or inline_code_block, then " line N at KIND"), closing the bypass where a quoted function name containing a newline or " line 1 at SQL statement"-shaped text could defeat the old first-line split. Part of #4058. * 4058: a function named inline_code_block is parsed as a signature, not a DO block (its RAISE failed open); the innermost-frame parser's unit tests * 4058 review round 2: remarks say innermost frame, that terse logging loses both signals, and that a translated lc_messages fails open; a genuine duration record's Location is exec_simple_query/exec_execute_message
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Part of #4053 (plan capture on csvlog; depends on #4124)
What changed
PgPlanCaptureCollectornow readsauto_explainplans out of a.csvlog file when the target'slog_destinationincludescsvlog— the same flagPgLogEventsCollectoralready reads for its own csvlogbranch (
context.PgLogUsesCsvlog, from #4124). Three pieces:BuildQuerysends a new csv statement pair —CsvQueryText/CsvBinaryQueryText, opened onPgServerLogTail.TailCsvCteSql/TailCsvCteBinarySql— instead of the existing stderr pair, oncecontext.PgLogUsesCsvlogis set. The two existing stderr statements are byte-identical to before thischange; only the new csv pair is added. Their marker arm carries
PgNoCsvlogFileException.Marker(not
PgNoStderrLogFileException.Marker), so the fault this route throws names csvlog rather thanstderr, matching
PgLogEventsCollector's own csv branch.ReadAsyncdispatches to a new privateReadCsvAsyncwhencontext.PgLogUsesCsvlogis set. It:PgLogEventsCollector's csv branch does (PgBinaryTailText.DecodeWhole);PgServerLogCsvParser.Parseon the raw body (the shared csvlog parser from Wire the csvlog parser into pg_log_events on the self-hosted route (#4053 part a1b) #4124/part a1);Messagestarts with a csvlog-specific plan marker literal. Verified on alive pg18 rig with
logging_collector=on,log_destination=csvlog,auto_explainloaded: csvlogcarries severity in its own column, never glued onto
Messagethe way the stderr route'slog_line_prefixglues"LOG: "on — a captured record's message readsduration: N ms plan:\n{json}, notLOG: duration: N ms plan:\n{json}. The marker literal usedhere (
PlanMarkerCsvLiteral = "duration: ") is the stderr literal minus that head.query_idcolumn (the last of the 26 fields, PG14+) rather thanparsing any prefix text — csvlog carries no
%Q-rendered prefix at all;chain (
^[0-9]{1,15}(\.[0-9]{1,9})?$, done in C# ass_csvDurationShape), so a duration shaped like1.2.3is skipped and counted rather than trusted to double.TryParse's more permissive grammar;PgPlanLogParser.FromBlock, the same redaction and hashing pathboth existing transports use.
forged_captures_skippedmeasurement; a record the csv parser itself discarded (a resync fragment orbad shape) is counted under
csv_records_discarded, reusingPgLogEventsCollector.CsvRecordsDiscardedMeasurement's exact label.Tests:
PgPlanCaptureCsvUnitTests(new, Darling.Tests): a FakeReader over the csv statement's two columns.One real auto_explain csvlog record (captured live, put into a
const stringfixture, not pasted intoprose) → one row with the right query id and duration, redacted; a quoted user field carrying a
forged newline plus a fake plan-shaped line → no extra row; a duration shaped
1.2.3→ skipped andcounted under
forged_captures_skipped; the no-csvlog-file marker → throwsPgNoCsvlogFileException.PgPlanCaptureCsvLiveTests(new, Darling.Tests): gated onDARLING_TEST_PG_CSVLOG_AUTOEXPLAIN. Runs areal query over the threshold against a rig started with
logging_collector=on,log_destination=csvlog, setscontext.PgLogUsesCsvlog = truedirectly, runs the csv statement plusReadAsyncthrough both the text and binary route, and asserts one plan row for that query.What I ran
dotnet buildonPerformanceMonitor.CollectorsandDarling.Tests: clean, 0 warnings/errors.dotnet buildonLite.Tests: clean (execution is CI's, per the Mac rig note — WPF).Darling.Tests.dll -class Darling.Tests.PgPlanCaptureCsvUnitTests):Total: 4, Failed: 0.PgLogEventsPipelineTests+PgServerLogCsvParserTests(untouched files this branch reuses):Total: 73, Failed: 0.timescale/timescaledb:2.28.1-pg18rig(
docker run ... -c logging_collector=on -c log_destination=csvlog -c compute_query_id=on -c shared_preload_libraries=timescaledb,auto_explain -c auto_explain.log_min_duration=0), both the text andbinary (
pg_read_binary_file) route:Total: 1, Failed: 0. Container removed before this push.Darling.Tests.dllrun (no filter,DARLING_TEST_PG*unset):Total: 13421, Failed: 215, Skipped: 717. Every failure is in the known Windows-only set this Mac rig cannot run (ViewerHistoryWindowTests,ViewerDrillDownTests,ViewerSettingsTests,ViewerConfigDiagnosticsTests,ViewerServerSummaryDisplayTests,DarlingInstallLocationTests,DarlingFileSecurityTests,DarlingRuntimePreflightTests,DarlingConfigTests.ConnectionString_MirrorsLitePosture_Integrated) — 215vs the brief's quoted 214 baseline, no new class outside that set, and nothing in
PgPlanCapture*/PgLogEvents*/PgServerLogCsvParser*failed.scrubcheckon the staged diff:0 hit(s), 17/17 controls firedbefore commit.What I did NOT verify
C#-side
s_csvDurationShapepluslong.TryParse, not a SQL CASE chain like the stderr route, sincecsvlog's own
query_idcolumn is already a well-typed bigint from PostgreSQL — there is no forged-prefixtext to guard against on that column the way stderr's
%Qneeds guarding).timescale/timescaledb:2.28.1-pg18image); the csv statement sharesPgServerLogTail's CTEs unmodified,which Wire the csvlog parser into pg_log_events on the self-hosted route (#4053 part a1b) #4124's own tests already cover across versions.
Coordinator verification (branch head e1f5263, rebased onto dev after #4136)
pg_plan_capturetoPgLogFormatCapability.RoutedCollectors, so the runner probes the log format for it and its no-file fault can clear the cached verdict.PgReadBinaryFileCapabilityTestsexpects 2 probes for it.log_min_duration_statementorlog_durationrecord) is skipped without being counted as forged. Before,forged_captures_skippedgrew with every slow statement.PgPlanCaptureCsvUnitTestspasses (6/6).query_idcolumn (0 is stored, as on stderr), the duration guard, taking the plan JSON from the message field, and the discard accounting. The stderr route's byte-pinned SQL is untouched.PgPlanCaptureCsvLiveTestspasses (1/1) at this head: a real Seq Scan plan row on both read routes. Before the review fix, the deadlocks and log-events live classes also passed on one rig.CHANGELOG entry
pg_plan_capturenow readsauto_explainplans from a.csvlog file when the target'slog_destinationincludescsvlog, in addition to the existing plain-textstderrroute (Postgres log readers: read csvlog/jsonlog when a target writes them, so a client can't forge a line through %u/%d (#4046 part 2) #4053).