Skip to content

The target log tail no longer picks the csvlog/jsonlog sibling over the stderr log (#3997) - #4025

Merged
erikdarlingdata merged 4 commits into
devfrom
fix/3997-log-tail-stderr-sibling
Sep 23, 2026
Merged

erikdarlingdata merged 4 commits into
devfrom
fix/3997-log-tail-stderr-sibling

Conversation

@erikdarlingdata

Copy link
Copy Markdown
Owner

Closes #3997.

Why

The shared log tail (PgServerLogTail.TailCteSql) that pg_log_events, pg_deadlocks and pg_plan_capture
all open with picked the newest file in log_directory by modification time alone, whatever its extension. A
target whose log_destination includes csvlog or jsonlog writes every message to a second file beside
the stderr one, and pg_ls_logdir()'s modification is a stat mtime with no ordering guarantee between two
files written the same instant.

Measured live on a fresh PostgreSQL 18.6 instance started with log_destination = 'stderr,csvlog': the
sibling pair (postgresql-<ts>.log / postgresql-<ts>.csv) carried the identical modification instant,
confirming the issue's "when both carry the same timestamp the pick is arbitrary" concern is real, not
theoretical. When the sibling won, none of the three stderr-format parsers matched anything in it, so a cycle
silently read as quiet instead of misread.

What changes

  • PgServerLogTail.TailCteSql's newest CTE now excludes .csv/.json names (AND name !~* '\.(csv|json)$'),
    mirroring StoreLogSweep.IsStderrLogFile's existing rule for the store's own log sweep - one rule for "is
    this file stderr-format" instead of two that could drift.
  • A new PgNoStderrLogFileException / PgServerLogTail.NoStderrLogFileMarkerSql name the narrower case where
    logging_collector is on but the exclusion above leaves newest empty. All three collectors append it as a
    second UNION ALL marker arm beside the existing logging_collector = off one (mutually exclusive by
    construction - one requires the setting off, the other on), and DarlingWorker.cs classifies it the same
    non-fatal PERMISSIONS way as the existing PgLoggingCollectorOffException arm, so it never inflates the
    error counts collector health, the daily band and self-alerts read.
  • The RDS log route (RdsLogSource.NewestLogFileAsync) had the identical bug: DescribeDBLogFiles returns
    both the stderr file and its .csv/.json siblings under the same FilenameContains = "postgresql"
    filter, and OrderByDescending(LastWritten) alone could pick either. Same fix: exclude both suffixes before
    taking the newest.

A measured scope note, found while live-testing the "csvlog-only" case

PgNoStderrLogFileException's NOT EXISTS check is correct for a directory with literally zero non-csv/json
files, but that is narrower in practice than "this target has never had stderr configured": PostgreSQL's
syslogger writes one small stderr-format "breadcrumb" file (LOG: ending log output to stderr / HINT: Future log output will go to log destination "csvlog", measured at 170 bytes) the moment it determines stderr is not
among the final destinations - even on a target started with log_destination = 'csvlog' from its very first
start. newest finds that file, so the exception under-fires in the most common real-world case; the three
collectors instead read it every cycle and match nothing.

Recognising a breadcrumb-only file as equivalent to none needs a design call (a size heuristic risks a false
positive on a genuinely quiet but real stderr target; a text match on the breadcrumb inherits the same
lc_messages translation blind spot pg_plan_capture_readiness's message_locale facet already tracks), so
I filed #4019 with the full measurement rather than guessing at a threshold. The exclusion fix in this PR (the
issue's actual, explicitly-scoped ask) stands on its own regardless of #4019's outcome.

Lite

Lite does not read PostgreSQL logs at all - no SQL Server equivalent to gate, no Lite-side change needed. The
PerformanceMonitor.Collectors project is shared, so Lite.Tests carries this fix's tests (marker recognition
in PgLoggingCollectorGateTests), same as the existing logging_collector = off coverage there.

Test plan

  • TheTailerExtraction_LeftBothSiblingsSqlByteIdentical (PgLogEventsPipelineTests) updated deliberately
    for the new newest CTE text and the second marker arm on all three collectors; reverting either
    change (proved twice, separately) makes it fail.
  • New marker-recognition tests: ThePlanReadRefusesTheNoStderrMarkerRow /
    TheDeadlockReadRefusesTheNoStderrMarkerRow (Lite.Tests/PgLoggingCollectorGateTests), the events
    collector's equivalent in PgLogEventsPipelineTests, and Worker_Records_A_NoStderrLogFile_As_Permissions_Not_Error
    (PgLoggingCollectorOffTests) pinning the DarlingWorker.cs classification arm.
  • New RDS-route regression: ACsvlogSiblingWrittenLater_DoesNotWinOverTheStderrFile (RdsLogSourceTests) -
    fails on the pre-fix shape (proved by reverting the filter).
  • Live test against a real rig (PostgreSQL 18.6, logging_collector = on,
    log_destination = 'stderr,csvlog', log_line_prefix = '%m [%p] %Q '):
    PgLogTailStderrSiblingLiveTests.TheSharedTail_ReadsTheStderrFile_AndAllThreeFamiliesStillFindTheirEntries
    provokes a real plan (auto_explain), a real duplicate-key log event and a real two-session deadlock, then
    runs the actual production BuildQuery()/ReadAsync() for all three collectors against the same target
    (which has both the .log and .csv files, same-second mtime) and confirms all three find their entry
    from the stderr file.
  • Targeted run: 60 tests, 0 failures (PgLogEventsPipelineTests, PgLoggingCollectorOffTests,
    RdsLogSourceTests, PgLogTailStderrSiblingLiveTests).
  • Full suite, merged with origin/dev (which landed Plan capture keeps working under a custom log prefix with fields before the pid (#4008 follow-up) #4016's plan-capture regex fix and raw_line_hash and statement_fingerprint are unkeyed hashes a store reader can use to guess the literals they hide #4004's keyed log
    hashes while this branch was in flight - both reconciled in the merge):
    - Darling.Tests: 13028 total, 2 failed, 31 skipped. Both failures are pre-existing and unrelated -
    CollectionLogDrainForensicsStoreTests.ThePeerMarkIsCapturedAtDispatchNotAtCompletion (an off-by-one
    count) and StoreSelfMetricsTickRecoveryLiveTests.AFailedStoreLogCapture_... (a connection-recovery
    test matching the known "Connection is not open" flake pattern) - confirmed by re-running each alone;
    neither touches this PR's files.
    - Lite.Tests: 5178 total, 0 failed.

Issues filed

🤖 Generated with Claude Code

https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv

erikdarlingdata and others added 3 commits September 23, 2026 07:47
…e gap when no stderr file survives (#3997)

The shared tail three PostgreSQL collectors read (pg_log_events, pg_deadlocks, pg_plan_capture) picked
the newest file in log_directory regardless of extension. A target logging to both stderr and csvlog/jsonlog
writes every message to two files with the same modification instant, so the pick between them was
arbitrary - and a cycle that picked the sibling read nothing a stderr-format parser recognizes, reporting a
quiet target instead of a misread one.

The newest CTE now excludes .csv/.json siblings, mirroring StoreLogSweep.IsStderrLogFile. A second marker
(PgNoStderrLogFileException) names the narrower case where logging_collector is on but no stderr-format file
survives that exclusion, classified the same non-fatal way as the existing logging_collector=off case. The
RDS log route had the identical bug (DescribeDBLogFiles' newest-by-LastWritten pick) and gets the same fix.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv
Resolved TheTailerExtraction_LeftBothSiblingsSqlByteIdentical's plan-capture pin: kept dev's #4016 regex
fix (tolerates a prefix token before the pid bracket) and layered this branch's second UNION ALL marker
arm on top of it, rather than reverting to the pre-#4016 pattern.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv
…4004 follow-up, #3997)

PgLogEventsCollector.BuildQuery now refuses without CollectorContext.LogHashKey, per #4004 merged from
dev after this branch started. Missed in the merge resolution; caught by re-running this test against
the live rig.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv
@erikdarlingdata
erikdarlingdata enabled auto-merge (squash) September 23, 2026 12:07
…enth early-return fault arm

The new PgNoStderrLogFileException arm in DarlingWorker drains nothing and
fetches nothing, so it passes drain: null and fetchPhases: null like the
logging_collector-off arm beside it. Both counted pins move from 10 to 11,
with the arm named in the comment.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv
erikdarlingdata added a commit that referenced this pull request Sep 23, 2026
…e pin and census tests read the files it changed (#4027)

#4025's lane called CollectionLogDrainForensicsStoreTests pre-existing
because it reproduced alone. It reproduced because the test counts
DarlingWorker's fault arms and the lane had added one; dev's CI passed it.


Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv

Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@erikdarlingdata
erikdarlingdata merged commit 7406368 into dev Sep 23, 2026
15 of 16 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/3997-log-tail-stderr-sibling branch September 23, 2026 12:21
erikdarlingdata added a commit that referenced this pull request Sep 23, 2026
…ntries in their sections (#4080)

Adds 42 entries and 42 link refs (#3992, #3995, #3996, #3998, #4001, #4002, #4003, #4007, #4010, #4011, #4013, #4015, #4020, #4022, #4025, #4029, #4030, #4031, #4036, #4038, #4039, #4040, #4044, #4047, #4048, #4049, #4050, #4051, #4055, #4061, #4063, #4064, #4065, #4066, #4067, #4068, #4069, #4070, #4071, #4073, #4074, #4078). Each PR's entry was buffered, and this lands every entry whose PR was merged on origin/dev when it ran.

#3989 left 26 entries under bare 'Changed' and 'Fixed' lines above '### Added'. They move into '### Changed' and '### Fixed', below the new entries, and one blank line stays under [Unreleased].


Claude-Session: https://claude.ai/code/session_01Ua31ugERL5DmhFVRtf6keQ

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant