package notify_test import ( "bytes" "context" "log/slog" "net/http" "net/http/httptest" "net/url" "strings" "sync" "sync/atomic" "testing" "time" "go.uber.org/fx" "sneak.berlin/go/dnswatcher/internal/config" "sneak.berlin/go/dnswatcher/internal/globals" "sneak.berlin/go/dnswatcher/internal/logger" "sneak.berlin/go/dnswatcher/internal/notify" ) // Timings used by the drain tests. They stay in the same // 10-100ms band as the retry tests so the suite never waits on // a real backoff delay. const ( // inFlightHold is how long a delivery is kept mid-request // before the handler is released. inFlightHold = 30 * time.Millisecond // drainDeadline bounds a drain that is expected to time // out. drainDeadline = 50 * time.Millisecond // 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. 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 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 ) // syncBuffer is an io.Writer safe for concurrent use, so log // output written from delivery goroutines can be inspected. type syncBuffer struct { mu sync.Mutex buf bytes.Buffer } func (sb *syncBuffer) Write(p []byte) (int, error) { sb.mu.Lock() defer sb.mu.Unlock() return sb.buf.Write(p) //nolint:wrapcheck // test helper } func (sb *syncBuffer) String() string { sb.mu.Lock() defer sb.mu.Unlock() return sb.buf.String() } // newLoggingService returns a Service writing JSON logs into // the returned buffer, debug level included. func newLoggingService( transport http.RoundTripper, ) (*notify.Service, *syncBuffer) { logs := &syncBuffer{} handler := slog.NewJSONHandler( logs, &slog.HandlerOptions{Level: slog.LevelDebug}, ) return notify.NewTestServiceWithLogger(transport, handler), logs } // blockingNtfyServer returns a server whose handler signals on // entered, waits for release, and then responds 200. func blockingNtfyServer( entered chan<- struct{}, release <-chan struct{}, served *atomic.Bool, ) *httptest.Server { var once sync.Once return httptest.NewServer( http.HandlerFunc( func(w http.ResponseWriter, _ *http.Request) { once.Do(func() { close(entered) }) <-release served.Store(true) w.WriteHeader(http.StatusOK) }), ) } // TestDrainWaitsForInFlightDelivery verifies that a delivery // already under way when shutdown starts is allowed to finish. func TestDrainWaitsForInFlightDelivery(t *testing.T) { t.Parallel() var served atomic.Bool entered := make(chan struct{}) release := make(chan struct{}) srv := blockingNtfyServer(entered, release, &served) defer srv.Close() // srv.Close waits for the handler, so release it however the // test ends; otherwise a drain that returns early hangs the // package instead of failing this test. releaseHandler := sync.OnceFunc(func() { close(release) }) defer releaseHandler() topicURL, _ := url.Parse(srv.URL) svc := notify.NewTestService(http.DefaultTransport) svc.SetNtfyURL(topicURL) svc.SendNotification( context.Background(), "t", "m", prioInfo, ) // Make sure the delivery really is mid-request before the // drain begins. select { case <-entered: case <-time.After(reachEndpointTimeout): 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, releaseHandler) defer timer.Stop() ctx, cancel := context.WithTimeout( context.Background(), longDrainDeadline, ) defer cancel() svc.Drain(ctx) elapsed := time.Since(start) if !served.Load() { t.Error( "drain returned before the in-flight delivery " + "completed", ) } if elapsed < inFlightHold { t.Errorf( "drain took %v, want at least %v", elapsed, inFlightHold, ) } if got := svc.OutstandingDeliveries(); got != 0 { t.Errorf("outstanding deliveries = %d, want 0", got) } } // neverFires returns a channel that never delivers, standing in // for a long backoff sleep without actually sleeping. func neverFires(_ time.Duration) <-chan time.Time { return make(chan time.Time) } // TestDrainBoundedByContextDeadline verifies that a delivery // stuck retrying against a dead endpoint does not hold shutdown // past the OnStop context deadline, and that the abandoned // deliveries are logged at warn level rather than dropped // silently. func TestDrainBoundedByContextDeadline(t *testing.T) { t.Parallel() var requests atomic.Int64 srv := httptest.NewServer( http.HandlerFunc( func(w http.ResponseWriter, _ *http.Request) { requests.Add(1) w.WriteHeader(http.StatusInternalServerError) }), ) defer srv.Close() topicURL, _ := url.Parse(srv.URL) svc, logs := newLoggingService(http.DefaultTransport) svc.SetNtfyURL(topicURL) // Never let the backoff sleep complete: the delivery is // parked in its retry wait until shutdown releases it. svc.SetSleepFunc(neverFires) svc.SetRetryConfig(notify.RetryConfig{ MaxRetries: 5, BaseDelay: time.Hour, MaxDelay: time.Hour, }) svc.SendNotification( context.Background(), "t", "m", prioError, ) waitForCondition(t, func() bool { return requests.Load() >= 1 && 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() // 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 -timeout. returned := make(chan struct{}) go func() { defer close(returned) svc.Drain(ctx) }() select { case <-returned: case <-time.After(timeoutDrainBound): t.Fatalf( "drain did not return within %v; its %v deadline "+ "did not bound it", timeoutDrainBound, drainDeadline, ) } // 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 returned after %v, before its %v deadline", elapsed, drainDeadline, ) } assertAbandonLogged(t, logs.String()) // The abandoned delivery must stop retrying rather than // outlive the drain. waitForCondition(t, func() bool { return svc.OutstandingDeliveries() == 0 }) } // assertAbandonLogged checks that the drain logged the // abandoned deliveries at warn level with a count. func assertAbandonLogged(t *testing.T, output string) { t.Helper() if !strings.Contains(output, `"level":"WARN"`) { t.Errorf( "abandoned deliveries not logged at warn level; "+ "log output: %s", output, ) } if !strings.Contains(output, `"abandoned":1`) { t.Errorf( "abandoned delivery count not logged; "+ "log output: %s", output, ) } } // TestDrainRefusesNewDeliveries verifies that notifications // submitted after the drain has begun are refused and logged, // so a stream of new work cannot extend shutdown indefinitely. func TestDrainRefusesNewDeliveries(t *testing.T) { t.Parallel() var requests atomic.Int64 srv := httptest.NewServer( http.HandlerFunc( func(w http.ResponseWriter, _ *http.Request) { requests.Add(1) w.WriteHeader(http.StatusOK) }), ) defer srv.Close() target, _ := url.Parse(srv.URL) svc, logs := newLoggingService(http.DefaultTransport) svc.SetNtfyURL(target) svc.SetSlackWebhookURL(target) svc.SetMattermostWebhookURL(target) ctx, cancel := context.WithTimeout( context.Background(), longDrainDeadline, ) defer cancel() // Nothing is in flight, so this returns immediately and // leaves the service refusing further deliveries. svc.Drain(ctx) for range 3 { svc.SendNotification( context.Background(), "t", "m", prioInfo, ) } time.Sleep(settleDelay) if got := requests.Load(); got != 0 { t.Errorf( "%d requests reached the endpoint after drain, "+ "want 0", got, ) } if got := svc.OutstandingDeliveries(); got != 0 { t.Errorf("outstanding deliveries = %d, want 0", got) } output := logs.String() if !strings.Contains(output, "shutdown in progress") { t.Errorf( "refused deliveries not logged; log output: %s", output, ) } } // recordingLifecycle is a minimal fx.Lifecycle that records the // hooks appended to it, so the wiring done by notify.New can be // inspected without standing up a whole fx application. type recordingLifecycle struct { hooks []fx.Hook } func (l *recordingLifecycle) Append(hook fx.Hook) { l.hooks = append(l.hooks, hook) } // newNotifyService builds a Service through the real // constructor, wired to the given lifecycle. func newNotifyService( t *testing.T, lifecycle fx.Lifecycle, ntfyTopic string, ) *notify.Service { t.Helper() g, err := globals.New(nil) if err != nil { t.Fatalf("globals.New: %v", err) } log, err := logger.New(nil, logger.Params{Globals: g}) if err != nil { t.Fatalf("logger.New: %v", err) } svc, err := notify.New(lifecycle, notify.Params{ Logger: log, Config: &config.Config{NtfyTopic: ntfyTopic}, }) if err != nil { t.Fatalf("notify.New: %v", err) } return svc } // TestNewRegistersDrainingStopHook verifies that notify.New // wires an OnStop hook into the fx lifecycle and that the hook // waits for in-flight deliveries. func TestNewRegistersDrainingStopHook(t *testing.T) { t.Parallel() var served atomic.Bool entered := make(chan struct{}) release := make(chan struct{}) srv := blockingNtfyServer(entered, release, &served) defer srv.Close() // As in TestDrainWaitsForInFlightDelivery: release the handler // however the test ends, before srv.Close waits for it. releaseHandler := sync.OnceFunc(func() { close(release) }) defer releaseHandler() lifecycle := &recordingLifecycle{} svc := newNotifyService(t, lifecycle, srv.URL) if len(lifecycle.hooks) != 1 { t.Fatalf( "appended %d lifecycle hooks, want 1", len(lifecycle.hooks), ) } stop := lifecycle.hooks[0].OnStop if stop == nil { t.Fatal("lifecycle hook has no OnStop function") } svc.SendNotification( context.Background(), "t", "m", prioInfo, ) select { case <-entered: case <-time.After(reachEndpointTimeout): t.Fatal("delivery never reached the endpoint") } timer := time.AfterFunc(inFlightHold, releaseHandler) defer timer.Stop() ctx, cancel := context.WithTimeout( context.Background(), longDrainDeadline, ) defer cancel() err := stop(ctx) if err != nil { t.Fatalf("OnStop returned error: %v", err) } if !served.Load() { t.Error( "OnStop returned before the in-flight delivery " + "completed", ) } } // TestDrainWithoutDeliveriesReturnsImmediately verifies the // common case: nothing in flight, shutdown is not delayed. func TestDrainWithoutDeliveriesReturnsImmediately(t *testing.T) { t.Parallel() 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(), longDrainDeadline, ) defer cancel() svc.Drain(ctx) if elapsed := time.Since(start); elapsed > idleDrainBound { t.Errorf( "drain of an idle service took %v, want at most "+ "%v; its deadline was %v", elapsed, idleDrainBound, longDrainDeadline, ) } } // 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, 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() svc, logs := newLoggingService(http.DefaultTransport) ctx, cancel := context.WithCancel(context.Background()) cancel() // A watchdog, as in TestDrainBoundedByContextDeadline, so // that a drain which never returns fails here instead of // hanging the package. returned := make(chan struct{}) 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", output, ) } }