fix(symlinkguard): deliver alerts beside the scan, not inside it (#164) (#180)

Co-authored-by: Mathias <mthbqv@gmail.com>

ingestion/internal/symlinkguard/symlinkguard_test.go

@@ -1,10 +1,12 @@
 package symlinkguard
 
 import (
+	"bytes"
 	"context"
 	"errors"
 	"fmt"
 	"os"
+	"log/slog"
 	"path/filepath"
 	"strconv"
 	"strings"
@@ -345,13 +347,19 @@ func TestWatchDropsAMessageThatNeverSendsSoLaterAlertsFlow(t *testing.T) {
 	}, 3*time.Second, 10*time.Millisecond, "a later alert is delivered despite a poison message")
 }
 
-// toggleNotifier fails while down is set.
+// toggleNotifier fails while down is set. Like the real audit.NtfyNotifier
+// (http.NewRequestWithContext), it also fails, without recording, when its
+// ctx is already done (PR #180 round 2: notifiers that ignored ctx let a
+// final flush on the cancelled ctx pass).
 type toggleNotifier struct {
 	recNotifier
 	down atomic.Bool
 }
 
 func (r *toggleNotifier) Notify(ctx context.Context, m string) error {
+	if err := ctx.Err(); err != nil {
+		return err
+	}
 	if r.down.Load() {
 		return errors.New("ntfy down")
 	}
@@ -496,3 +504,271 @@ func TestWatchDropsAPoisonMessageAndCountsIt(t *testing.T) {
 		return false
 	}, 3*time.Second, 5*time.Millisecond, "the dropped poison alert is counted in a summary")
 }
+
+// hungNotifier answers every Notify only after latency (or when ctx ends),
+// with an outage error: an ntfy that accepts connections but never responds
+// until its timeout.
+type hungNotifier struct{ latency time.Duration }
+
+func (h hungNotifier) Notify(ctx context.Context, _ string) error {
+	select {
+	case <-time.After(h.latency):
+	case <-ctx.Done():
+	}
+	return errors.New("ntfy timeout")
+}
+
+func waitGone(t *testing.T, link string) {
+	t.Helper()
+	require.Eventually(t, func() bool { _, err := os.Lstat(link); return os.IsNotExist(err) }, 10*time.Second, time.Millisecond)
+}
+
+// hyperguild#164: alerts were flushed in the scan goroutine, so with a hung
+// ntfy and a full queue one flush (6 x notify timeout) delayed the next scan.
+// The notifier here is slower than the interval, as in production (10 s
+// timeout vs 30 s interval with 6 messages), so the alert handoff is full:
+// a scan that waited on it would keep a link for seconds.
+func TestWatchLinkLifetimeStaysNearOneIntervalWithANotifierSlowerThanTheInterval(t *testing.T) {
+	const interval = 100 * time.Millisecond
+	brain := t.TempDir()
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	go Watch(ctx, brain, interval, hungNotifier{latency: 400 * time.Millisecond})
+
+	for i := 0; i < 2*maxPending+3; i++ { // overfill queue and handoff
+		link := filepath.Join(brain, "fill"+strconv.Itoa(i))
+		require.NoError(t, os.Symlink(t.TempDir(), link))
+		waitGone(t, link)
+	}
+	var worst time.Duration
+	for i := 0; i < 6; i++ {
+		link := filepath.Join(brain, "probe"+strconv.Itoa(i))
+		require.NoError(t, os.Symlink(t.TempDir(), link))
+		planted := time.Now()
+		waitGone(t, link)
+		worst = max(worst, time.Since(planted))
+	}
+	assert.LessOrEqual(t, worst, interval+interval/2, "worst link lifetime %v with a hung notifier", worst)
+}
+
+// Review of PR #180: delivery waited for its own tick, about one interval
+// after the removal. An alert is now flushed as soon as it is handed over.
+func TestWatchDeliversARemovalAlertWellWithinOneInterval(t *testing.T) {
+	const interval = 400 * time.Millisecond
+	brain := t.TempDir()
+	n := &recNotifier{}
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	go Watch(ctx, brain, interval, n)
+	link := filepath.Join(brain, "prompt")
+	require.NoError(t, os.Symlink(t.TempDir(), link))
+	waitGone(t, link)
+	removed := time.Now()
+	require.Eventually(t, func() bool { return n.count() == 1 }, 2*time.Second, time.Millisecond)
+	assert.Less(t, time.Since(removed), interval/4)
+}
+
+// Review of PR #180: on ctx end, deliver returned without draining what the
+// scan had handed over, so a removal just before shutdown was neither
+// delivered nor counted. Watch now drains and flushes before returning.
+func TestWatchDeliversAnAlertHandedOverJustBeforeShutdown(t *testing.T) {
+	for i := 0; i < 20; i++ {
+		brain := t.TempDir()
+		n := &recNotifier{}
+		ctx, cancel := context.WithCancel(context.Background())
+		done := make(chan struct{})
+		go func() { Watch(ctx, brain, 5*time.Millisecond, n); close(done) }()
+		link := filepath.Join(brain, "late")
+		require.NoError(t, os.Symlink(t.TempDir(), link))
+		waitGone(t, link)
+		cancel()
+		<-done
+		require.Equal(t, 1, n.count(), "iteration %d: the removal alert was lost at shutdown", i)
+	}
+}
+
+// blockingNotifier holds every Notify until its ctx ends, tracking calls in
+// flight.
+type blockingNotifier struct{ inFlight atomic.Int32 }
+
+func (b *blockingNotifier) Notify(ctx context.Context, _ string) error {
+	b.inFlight.Add(1)
+	defer b.inFlight.Add(-1)
+	<-ctx.Done()
+	return ctx.Err()
+}
+
+// Watch does not return while its delivery goroutine is still notifying.
+func TestWatchReturnsOnlyAfterDeliveryHasStopped(t *testing.T) {
+	prev := shutdownFlushTimeout
+	shutdownFlushTimeout = 50 * time.Millisecond
+	t.Cleanup(func() { shutdownFlushTimeout = prev })
+	brain := t.TempDir()
+	n := &blockingNotifier{}
+	ctx, cancel := context.WithCancel(context.Background())
+	done := make(chan struct{})
+	go func() { Watch(ctx, brain, 5*time.Millisecond, n); close(done) }()
+	link := filepath.Join(brain, "x")
+	require.NoError(t, os.Symlink(t.TempDir(), link))
+	waitGone(t, link)
+	require.Eventually(t, func() bool { return n.inFlight.Load() == 1 }, 2*time.Second, time.Millisecond)
+	cancel()
+	select {
+	case <-done:
+	case <-time.After(5 * time.Second):
+		t.Fatal("Watch did not return after cancel")
+	}
+	assert.Zero(t, n.inFlight.Load(), "Notify still running after Watch returned")
+}
+
+// slowToggleNotifier fails slowly (a hung ntfy) while down, then records.
+type slowToggleNotifier struct {
+	recNotifier
+	down    atomic.Bool
+	latency time.Duration
+}
+
+func (r *slowToggleNotifier) Notify(ctx context.Context, m string) error {
+	if r.down.Load() {
+		select {
+		case <-time.After(r.latency):
+		case <-ctx.Done():
+		}
+		return errors.New("ntfy timeout")
+	}
+	return r.recNotifier.Notify(ctx, m)
+}
+
+// Review of PR #180: with a slow notifier the scan's handoff overflows, and
+// those alerts exist only in the overflow counter. Every removal is still
+// delivered or counted in the summary.
+func TestWatchCountsHandoffOverflowWithASlowNotifier(t *testing.T) {
+	brain := t.TempDir()
+	n := &slowToggleNotifier{latency: 30 * time.Millisecond}
+	n.down.Store(true)
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	go Watch(ctx, brain, 2*time.Millisecond, n)
+	const plants = 40
+	for i := 0; i < plants; i++ {
+		link := filepath.Join(brain, "ov"+strconv.Itoa(i))
+		require.NoError(t, os.Symlink(t.TempDir(), link))
+		waitGone(t, link)
+	}
+	n.down.Store(false)
+	delivered, counted := 0, 0
+	require.Eventually(t, func() bool {
+		n.mu.Lock()
+		defer n.mu.Unlock()
+		delivered, counted = 0, 0
+		for _, m := range n.msgs {
+			if strings.Contains(m, "removed 1 symlink(s)") {
+				delivered++
+			}
+			if i := strings.Index(m, "): "); i >= 0 && strings.Contains(m, "suppressed") {
+				var c int
+				_, _ = fmt.Sscanf(m[i+3:], "%d", &c)
+				counted += c
+			}
+		}
+		return delivered+counted == plants
+	}, 5*time.Second, 10*time.Millisecond, "delivered %d + counted %d of %d", delivered, counted, plants)
+}
+
+// An alert still queued when Watch stops (its send failed, the notifier has
+// since recovered, the retry tick has not come) is flushed once more before
+// Watch returns, on a ctx that is not the cancelled one: toggleNotifier fails
+// on a done ctx, as the real ntfy notifier does.
+func TestWatchFinalFlushSendsAQueuedAlertOnACtxThatOutlivesTheCancel(t *testing.T) {
+	brain := t.TempDir()
+	n := &toggleNotifier{}
+	n.down.Store(true)
+	ctx, cancel := context.WithCancel(context.Background())
+	done := make(chan struct{})
+	go func() { Watch(ctx, brain, 300*time.Millisecond, n); close(done) }()
+	link := filepath.Join(brain, "queued")
+	require.NoError(t, os.Symlink(t.TempDir(), link))
+	waitGone(t, link)
+	time.Sleep(20 * time.Millisecond) // let the immediate send fail
+	n.down.Store(false)
+	cancel()
+	<-done
+	assert.Equal(t, 1, n.count(), "the queued alert was not flushed at shutdown")
+}
+
+// lockedBuffer is a goroutine-safe log sink: Watch goroutines of earlier
+// tests may still log while one test captures.
+type lockedBuffer struct {
+	mu  sync.Mutex
+	buf bytes.Buffer
+}
+
+func (b *lockedBuffer) Write(p []byte) (int, error) {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+	return b.buf.Write(p)
+}
+
+func (b *lockedBuffer) String() string { b.mu.Lock(); defer b.mu.Unlock(); return b.buf.String() }
+
+func captureLog(t *testing.T) *lockedBuffer {
+	t.Helper()
+	b := &lockedBuffer{}
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(b, nil)))
+	t.Cleanup(func() { slog.SetDefault(prev) })
+	return b
+}
+
+// PR #180 round 2: when the final flush fails (ntfy hung at shutdown) the
+// undelivered alerts vanished with only "will retry" warnings. Watch now logs
+// one error with both counts.
+func TestWatchLogsUndeliveredAndSuppressedCountsWhenTheFinalFlushFails(t *testing.T) {
+	prev := shutdownFlushTimeout
+	shutdownFlushTimeout = 50 * time.Millisecond
+	t.Cleanup(func() { shutdownFlushTimeout = prev })
+	logs := captureLog(t)
+	brain := t.TempDir()
+	ctx, cancel := context.WithCancel(context.Background())
+	done := make(chan struct{})
+	go func() { Watch(ctx, brain, 5*time.Millisecond, hungNotifier{latency: time.Hour}); close(done) }()
+	link := filepath.Join(brain, "lost")
+	require.NoError(t, os.Symlink(t.TempDir(), link))
+	waitGone(t, link)
+	cancel()
+	<-done
+	out := logs.String()
+	assert.Contains(t, out, "level=ERROR")
+	assert.Contains(t, out, `msg="symlink tripwire alerts not delivered at shutdown"`)
+	assert.Contains(t, out, "undelivered=1")
+	assert.Contains(t, out, "suppressed=0")
+}
+
+// deliver, given a handoff that already holds alerts and is closed, moves them
+// into the queue and runs the final flush, even though the ctx is cancelled:
+// the drain-on-close path, without depending on when the close lands.
+func TestDeliverFlushesAlertsDrainedFromAClosedHandoffOnACancelledCtx(t *testing.T) {
+	alerts := make(chan string, 3)
+	alerts <- "a1"
+	alerts <- "a2"
+	close(alerts)
+	ctx, cancel := context.WithCancel(context.Background())
+	cancel()
+	n := &toggleNotifier{}
+	var overflow atomic.Int64
+	deliver(ctx, time.Hour, n, alerts, &overflow)
+	assert.Equal(t, []string{"a1", "a2"}, n.msgs)
+}
+
+// PR #180 round 2: when the first receive after close finds the handoff empty,
+// overflow counted by the scan was never moved into the summary.
+func TestDeliverCountsOverflowWhenTheHandoffIsClosedAndEmpty(t *testing.T) {
+	alerts := make(chan string)
+	close(alerts)
+	n := &recNotifier{}
+	var overflow atomic.Int64
+	overflow.Store(3)
+	deliver(context.Background(), time.Hour, n, alerts, &overflow)
+	require.Len(t, n.msgs, 1)
+	assert.Contains(t, n.msgs[0], "3 further alert(s)")
+}