diff --git a/TODO.md b/TODO.md index 5f654fe..5e7cad9 100644 --- a/TODO.md +++ b/TODO.md @@ -19,6 +19,8 @@ Rationale, Design, TODO, License, Author) if any are still missing. # Completed Steps +- 2026-10-01: notify shutdown tests use one timing constant per meaning, name + the bound they check, and require the drain's debug line (closes #116). - 2026-09-29: the live-DNS test package is renamed `internal/livednstest` and added to the `test-support` `deny` list in `.golangci.yml`, so `make lint` fails when program code imports it (closes #164). diff --git a/internal/notify/shutdown_test.go b/internal/notify/shutdown_test.go index f938b64..224741d 100644 --- a/internal/notify/shutdown_test.go +++ b/internal/notify/shutdown_test.go @@ -33,10 +33,29 @@ const ( // out. drainDeadline = 50 * time.Millisecond - // drainSlack is the upper bound on how long a bounded - // drain may take; generous enough for a loaded CI box, - // still far below the 20s test ceiling. - drainSlack = 2 * time.Second + // timeoutDrainBound is how long a drain given drainDeadline + // may take to return before the test gives up on it. At + // forty times drainDeadline it leaves ample room for + // scheduling delay on a loaded box under -race, yet it is far + // below the test binary's -timeout, so a drain that its + // deadline does not bound fails that one test instead of + // hanging the package. + timeoutDrainBound = 2 * time.Second + + // longDrainDeadline is the deadline given to a drain that is + // expected to finish well before it: when the in-flight + // delivery completes after inFlightHold, or at once when + // nothing is in flight. It is far above inFlightHold, so + // those drains never reach it, and four times + // idleDrainBound, so an idle drain that waited for its + // deadline instead of returning fails that bound. + longDrainDeadline = 2 * time.Second + + // reachEndpointTimeout is how long a submitted delivery may + // take to reach the test server. That normally takes a few + // milliseconds; the margin is for a loaded box under -race, + // and only a failing run ever waits this long. + reachEndpointTimeout = 2 * time.Second // settleDelay is how long to wait before asserting that // something did *not* happen. @@ -46,10 +65,11 @@ const ( // 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. + // parallel tests — and far below longDrainDeadline, 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 ) @@ -75,12 +95,14 @@ func (sb *syncBuffer) String() string { } // newLoggingService returns a Service writing JSON logs into -// the returned buffer. +// the returned buffer, debug level included. func newLoggingService( transport http.RoundTripper, ) (*notify.Service, *syncBuffer) { logs := &syncBuffer{} - handler := slog.NewJSONHandler(logs, nil) + handler := slog.NewJSONHandler( + logs, &slog.HandlerOptions{Level: slog.LevelDebug}, + ) return notify.NewTestServiceWithLogger(transport, handler), logs @@ -134,7 +156,7 @@ func TestDrainWaitsForInFlightDelivery(t *testing.T) { // drain begins. select { case <-entered: - case <-time.After(drainSlack): + case <-time.After(reachEndpointTimeout): t.Fatal("delivery never reached the endpoint") } @@ -151,7 +173,7 @@ func TestDrainWaitsForInFlightDelivery(t *testing.T) { defer timer.Stop() ctx, cancel := context.WithTimeout( - context.Background(), drainSlack, + context.Background(), longDrainDeadline, ) defer cancel() @@ -257,11 +279,11 @@ func TestDrainBoundedByContextDeadline(t *testing.T) { select { case <-returned: - case <-time.After(drainSlack): + case <-time.After(timeoutDrainBound): t.Fatalf( "drain did not return within %v; its %v deadline "+ "did not bound it", - drainSlack, drainDeadline, + timeoutDrainBound, drainDeadline, ) } @@ -333,7 +355,7 @@ func TestDrainRefusesNewDeliveries(t *testing.T) { svc.SetMattermostWebhookURL(target) ctx, cancel := context.WithTimeout( - context.Background(), drainSlack, + context.Background(), longDrainDeadline, ) defer cancel() @@ -446,7 +468,7 @@ func TestNewRegistersDrainingStopHook(t *testing.T) { select { case <-entered: - case <-time.After(drainSlack): + case <-time.After(reachEndpointTimeout): t.Fatal("delivery never reached the endpoint") } @@ -456,7 +478,7 @@ func TestNewRegistersDrainingStopHook(t *testing.T) { defer timer.Stop() ctx, cancel := context.WithTimeout( - context.Background(), drainSlack, + context.Background(), longDrainDeadline, ) defer cancel() @@ -487,7 +509,7 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) { start := time.Now() ctx, cancel := context.WithTimeout( - context.Background(), drainSlack, + context.Background(), longDrainDeadline, ) defer cancel() @@ -495,9 +517,9 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) { if elapsed := time.Since(start); elapsed > idleDrainBound { t.Errorf( - "drain of an idle service took %v, want well "+ - "under its %v deadline", - elapsed, drainSlack, + "drain of an idle service took %v, want at most "+ + "%v; its deadline was %v", + elapsed, idleDrainBound, longDrainDeadline, ) } } @@ -505,10 +527,11 @@ func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) { // 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. +// to abandon, and that the drain returns and says at debug level +// that nothing was in flight. 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() @@ -517,11 +540,43 @@ func TestDrainWithCancelledContextDoesNotWarn(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) cancel() - svc.Drain(ctx) + // A watchdog, as in TestDrainBoundedByContextDeadline, so + // that a drain which never returns fails here instead of + // hanging the package. + returned := make(chan struct{}) - if output := logs.String(); strings.Contains( - output, `"level":"WARN"`, + go func() { + defer close(returned) + + svc.Drain(ctx) + }() + + select { + case <-returned: + case <-time.After(idleDrainBound): + t.Fatalf( + "drain with nothing in flight and a cancelled "+ + "context did not return within %v", + idleDrainBound, + ) + } + + output := logs.String() + + // The absence of a warning alone would also pass if the drain + // logged nothing at all, so require the debug line it writes + // when it finds nothing outstanding. + if !strings.Contains( + output, "all in-flight notifications completed", ) { + t.Errorf( + "drain did not log that nothing was in flight; "+ + "log output: %s", + output, + ) + } + + if strings.Contains(output, `"level":"WARN"`) { t.Errorf( "drain with nothing in flight warned about "+ "abandoned deliveries; log output: %s",