From cd06bba03450772e16e8371b7a58d059d479a05e Mon Sep 17 00:00:00 2001 From: clawbot Date: Sun, 9 Aug 2026 05:21:57 +0000 Subject: [PATCH] notify: fix flaky drain timing assertions, drop false abandon warn (closes #106) The drain tests measured elapsed time from an instant captured after the clock they compared it against had already started, so the lower bounds were structurally unreachable and passed only when the gap between the two statements rounded to zero. TestDrainBoundedByContext- Deadline failed the Docker gate outright (49.9ms against its own 50ms deadline) and roughly 1 run in 12 locally. - TestDrainBoundedByContextDeadline: capture start before context.WithTimeout, so the measured interval is a superset of the deadline interval and only an early return can fail the lower bound. The upper bound moves to a watchdog around the drain, which turns an unbounded drain into a prompt failure instead of a package-timeout hang. - TestDrainWaitsForInFlightDelivery: same ordering fix, ahead of the timer that releases the held delivery. - TestDrainWithoutDeliveriesReturnsImmediately: its 50ms ceiling was under the observed cost of the goroutine hop through inFlight.Wait() on a loaded box (57ms), and failed once in 20 runs. It now bounds the idle drain at 500ms, still well under the 2s deadline a stalled drain would hit. - drain: an OnStop context already expired on entry with nothing outstanding logged a WARN about abandoning deliveries with abandoned=0 and closed the abandon channel for no reason. The timeout branch now reports at debug level when the outstanding count is zero, and warns only when deliveries genuinely are abandoned. TestDrainWithCancelledContextDoesNotWarn covers it. Verified: script/cibuild passes; 25 consecutive cache-bypassed make test runs under -race, all clean; make check green at 5.2s. Both corrected assertions were confirmed non-vacuous by temporarily breaking drain and watching them fail. --- TODO.md | 4 +- internal/notify/shutdown.go | 23 ++++++- internal/notify/shutdown_test.go | 107 ++++++++++++++++++++++++++----- 3 files changed, 115 insertions(+), 19 deletions(-) diff --git a/TODO.md b/TODO.md index 7431d94..da9276c 100644 --- a/TODO.md +++ b/TODO.md @@ -31,7 +31,9 @@ confirm make check still passes. `OnStop` context; on expiry the outstanding count is logged at warn level and parked retry backoffs are released instead of being dropped silently, and deliveries submitted after the drain begins are refused - so shutdown cannot be extended indefinitely + so shutdown cannot be extended indefinitely; an `OnStop` context that + is already expired on entry with nothing outstanding drains quietly + rather than warning about deliveries that were never abandoned - 2026-08-07: golangci-lint bumped to v2.12.2 (commit-pinned installs in `Dockerfile` and `script/bootstrap`); `.golangci.yml` set to the org-standard v2-schema config used across the org's repos diff --git a/internal/notify/shutdown.go b/internal/notify/shutdown.go index dd1c3c7..0269889 100644 --- a/internal/notify/shutdown.go +++ b/internal/notify/shutdown.go @@ -64,6 +64,11 @@ func (svc *Service) startDelivery(endpoint string, fn func()) { // closed, which releases any retry loop sleeping in backoff. // Deliveries already inside an HTTP round trip are bounded by // the existing httpClientTimeout instead. +// +// A ctx that is already expired on entry is not by itself cause +// for alarm: if nothing is outstanding there is nothing to +// abandon, and the drain says so at debug level rather than +// warning about deliveries that do not exist. func (svc *Service) drain(ctx context.Context) { svc.drainMu.Lock() svc.draining = true @@ -82,6 +87,22 @@ func (svc *Service) drain(ctx context.Context) { "all in-flight notifications completed", ) case <-ctx.Done(): + // outstanding is decremented before the WaitGroup + // counter, and startDelivery can no longer add to it + // now that draining is set, so a zero here means every + // delivery really did finish. ctx expiring in that + // state (an OnStop context that was already cancelled + // on entry is the usual way) abandons nothing, so it + // must not close abandon or warn about it. + abandoned := svc.outstanding.Load() + if abandoned == 0 { + svc.log.Debug( + "all in-flight notifications completed", + ) + + return + } + svc.abandonOnce.Do(func() { if svc.abandon != nil { close(svc.abandon) @@ -91,7 +112,7 @@ func (svc *Service) drain(ctx context.Context) { svc.log.Warn( "shutdown deadline reached with notifications "+ "still in flight; abandoning them", - "abandoned", svc.outstanding.Load(), + "abandoned", abandoned, "error", ctx.Err(), ) } diff --git a/internal/notify/shutdown_test.go b/internal/notify/shutdown_test.go index e88224f..f938b64 100644 --- a/internal/notify/shutdown_test.go +++ b/internal/notify/shutdown_test.go @@ -41,6 +41,16 @@ const ( // settleDelay is how long to wait before asserting that // something did *not* happen. settleDelay = 50 * time.Millisecond + + // idleDrainBound is the upper bound on a drain that has + // nothing in flight. It is deliberately far above the cost + // of the goroutine hop through inFlight.Wait() — which + // reached 57ms on a loaded box under -race with the package's + // parallel tests — and far below drainSlack, the deadline + // such a drain is given. A drain that blocked until its + // deadline instead of returning on the WaitGroup therefore + // still fails this bound, but scheduling delay alone cannot. + idleDrainBound = 500 * time.Millisecond ) // syncBuffer is an io.Writer safe for concurrent use, so log @@ -128,6 +138,13 @@ func TestDrainWaitsForInFlightDelivery(t *testing.T) { t.Fatal("delivery never reached the endpoint") } + // As in TestDrainBoundedByContextDeadline: start is captured + // before the clock it is compared against, here the timer + // holding the delivery open, so elapsed covers the whole hold + // and the lower bound cannot come out short from scheduling + // delay alone. + start := time.Now() + timer := time.AfterFunc(inFlightHold, func() { close(release) }) @@ -138,8 +155,6 @@ func TestDrainWaitsForInFlightDelivery(t *testing.T) { ) defer cancel() - start := time.Now() - svc.Drain(ctx) elapsed := time.Since(start) @@ -211,28 +226,53 @@ func TestDrainBoundedByContextDeadline(t *testing.T) { svc.OutstandingDeliveries() == 1 }) + // start must be captured *before* the deadline clock starts, + // so that the measured interval is a superset of the deadline + // interval. Capturing it after context.WithTimeout would + // make elapsed structurally smaller than drainDeadline and + // the lower bound below unfalsifiable-by-luck: it would fail + // whenever the two statements were separated by any + // scheduling delay, and pass otherwise, regardless of what + // the drain did. + start := time.Now() + ctx, cancel := context.WithTimeout( context.Background(), drainDeadline, ) defer cancel() - start := time.Now() + // The upper bound is enforced by a watchdog rather than by + // measuring after the fact: a drain that is not bounded at + // all never returns here (the delivery is parked in a backoff + // that never fires), so an unbounded drain must fail this + // test promptly instead of hanging the package until the test + // binary's 30s timeout. + returned := make(chan struct{}) - svc.Drain(ctx) + go func() { + defer close(returned) - elapsed := time.Since(start) + svc.Drain(ctx) + }() - if elapsed < drainDeadline { - t.Errorf( - "drain returned after %v, before its %v deadline", - elapsed, drainDeadline, + select { + case <-returned: + case <-time.After(drainSlack): + t.Fatalf( + "drain did not return within %v; its %v deadline "+ + "did not bound it", + drainSlack, drainDeadline, ) } - if elapsed > drainSlack { + // The lower bound is the real assertion: the drain must have + // waited for its whole deadline rather than giving up on the + // outstanding delivery early. With start captured above, an + // early return is the only thing that can make it fail. + if elapsed := time.Since(start); elapsed < drainDeadline { t.Errorf( - "drain took %v, want it bounded well under %v", - elapsed, drainSlack, + "drain returned after %v, before its %v deadline", + elapsed, drainDeadline, ) } @@ -440,19 +480,52 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) { svc := notify.NewTestService(http.DefaultTransport) + // Captured before the deadline clock, as elsewhere in this + // file; for an upper bound that is the conservative + // direction, since the measured interval can then only be + // longer than the drain itself. + start := time.Now() + ctx, cancel := context.WithTimeout( context.Background(), drainSlack, ) defer cancel() - start := time.Now() - svc.Drain(ctx) - if elapsed := time.Since(start); elapsed > settleDelay { + if elapsed := time.Since(start); elapsed > idleDrainBound { t.Errorf( - "drain of an idle service took %v, want ~0", - elapsed, + "drain of an idle service took %v, want well "+ + "under its %v deadline", + elapsed, drainSlack, + ) + } +} + +// TestDrainWithCancelledContextDoesNotWarn verifies that an +// OnStop context that is already dead on entry does not produce +// an "abandoning them" warning when there was nothing in flight +// to abandon. The expired context wins the select immediately, +// so only the outstanding count can tell the difference between +// a genuine timeout and a shutdown that had simply already run +// out of time with no work left. +func TestDrainWithCancelledContextDoesNotWarn(t *testing.T) { + t.Parallel() + + svc, logs := newLoggingService(http.DefaultTransport) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + svc.Drain(ctx) + + if output := logs.String(); strings.Contains( + output, `"level":"WARN"`, + ) { + t.Errorf( + "drain with nothing in flight warned about "+ + "abandoned deliveries; log output: %s", + output, ) } }