Skip to content

Log self-alert firings, and enable TimescaleDB job audit logging (#1681) - #1685

Merged
erikdarlingdata merged 4 commits into
devfrom
feature/1681-log-selfalert-firings
Jul 26, 2026
Merged

erikdarlingdata merged 4 commits into
devfrom
feature/1681-log-selfalert-firings

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Jul 26, 2026 •

Copy link
Copy Markdown
Owner

Closes #1681. Two halves of the same field finding from prod-sql-use2-monitor-01: a compression job stuck 9 times in 6 days, and neither the service log nor the database could say anything useful about it.

Half 1 — the log showed recoveries but never firings

RecordResolutionAsync had always logged at Information. The firing path called _deliverer.DeliverAsync with no logger call at all. So the service log showed:

Compression Job Recovered

with nothing before it — a spontaneous recovery from a condition that never appeared. That is worse than logging neither half, because it reads as noise rather than a missing pair.

Verifying it showed the gap is not compression-specific. Every self-alert went through that same silent path: disk pressure, capture-down, agent-not-running, collection-health. All of them fire silently and only announce themselves on the way out.

Firings now log at Warning — a firing self-alert means something is wrong with the monitor itself, and it has to stand out from the Information-level recovery it will eventually pair with.

Muted alerts log too, flagged [muted]. Muting suppresses the notification channels, not the operator's ability to find the event afterwards; suppressing both would make a muted condition invisible everywhere at once.

Half 2 — there was no job audit trail to diagnose from

timescaledb.enable_job_execution_logging is off by default. On the field store that meant timescaledb_information.job_errors and job_history returned zero rows for every job — including jobs with dozens of confirmed successful runs. No captured error, no worker PID, no start/finish record.

That is why the hang still has no confirmed root cause, and why the next occurrence would have been equally opaque. Now enabled in the managed conf append. Rows are written once per job run, not per row processed.

What this does not do

It does not fix the hang. The working hypothesis — lock contention between high-volume inserts and the compression job's attempt to lock the just-closed chunk on the same table, given it only ever hits the two highest-write hypertables and never the other 35 — remains unconfirmed, because the evidence to confirm it did not exist. Half 2 is what makes the next occurrence diagnosable.

Auto-heal is 9-for-9 with no compression backlog, so this was not urgent; the alert text itself notes the re-arm budget is finite and eventually escalates instead.

Test plan

The harness now passes a real capturing logger to every self-alert test rather than null, so the added logging is exercised by the whole existing suite rather than only by the two new assertions — which cover that a firing logs at Warning, and that a muted firing still logs, flagged.

  • Darling.Tests: 3129 passed, 0 failed (149 gated-live skipped)
  • Solution builds 0 warnings, 0 errors

🤖 Generated with Claude Code

erikdarlingdata and others added 4 commits July 26, 2026 11:38
Two halves of the same field finding: a compression job stuck 9 times in 6 days
on prod-pos-use2-monitor-01, and neither the service log nor the database could
say anything useful about it.

RecordResolutionAsync had always logged at Information while the firing path
called the deliverer with no logger call at all. So the log showed "Compression
Job Recovered" with nothing before it -- a spontaneous recovery from a condition
that never appeared, which is worse than logging neither half. Verifying it
showed the gap was not compression-specific: every self-alert went through that
same silent path, including disk pressure, capture-down, agent-not-running and
collection-health.

Firings now log at Warning. Warning rather than Information because a firing
self-alert means something is wrong with the monitor itself, and because it has
to stand out from the Information-level recovery it will eventually pair with.
Muted alerts log too, flagged: muting suppresses the notification channels, not
the operator's ability to find the event afterwards -- suppressing both would
make a muted condition invisible everywhere at once.

The second half is why that hang still has no confirmed cause.
timescaledb.enable_job_execution_logging is off by default, so
timescaledb_information.job_errors and job_history returned zero rows for EVERY
job on that store -- including jobs with dozens of confirmed successful runs.
No captured error, no worker PID, no start/finish record. Now enabled in the
managed conf append; rows are written once per job run, not per row processed.

The test harness now passes a real capturing logger to every self-alert test
rather than null, so the added logging is exercised by the whole existing suite,
not just the two new assertions.

Darling.Tests 3129 passed; solution builds 0 warnings.

Closes #1681

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The previous resolution handled only the first hunk and pushed with a marker
still in the file. Both sides added a bottom link-ref; keeping both.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@erikdarlingdata
erikdarlingdata merged commit 14c96ed into dev Jul 26, 2026
4 checks passed
@erikdarlingdata
erikdarlingdata deleted the feature/1681-log-selfalert-firings branch July 26, 2026 16:45
pull Bot pushed a commit to ehtick/PerformanceMonitor that referenced this pull request Jul 29, 2026
…ikdarlingdata#1681)

AUDITED FIRST, because erikdarlingdata#1685 already landed half of this and the brief warned
about stacking duplicates. What was actually left:

  Darling self-alerts    fired LOGGED (erikdarlingdata#1685)   resolved LOGGED   symmetric, done
  Shared engine (x9)     fired SILENT           resolved LOGGED   ASYMMETRIC
  Lite connection alert  fired SILENT           resolved toast    no log at all
  Lite AG alerts         fired SILENT           resolved toast    no log at all
  Lite engine alerts     fired SILENT           resolved toast    no log at all

So the issue's own complaint - "Recovered with no preceding event" - was still
true for the nine ENGINE families in Darling, where the resolution callback logs
at Information and the firing logged nothing. erikdarlingdata#1685 fixed the self-alert
evaluator, which is a different path. Lite logged neither half anywhere, so an
operator reading Lite's log file after the fact found no alert history at all;
its resolution toast is transient and reaches no log.

Fixed at each app's real choke point, deliberately NOT by adding a second log to
a path that already has one:

- AlertEngine gains a FireAsync funnel and all NINE families route through it.
  They previously each built an outcome and called the deliverer directly, which
  is exactly how they all ended up silent together. Shared code, so Darling and
  Lite both get it from one change. It logs BEFORE delivering: delivery does I/O
  and swallows its own failures, so logging afterwards would lose the record of
  an alert whose delivery hung - which is the alert someone later goes looking
  for.
- Lite's connection and AG senders bypass both the engine and Darling's
  evaluator, so they log at their own send sites.
- Lite's resolution callback now logs the RESOLVED half, which it never did.
- Darling's self-alert firing log is NOT duplicated. It stays where erikdarlingdata#1685 put
  it; self-alerts do not pass through the engine, so there is no overlap.

The line shape is one definition (AlertFiringLog in Notifications, not Common -
Alerting already references Notifications, and a new ProjectReference would drag
in the locked-lockfile regeneration). Both halves carry server and metric so one
server's story greps together, and both spell out TRIGGERED / RESOLVED so they
are distinguishable without knowing how each app maps severity to log level -
which matters because the two halves are written at different levels by
different code paths in two different apps. Darling's existing lines were routed
through the same formatter so all paths read identically.

A muted alert still logs, flagged. Muting suppresses the notification CHANNELS,
not the operator's ability to find the event afterwards; suppressing both is how
a muted-and-forgotten alert becomes an outage nobody can reconstruct.

Tests: the fired/resolved symmetry matrix, duplicated verbatim into both suites
so neither app's format can drift alone. Plus a regression guard that scans
AlertEngine and fails if ANY direct deliverer call survives outside the funnel -
a source scan rather than a behavioral test on purpose, because the way a tenth
family skips the log is by copying an existing block, and "the ones I knew about
are fixed" would not catch that.

Suites green: Darling 3363, Lite 1579, Dashboard 768.

Closes erikdarlingdata#1681

Co-Authored-By: Claude Fable 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