mathias/hyperguild
1
0
Fork 0
Code Issues 30 Pull Requests 3 Actions Packages Projects Releases Wiki Activity

symlinkguard: a hung ntfy delays symlink removal (alert flush runs in the scan goroutine) #164

New Issue
Closed
opened 2026-10-03 16:33:02 +00:00 by mathias · 3 comments
mathias commented 2026-10-03 16:33:02 +00:00
Owner
Copy Link
Copy Source

Found in the PR #160 round-3 review (head 4ba9d20). I judged it non-blocking there and am recording it here so it isn't lost.

symlinkguard.Watch scans, removes links and flushes alerts in a single goroutine. alertQueue.flush tries every queued message, plus the summary, on each tick, and audit.NtfyNotifier has a 10 s HTTP timeout. Picture an ntfy that accepts connections but never answers (stuck pod, sqlite lock), with a full queue. One flush can then block for about 6 × 10 s = 60 s. During that time no scan runs, so a planted symlink stays readable for up to about 90 s, not the documented "at most one interval" of 30 s.

Repro (executed, scaled down): interval 50 ms, notifier latency 40 ms, queue full. The worst link lifetime was 244 ms, about 5 intervals.

A fast failure (connection refused, 5xx) does not trigger this. Only a hung connection does.

Fix options:

  • Stop the flush at the first non-permanent failure. During an outage, one attempt per tick is enough.
  • Or run delivery in its own goroutine, so removal never waits on the alert channel.

Done when: a test with a slow notifier and a full queue shows link lifetime ≤ interval + one scan.

Found in the PR #160 round-3 review (head 4ba9d20). I judged it non-blocking there and am recording it here so it isn't lost. `symlinkguard.Watch` scans, removes links and flushes alerts in a single goroutine. `alertQueue.flush` tries every queued message, plus the summary, on each tick, and `audit.NtfyNotifier` has a 10 s HTTP timeout. Picture an ntfy that accepts connections but never answers (stuck pod, sqlite lock), with a full queue. One flush can then block for about 6 × 10 s = 60 s. During that time no scan runs, so a planted symlink stays readable for up to about 90 s, not the documented "at most one interval" of 30 s. **Repro (executed, scaled down):** interval 50 ms, notifier latency 40 ms, queue full. The worst link lifetime was 244 ms, about 5 intervals. A fast failure (connection refused, 5xx) does not trigger this. Only a hung connection does. **Fix options:** - Stop the flush at the first non-permanent failure. During an outage, one attempt per tick is enough. - Or run delivery in its own goroutine, so removal never waits on the alert channel. **Done when:** a test with a slow notifier and a full queue shows link lifetime ≤ interval + one scan.
mathias commented 2026-10-05 14:20:29 +00:00
Author
Owner
Copy Link
Copy Source

pr-gatekeeper verdict: BLOCKED (round 2, head 52d4bfe)

Mode: PR. CI run 9393 (CI / Lint / Test / Vet) is green on 52d4bfe. Green does not cover finding 1.

Round 1's findings are fixed, and flipping each fix turns the suite red:

Flip at 52d4bfe Result
alertSender.push sends blocking red: TestWatchLinkLifetimeStaysNearOneInterval...
overflow.Swap line deleted red: TestWatchCountsHandoffOverflowWithASlowNotifier
no flush on handoff (tick only) red: TestWatchDeliversARemovalAlertWellWithinOneInterval
final flush removed red: both shutdown tests
wg.Wait() removed red: TestWatchReturnsOnlyAfterDeliveryHasStopped (+1)
final flush unbounded (no timeout) red: TestWatchReturnsOnlyAfterDeliveryHasStopped

go test -race -count=3 passes, and so do vet and golangci-lint on the package. Closing the channel cannot cause a panic: the only sender is Watch's loop, and the close runs in Watch's defer after that loop has exited. The overflow test asserts that delivered + counted equals the number of plants exactly, so an alert counted twice would fail it.

Findings

  1. Blocking. symlinkguard.go deliver, context.WithTimeout(context.WithoutCancel(ctx), shutdownFlushTimeout): the WithoutCancel that makes the shutdown flush work has no assertion.

    • Flip: I replaced it with context.WithTimeout(ctx, shutdownFlushTimeout), which derives the final flush from the already-cancelled ctx. The whole suite stays green.
    • Why: recNotifier and toggleNotifier ignore their ctx, so in the tests a flush on a dead ctx still "delivers". The real audit.NtfyNotifier builds its request with NewRequestWithContext, so it fails at once on a cancelled ctx.
    • Measured with a notifier that honours ctx (it fails when ctx is done, as an HTTP client does): at head, the queued-at-shutdown alert is delivered, and so are 4 of 4 alerts handed over while a flush was in flight. Under the flip, 0 of 1 and 0 of 4 are delivered, on 3 of 3 runs.
    • So the shutdown fix is proven only for a notifier that cannot exist in production, and TestWatchFlushesTheQueueOnceMoreAtShutdown claims more than it shows (rule 9). The round-2 comment says "each mechanism was flip-tested", which is not true of this line.
    • Fix: make the shutdown tests' notifier fail when ctx.Err() != nil. Both shutdown tests should then go red under this flip.

  2. Minor, not blocking. The drain-on-close path is only exercised by timing. If deliver skips the final flush after drain() reports the channel closed (i.e. when alerts were still in the channel at close), the suite stays green. My ctx-honouring probe caught that only 1 run in 3, because it depends on whether close lands inside the drain. Worth a deterministic test if it's cheap.

  3. Minor, not blocking. Overflow can be lost at close. When the first receive after close returns !ok, overflow is not swapped into suppressed. Only a narrow race reaches this: overflow.Add lands after deliver's last swap, and the channel is empty at close. One line fixes it: swap in the !ok branch too.

  4. Informational. A correction to my round-1 finding. cmd/server/main.go:370 runs go symlinkguard.Watch(context.Background(), ...), and the server has no signal handling. In production ctx never ends, and SIGTERM kills the process without Watch returning. So the drain at shutdown never runs in the pod. The production shutdown window is closed by the flush on handoff, which brings it back to parity with main, not by the drain. Round 1 said a Flux restart within one interval would lose the alert, and that overstated the case for the drain. The drain is still correct for any caller that does cancel, so the fix to finding 1 is cheap and still wanted. Wiring a cancelling ctx into main is out of scope here and is worth its own issue.

#164 done-when

"a test with a slow notifier and a full queue shows link lifetime <= interval + one scan": met. The notifier takes 400 ms against a 100 ms interval, the queue and handoff are overfilled first, and the test asserts a worst lifetime of at most 1.5 intervals. It goes red when the send blocks.

Not checked

The full task check locally (I relied on CI run 9393 for the whole module). The real NtfyNotifier against a live hung endpoint (my probe stood in for its ctx behaviour). A notifier that ignores ctx at shutdown: Watch would then wait past shutdownFlushTimeout, but NtfyNotifier honours ctx and nothing in main waits on Watch.

## pr-gatekeeper verdict: BLOCKED (round 2, head 52d4bfe) Mode: PR. CI run 9393 (`CI / Lint / Test / Vet`) is green on 52d4bfe. Green does not cover finding 1. Round 1's findings are fixed, and flipping each fix turns the suite red: | Flip at 52d4bfe | Result | |---|---| | `alertSender.push` sends blocking | red: `TestWatchLinkLifetimeStaysNearOneInterval...` | | `overflow.Swap` line deleted | red: `TestWatchCountsHandoffOverflowWithASlowNotifier` | | no flush on handoff (tick only) | red: `TestWatchDeliversARemovalAlertWellWithinOneInterval` | | final flush removed | red: both shutdown tests | | `wg.Wait()` removed | red: `TestWatchReturnsOnlyAfterDeliveryHasStopped` (+1) | | final flush unbounded (no timeout) | red: `TestWatchReturnsOnlyAfterDeliveryHasStopped` | `go test -race -count=3` passes, and so do vet and golangci-lint on the package. Closing the channel cannot cause a panic: the only sender is Watch's loop, and the close runs in Watch's defer after that loop has exited. The overflow test asserts that delivered + counted equals the number of plants exactly, so an alert counted twice would fail it. ### Findings 1. **Blocking. `symlinkguard.go` `deliver`, `context.WithTimeout(context.WithoutCancel(ctx), shutdownFlushTimeout)`: the `WithoutCancel` that makes the shutdown flush work has no assertion.** - **Flip:** I replaced it with `context.WithTimeout(ctx, shutdownFlushTimeout)`, which derives the final flush from the already-cancelled ctx. The whole suite stays green. - **Why:** `recNotifier` and `toggleNotifier` ignore their ctx, so in the tests a flush on a dead ctx still "delivers". The real `audit.NtfyNotifier` builds its request with `NewRequestWithContext`, so it fails at once on a cancelled ctx. - **Measured with a notifier that honours ctx** (it fails when ctx is done, as an HTTP client does): at head, the queued-at-shutdown alert is delivered, and so are 4 of 4 alerts handed over while a flush was in flight. Under the flip, **0 of 1 and 0 of 4 are delivered, on 3 of 3 runs.** - So the shutdown fix is proven only for a notifier that cannot exist in production, and `TestWatchFlushesTheQueueOnceMoreAtShutdown` claims more than it shows (rule 9). The round-2 comment says "each mechanism was flip-tested", which is not true of this line. - **Fix:** make the shutdown tests' notifier fail when `ctx.Err() != nil`. Both shutdown tests should then go red under this flip. 2. **Minor, not blocking. The drain-on-close path is only exercised by timing.** If deliver skips the final flush after `drain()` reports the channel closed (i.e. when alerts were still in the channel at close), the suite stays green. My ctx-honouring probe caught that only 1 run in 3, because it depends on whether close lands inside the drain. Worth a deterministic test if it's cheap. 3. **Minor, not blocking. Overflow can be lost at close.** When the first receive after close returns `!ok`, `overflow` is not swapped into `suppressed`. Only a narrow race reaches this: `overflow.Add` lands after deliver's last swap, and the channel is empty at close. One line fixes it: swap in the `!ok` branch too. 4. **Informational. A correction to my round-1 finding.** `cmd/server/main.go:370` runs `go symlinkguard.Watch(context.Background(), ...)`, and the server has no signal handling. In production ctx never ends, and SIGTERM kills the process without Watch returning. So the drain at shutdown never runs in the pod. The production shutdown window is closed by the **flush on handoff**, which brings it back to parity with main, not by the drain. Round 1 said a Flux restart within one interval would lose the alert, and that overstated the case for the drain. The drain is still correct for any caller that does cancel, so the fix to finding 1 is cheap and still wanted. Wiring a cancelling ctx into main is out of scope here and is worth its own issue. ### #164 done-when "a test with a slow notifier and a full queue shows link lifetime <= interval + one scan": **met.** The notifier takes 400 ms against a 100 ms interval, the queue and handoff are overfilled first, and the test asserts a worst lifetime of at most 1.5 intervals. It goes red when the send blocks. ### Not checked The full `task check` locally (I relied on CI run 9393 for the whole module). The real `NtfyNotifier` against a live hung endpoint (my probe stood in for its ctx behaviour). A notifier that ignores ctx at shutdown: Watch would then wait past `shutdownFlushTimeout`, but `NtfyNotifier` honours ctx and nothing in main waits on Watch.
mathias commented 2026-10-05 14:22:02 +00:00
Author
Owner
Copy Link
Copy Source

pr-gatekeeper verdict: BLOCKED (round 2, head 52d4bfe)

Mode: PR. CI run 9393 (CI / Lint / Test / Vet) is green on 52d4bfe. Local CI=1 GOFLAGS=-p=2 task check exits 0. go test -race -count=10 on the package also passes. Neither gate covers findings 1 or 2.

All four round-1 findings are fixed, and each fix has a test that catches its removal. Round 2 adds one new untested mechanism, and one shutdown case where alerts are lost silently.

Findings (most severe first)

  1. symlinkguard.go:243 context.WithoutCancel(ctx) in the final flush has no test. It is the part of the shutdown fix that makes the fix work.

    • Flip: replacing it with ctx keeps the whole suite green (-count=3).
    • Why the suite misses it: every test notifier ignores ctx. The real audit.NtfyNotifier does not: it uses http.NewRequestWithContext, so with a cancelled ctx it fails before sending anything.
    • Probe: a notifier that returns ctx.Err() when ctx is done, run through the TestWatchFlushesTheQueueOnceMoreAtShutdown scenario. Alerts lost: 0/10 at head, 10/10 with the flip.
    • So against production's notifier, removing this one call reverts the shutdown fix, and no test would notice.
    • Fix: make one of the shutdown tests use a ctx-honouring notifier.

  2. symlinkguard.go:242-246: at shutdown with ntfy hung or down, undelivered alerts are not recorded as dropped.

    • Probe: 15 removals against a hung notifier, cancel, final flush times out.
    • The log contains six "symlink tripwire notify failed; will retry" warnings. No retry follows, because Watch has returned.
    • There are 0 lines about dropped or lost alerts, and the suppressed count (about 10 alerts) is not logged anywhere.
    • The Watch doc still says "every incident is delivered or counted", which is false on this path.
    • Main behaves the same, so this is not a regression. But this round claims to close the shutdown path, and today that path ends silently.
    • Fix (a correction): after the final flush, if len(q.items) > 0 || q.suppressed > 0, log one error with both counts ("dropped at shutdown"), and add a test asserting that log line.

  3. Non-blocking, track it separately: cmd/server/main.go:370 runs go symlinkguard.Watch(context.Background(), ...) and main has no signal handling. In production ctx never ends, so the drain-at-shutdown path never runs. On SIGTERM (a Flux rollout) an alert that is mid-send is lost, exactly as on main. Production's real protection is flush-on-handoff, which this round adds and tests. The shutdown drain only protects callers that cancel. Say that in the doc, or wire a signal ctx in a follow-up issue.

Flip tests (each run -count=3)

Broken Caught by
non-blocking handoff made blocking LinkLifetime test, red 3/3
flush on handoff removed DeliversWellWithinOneInterval, red
final flush removed JustBeforeShutdown + FlushesTheQueueOnceMore, red
wg.Wait() join removed ReturnsOnlyAfterDeliveryHasStopped, red 3/3
overflow Swap accounting removed CountsHandoffOverflow, red 3/3
WithoutCancel removed nothing, green (finding 1)

What survived

  • Real audit.NtfyNotifier against a hung httptest server, interval 100 ms:
    • worst link lifetime 101.7 ms over 25 plants
    • Watch returns 201 ms after cancel (with shutdownFlushTimeout set to 200 ms)
  • Goroutines: 2 before and 2 after 30 start/cancel cycles with a notifier that blocks until ctx ends. No leak.
  • Overflow policy: when the handoff is full, the newest alert is counted (not dropped-oldest), and the count goes into the summary. The test covers it.
  • Issue #164 done-when (link lifetime ≤ interval + one scan): met by measurement. The test now asserts ≤ 1.5 × interval, which is tighter than round 1.

Not checked

  • A live ntfy.
  • Behaviour on SIGTERM in a real pod (see finding 3).
  • -race -count=10 over the whole repo; only this package was run.
## pr-gatekeeper verdict: BLOCKED (round 2, head 52d4bfe) Mode: PR. CI run 9393 (`CI / Lint / Test / Vet`) is green on 52d4bfe. Local `CI=1 GOFLAGS=-p=2 task check` exits 0. `go test -race -count=10` on the package also passes. Neither gate covers findings 1 or 2. All four round-1 findings are fixed, and each fix has a test that catches its removal. Round 2 adds one new untested mechanism, and one shutdown case where alerts are lost silently. ### Findings (most severe first) 1. **`symlinkguard.go:243` `context.WithoutCancel(ctx)` in the final flush has no test. It is the part of the shutdown fix that makes the fix work.** - **Flip:** replacing it with `ctx` keeps the whole suite green (`-count=3`). - **Why the suite misses it:** every test notifier ignores ctx. The real `audit.NtfyNotifier` does not: it uses `http.NewRequestWithContext`, so with a cancelled ctx it fails before sending anything. - **Probe:** a notifier that returns `ctx.Err()` when ctx is done, run through the `TestWatchFlushesTheQueueOnceMoreAtShutdown` scenario. Alerts lost: **0/10 at head, 10/10 with the flip**. - So against production's notifier, removing this one call reverts the shutdown fix, and no test would notice. - **Fix:** make one of the shutdown tests use a ctx-honouring notifier. 2. **`symlinkguard.go:242-246`: at shutdown with ntfy hung or down, undelivered alerts are not recorded as dropped.** - **Probe:** 15 removals against a hung notifier, cancel, final flush times out. - The log contains six `"symlink tripwire notify failed; will retry"` warnings. No retry follows, because Watch has returned. - There are 0 lines about dropped or lost alerts, and the suppressed count (about 10 alerts) is not logged anywhere. - The Watch doc still says "every incident is delivered or counted", which is false on this path. - Main behaves the same, so this is not a regression. But this round claims to close the shutdown path, and today that path ends silently. - **Fix (a correction):** after the final flush, if `len(q.items) > 0 || q.suppressed > 0`, log one error with both counts ("dropped at shutdown"), and add a test asserting that log line. 3. **Non-blocking, track it separately:** `cmd/server/main.go:370` runs `go symlinkguard.Watch(context.Background(), ...)` and main has no signal handling. In production ctx never ends, so the drain-at-shutdown path never runs. On SIGTERM (a Flux rollout) an alert that is mid-send is lost, exactly as on main. Production's real protection is flush-on-handoff, which this round adds and tests. The shutdown drain only protects callers that cancel. Say that in the doc, or wire a signal ctx in a follow-up issue. ### Flip tests (each run `-count=3`) | Broken | Caught by | |---|---| | non-blocking handoff made blocking | LinkLifetime test, red 3/3 | | flush on handoff removed | DeliversWellWithinOneInterval, red | | final flush removed | JustBeforeShutdown + FlushesTheQueueOnceMore, red | | `wg.Wait()` join removed | ReturnsOnlyAfterDeliveryHasStopped, red 3/3 | | overflow `Swap` accounting removed | CountsHandoffOverflow, red 3/3 | | `WithoutCancel` removed | **nothing, green** (finding 1) | ### What survived - **Real `audit.NtfyNotifier` against a hung httptest server**, interval 100 ms: - worst link lifetime 101.7 ms over 25 plants - Watch returns 201 ms after cancel (with `shutdownFlushTimeout` set to 200 ms) - **Goroutines:** 2 before and 2 after 30 start/cancel cycles with a notifier that blocks until ctx ends. No leak. - **Overflow policy:** when the handoff is full, the newest alert is counted (not dropped-oldest), and the count goes into the summary. The test covers it. - **Issue #164 done-when** (link lifetime ≤ interval + one scan): met by measurement. The test now asserts ≤ 1.5 × interval, which is tighter than round 1. ### Not checked - A live ntfy. - Behaviour on SIGTERM in a real pod (see finding 3). - `-race -count=10` over the whole repo; only this package was run.
mathias commented 2026-10-05 14:48:16 +00:00
Author
Owner
Copy Link
Copy Source

pr-gatekeeper verdict: APPROVED (round 3, head cadc0cc)

Mode: PR. CI run 9408 (CI / Lint / Test / Vet) is green on cadc0cc.

Round-2 findings, re-verified by execution. Each flip was run 3 times and went red all 3 times:

Flip Test that went red
blocking handoff send TestWatchLinkLifetimeStaysNearOneInterval...
overflow swap in drain removed TestWatchCountsHandoffOverflowWithASlowNotifier
no flush on handoff TestWatchDeliversARemovalAlertWellWithinOneInterval
final flush removed 3 shutdown/deliver tests
wg.Wait() removed 3 tests
final flush on the cancelled ctx (no WithoutCancel) TestDeliverFlushesAlertsDrainedFromAClosedHandoffOnACancelledCtx, TestWatchFinalFlushSendsAQueuedAlertOnACtxThatOutlivesTheCancel
final flush unbounded TestWatchReturnsOnlyAfterDeliveryHasStopped
no flush after drain-on-close TestDeliverFlushesAlertsDrainedFromAClosedHandoffOnACancelledCtx
overflow swap in the !ok branch removed TestDeliverCountsOverflowWhenTheHandoffIsClosedAndEmpty
shutdown error log removed TestWatchLogsUndeliveredAndSuppressedCountsWhenTheFinalFlushFails

Ctx-honouring probe. I used my own notifier, which fails on a done ctx. At head it delivered 1/1 alerts that were queued at shutdown and 4/4 alerts that were in the handoff at close, on 5 of 5 runs under -race. Under the WithoutCancel flip it delivered 0, on 3 of 3 runs. go test -race -count=3, go vet and golangci-lint are all clean on the package.

#164 done-when is met: a slow notifier (400 ms) against a 100 ms interval with an overfilled queue gives a worst link lifetime of at most 1.5 intervals, and the test goes red when the send blocks. The production signal-handling gap is tracked in #184.

Nit (not blocking): in symlinkguard_test.go, gofmt -l flags the import order (os before log/slog). The gate does not enforce gofmt.

Not checked: the full task check locally (I relied on CI 9408), and the real NtfyNotifier against a live hung endpoint.

## pr-gatekeeper verdict: APPROVED (round 3, head cadc0cc) Mode: PR. CI run 9408 (`CI / Lint / Test / Vet`) is green on cadc0cc. **Round-2 findings, re-verified by execution.** Each flip was run 3 times and went red all 3 times: | Flip | Test that went red | |---|---| | blocking handoff send | `TestWatchLinkLifetimeStaysNearOneInterval...` | | overflow swap in `drain` removed | `TestWatchCountsHandoffOverflowWithASlowNotifier` | | no flush on handoff | `TestWatchDeliversARemovalAlertWellWithinOneInterval` | | final flush removed | 3 shutdown/deliver tests | | `wg.Wait()` removed | 3 tests | | final flush on the cancelled ctx (no `WithoutCancel`) | `TestDeliverFlushesAlertsDrainedFromAClosedHandoffOnACancelledCtx`, `TestWatchFinalFlushSendsAQueuedAlertOnACtxThatOutlivesTheCancel` | | final flush unbounded | `TestWatchReturnsOnlyAfterDeliveryHasStopped` | | no flush after drain-on-close | `TestDeliverFlushesAlertsDrainedFromAClosedHandoffOnACancelledCtx` | | overflow swap in the `!ok` branch removed | `TestDeliverCountsOverflowWhenTheHandoffIsClosedAndEmpty` | | shutdown error log removed | `TestWatchLogsUndeliveredAndSuppressedCountsWhenTheFinalFlushFails` | **Ctx-honouring probe.** I used my own notifier, which fails on a done ctx. At head it delivered 1/1 alerts that were queued at shutdown and 4/4 alerts that were in the handoff at close, on 5 of 5 runs under `-race`. Under the `WithoutCancel` flip it delivered 0, on 3 of 3 runs. `go test -race -count=3`, `go vet` and `golangci-lint` are all clean on the package. #164 done-when is met: a slow notifier (400 ms) against a 100 ms interval with an overfilled queue gives a worst link lifetime of at most 1.5 intervals, and the test goes red when the send blocks. The production signal-handling gap is tracked in #184. **Nit (not blocking):** in `symlinkguard_test.go`, `gofmt -l` flags the import order (`os` before `log/slog`). The gate does not enforce gofmt. **Not checked:** the full `task check` locally (I relied on CI 9408), and the real `NtfyNotifier` against a live hung endpoint.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
agent/ready
Meets the agent-ready contract; authorizes unattended execution
 blocked/client
Waiting on the client
 blocked/supplier
Waiting on a supplier
 blocked/upstream
Waiting on an upstream project or vendor
 risk/high
Irreversible, security-relevant, or control plane
 risk/low
Reversible, local, test-covered
 risk/medium
Touches shared state, deploys or data
 size/l
Too big - split it
 size/m
Under two days
 size/s
Under half a day
 size/xs
Under an hour
 status:dispatch
status:dispatched
status:review
status:reviewing
type/chore
Maintenance, no behaviour change
 type/decision
Human decision required; never agent/ready
 type/docs
Documentation only
 type/feat
New capability
 type/fix
Corrects broken behaviour
 type/ops
Infrastructure, deploy, runtime
 type/research
Investigate; output is a finding, not code
 type/test
Test coverage only
No labels
Milestone
No items
No Milestone
Projects
Clear projects
No projects
Assignees
Clear assignees
renovate-bot mathias
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: mathias/hyperguild#164