dnswatcher/internal/notify/shutdown_test.go

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,
		)
	}
}