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).

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",