ctrld/cmd/cli/query_health_test.go

package cli

import (
	"fmt"
	"reflect"
	"slices"
	"strings"
	"sync"
	"testing"
	"time"

	"github.com/rs/zerolog"
)

// queryHealthBase is the start time of every tracker test. The tracker takes
// the time from the caller, so no test waits for a real clock.
var queryHealthBase = time.Date(2026, 9, 16, 12, 0, 0, 0, time.UTC)

// feedQueryHealth counts queries, and one failed query for each failure of a
// class. The grade follows the failed queries, so a test that wants a class
// gives the failures that produced it.
func feedQueryHealth(q *queryHealth, queries int, failures map[string]int) {
	for i := 0; i < queries; i++ {
		q.countQuery()
	}
	for class, count := range failures {
		for i := 0; i < count; i++ {
			q.countFailure(class)
			q.countFailedQuery()
		}
	}
}

// waitForLogLine polls the buffer, because the loop logs from its own goroutine.
func waitForLogLine(t *testing.T, logs *syncBuffer, message string) {
	t.Helper()
	waitForLogLineOrExplain(t, logs, message, nil)
}

// waitForLogLineOrExplain is waitForLogLine with extra text for the failure.
func waitForLogLineOrExplain(t *testing.T, logs *syncBuffer, message string, explain func() string) {
	t.Helper()
	deadline := time.Now().Add(2 * time.Second)
	for time.Now().Before(deadline) {
		if strings.Contains(logs.String(), message) {
			return
		}
		time.Sleep(time.Millisecond)
	}
	extra := ""
	if explain != nil {
		extra = " " + explain()
	}
	t.Fatalf("no %q line before the deadline (global level %s, captured %q)%s", message, zerolog.GlobalLevel(), logs.String(), extra)
}

// loggerSwapRecord is one change of the main logger or of the global level.
type loggerSwapRecord struct {
	at     time.Duration
	level  zerolog.Level
	writer string
}

// watchLoggerSwaps records every change of the main logger and of the global
// level while the test runs, so a missing line names what took the logger.
func watchLoggerSwaps(t *testing.T) func() string {
	t.Helper()
	start := time.Now()
	stop := make(chan struct{})
	done := make(chan struct{})
	var mu sync.Mutex
	var records []loggerSwapRecord
	go func() {
		defer close(done)
		lastLogger, lastLevel := mainLog.Load(), zerolog.GlobalLevel()
		for {
			select {
			case <-stop:
				return
			default:
			}
			logger, level := mainLog.Load(), zerolog.GlobalLevel()
			if logger != lastLogger || level != lastLevel {
				mu.Lock()
				records = append(records, loggerSwapRecord{time.Since(start), level, loggerWriterType(logger)})
				mu.Unlock()
				lastLogger, lastLevel = logger, level
			}
			time.Sleep(50 * time.Microsecond)
		}
	}()
	t.Cleanup(func() { close(stop); <-done })
	return func() string {
		mu.Lock()
		defer mu.Unlock()
		parts := make([]string, 0, len(records))
		for _, r := range slices.Clone(records) {
			parts = append(parts, fmt.Sprintf("{at=%s level=%s writer=%s}", r.at, r.level, r.writer))
		}
		return fmt.Sprintf("swaps=%d %s current=%s", len(records), strings.Join(parts, " "), loggerWriterType(mainLog.Load()))
	}
}

// loggerWriterType names the writer behind a logger through its unexported
// field, so a swapped logger tells which init function built it.
func loggerWriterType(l *zerolog.Logger) string {
	if l == nil {
		return "nil"
	}
	w := reflect.ValueOf(l).Elem().FieldByName("w")
	if !w.IsValid() || w.IsNil() {
		return "none"
	}
	inner := w.Elem()
	name := inner.Type().String()
	if inner.Kind() == reflect.Struct && inner.NumField() == 1 && inner.Field(0).Kind() == reflect.Interface && !inner.Field(0).IsNil() {
		name += "(" + inner.Field(0).Elem().Type().String() + ")"
	}
	return name
}

func Test_queryHealthClassThresholds(t *testing.T) {
	// The class names go into the journal, so the test pins the text.
	tests := []struct {
		name     string
		queries  int
		failures int
		want     string
	}{
		{"no queries", 0, 0, "healthy"},
		{"two percent", 100, 2, "healthy"},
		{"five percent", 100, 5, "degraded"},
		{"six percent", 100, 6, "degraded"},
		{"half of twenty", 20, 12, "failing"},
		{"half of ten", 10, 5, "failing"},
		{"small sample cannot fail", 9, 9, "healthy"},
		{"small sample cannot degrade", 9, 1, "healthy"},
	}
	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			q := newQueryHealth()
			feedQueryHealth(q, tc.queries, map[string]int{sampleClassResolveFailed: tc.failures})

			event, emit := q.evaluate(queryHealthBase, 0, false)
			if !emit {
				t.Fatal("the first evaluate did not emit")
			}
			if event.Class != tc.want {
				t.Fatalf("class: got %q, want %q", event.Class, tc.want)
			}
		})
	}
}

func Test_queryHealthEmitsHeartbeatWithoutClassChange(t *testing.T) {
	q := newQueryHealth()
	if _, emit := q.evaluate(queryHealthBase, 0, false); !emit {
		t.Fatal("the first evaluate did not emit")
	}

	for _, minutes := range []int{1, 7, 14} {
		at := queryHealthBase.Add(time.Duration(minutes) * time.Minute)
		if _, emit := q.evaluate(at, 0, false); emit {
			t.Fatalf("emit at minute %d without a class change", minutes)
		}
	}

	event, emit := q.evaluate(queryHealthBase.Add(15*time.Minute), 0, false)
	if !emit {
		t.Fatal("no heartbeat at 15 minutes")
	}
	if event.Class != "healthy" {
		t.Fatalf("heartbeat class: got %q, want %q", event.Class, "healthy")
	}
	if _, emit := q.evaluate(queryHealthBase.Add(16*time.Minute), 0, false); emit {
		t.Fatal("a second emit follows the heartbeat")
	}
}

func Test_queryHealthEmitsOnClassChange(t *testing.T) {
	q := newQueryHealth()
	feedQueryHealth(q, 100, nil)
	event, emit := q.evaluate(queryHealthBase, 0, false)
	if !emit || event.Class != "healthy" {
		t.Fatalf("first report: emit %v, class %q", emit, event.Class)
	}

	feedQueryHealth(q, 0, map[string]int{sampleClassResolveFailed: 50})
	if _, emit := q.evaluate(queryHealthBase.Add(time.Minute), 0, false); emit {
		t.Fatal("emit on the first tick of the new class")
	}

	event, emit = q.evaluate(queryHealthBase.Add(2*time.Minute), 0, false)
	if !emit {
		t.Fatal("no emit after the new class held two ticks")
	}
	if event.Class != "failing" {
		t.Fatalf("class: got %q, want %q", event.Class, "failing")
	}

	if _, emit := q.evaluate(queryHealthBase.Add(3*time.Minute), 0, false); emit {
		t.Fatal("emit without a class change")
	}
}

// Test_queryHealthHoldsAClassChangeForTwoTicks proves that a class which lasts
// one tick reports nothing. A minute of noise must not open an event.
func Test_queryHealthHoldsAClassChangeForTwoTicks(t *testing.T) {
	q := newQueryHealth()
	feedQueryHealth(q, 20, nil)
	event, emit := q.evaluate(queryHealthBase, 0, false)
	if !emit || event.Class != queryHealthHealthy {
		t.Fatalf("first report: emit %v, class %q", emit, event.Class)
	}

	feedQueryHealth(q, 0, map[string]int{sampleClassResolveFailed: 12})
	if event, emit := q.evaluate(queryHealthBase.Add(time.Minute), 0, false); emit {
		t.Fatalf("emit after one tick of class %q", event.Class)
	}

	// The next tick grades the same window as degraded, so the failing class
	// never held two ticks and never reported.
	feedQueryHealth(q, 80, nil)
	if event, emit := q.evaluate(queryHealthBase.Add(2*time.Minute), 0, false); emit {
		t.Fatalf("emit after the class moved again to %q", event.Class)
	}

	event, emit = q.evaluate(queryHealthBase.Add(3*time.Minute), 0, false)
	if !emit {
		t.Fatal("no emit after the new class held two ticks")
	}
	if event.Class != queryHealthDegraded {
		t.Fatalf("class: got %q, want %q", event.Class, queryHealthDegraded)
	}
}

// Test_queryHealthNeedsASampleBeforeAClassChange proves that the empty window
// which follows a heartbeat reports nothing. The counters start at zero, and
// zero queries say nothing about the query path.
func Test_queryHealthNeedsASampleBeforeAClassChange(t *testing.T) {
	q := newQueryHealth()
	feedQueryHealth(q, 20, map[string]int{sampleClassResolveFailed: 12})
	event, emit := q.evaluate(queryHealthBase, 0, false)
	if !emit || event.Class != queryHealthFailing {
		t.Fatalf("first report: emit %v, class %q", emit, event.Class)
	}

	event, emit = q.evaluate(queryHealthBase.Add(15*time.Minute), 0, false)
	if !emit || event.Class != queryHealthFailing {
		t.Fatalf("window end: emit %v, class %q", emit, event.Class)
	}

	for _, minutes := range []int{16, 17} {
		at := queryHealthBase.Add(time.Duration(minutes) * time.Minute)
		if event, emit := q.evaluate(at, 0, false); emit {
			t.Fatalf("emit at minute %d with %d queries and class %q", minutes, event.Queries, event.Class)
		}
	}
}

func Test_queryHealthCacheHitRatio(t *testing.T) {
	q := newQueryHealth()
	event, _ := q.evaluate(queryHealthBase, 0, false)
	if event.CacheHitRatio != 0 {
		t.Fatalf("ratio without queries: got %v, want 0", event.CacheHitRatio)
	}

	feedQueryHealth(q, 20, nil)
	for i := 0; i < 5; i++ {
		q.countCacheHit()
	}

	event, _ = q.evaluate(queryHealthBase.Add(time.Minute), 0, false)
	if event.Queries != 20 || event.CacheHits != 5 {
		t.Fatalf("counters: got %d queries and %d cache hits, want 20 and 5", event.Queries, event.CacheHits)
	}
	if event.CacheHitRatio != 0.25 {
		t.Fatalf("ratio: got %v, want 0.25", event.CacheHitRatio)
	}
}

func Test_queryHealthResetsCountersAtWindowEnd(t *testing.T) {
	q := newQueryHealth()
	if _, emit := q.evaluate(queryHealthBase, 0, false); !emit {
		t.Fatal("the first evaluate did not emit")
	}
	feedQueryHealth(q, 20, map[string]int{sampleClassResolveFailed: 12})
	q.countCacheHit()

	closed, emit := q.evaluate(queryHealthBase.Add(15*time.Minute), 0, false)
	if !emit {
		t.Fatal("no emit at the window end")
	}
	if closed.Queries != 20 || closed.CacheHits != 1 || closed.Failures[sampleClassResolveFailed] != 12 {
		t.Fatalf("the closed window lost its counters: %+v", closed)
	}

	q.countFailure(sampleClassResolveFailed)
	next, _ := q.evaluate(queryHealthBase.Add(16*time.Minute), 0, false)
	if next.Queries != 0 || next.CacheHits != 0 {
		t.Fatalf("the counters survived the window end: %+v", next)
	}
	if next.Failures[sampleClassResolveFailed] != 1 {
		t.Fatalf("failures of the new window: got %d, want 1", next.Failures[sampleClassResolveFailed])
	}
}

func Test_queryHealthReportKeepsItsOwnFailures(t *testing.T) {
	q := newQueryHealth()
	feedQueryHealth(q, 10, map[string]int{sampleClassResolveFailed: 1})

	report, _ := q.evaluate(queryHealthBase, 0, false)
	q.countFailure(sampleClassResolveFailed)

	if got := report.Failures[sampleClassResolveFailed]; got != 1 {
		t.Fatalf("the report shares the live failure map: got %d, want 1", got)
	}
}

func Test_queryHealthLogsJournalEvent(t *testing.T) {
	swaps := watchLoggerSwaps(t)
	logs := captureDebugMainLog(t)
	q := newQueryHealth()
	feedQueryHealth(q, 20, map[string]int{
		sampleClassResolveFailed:      8,
		sampleClassAllEndpointsFailed: 4,
	})
	for i := 0; i < 5; i++ {
		q.countCacheHit()
	}

	event, emit := q.evaluate(queryHealthBase, 2, true)
	if !emit {
		t.Fatal("the first evaluate did not emit")
	}
	q.log(event)

	events := jsonLogEvents(t, logs, queryHealthMessage)
	if len(events) != 1 {
		t.Fatalf("health lines: got %d, want 1 (global level %s, captured %q) %s", len(events), zerolog.GlobalLevel(), logs.String(), swaps())
	}
	logged := events[0]
	wantField(t, logged, "journal", true)
	wantField(t, logged, "level", "info")
	wantField(t, logged, "class", "failing")
	wantField(t, logged, "window_s", float64(900))
	wantField(t, logged, "queries", float64(20))
	wantField(t, logged, "cache_hits", float64(5))
	wantField(t, logged, "upstreams_down", float64(2))
	wantField(t, logged, "bypass_active", true)
	wantField(t, logged, "cache_hit_ratio", 0.25)

	failures, ok := logged["failures_by_class"].(map[string]any)
	if !ok {
		t.Fatalf("failures_by_class: got %T, want an object", logged["failures_by_class"])
	}
	if len(failures) != 2 {
		t.Fatalf("failure classes: got %d, want 2", len(failures))
	}
	wantField(t, failures, sampleClassResolveFailed, float64(8))
	wantField(t, failures, sampleClassAllEndpointsFailed, float64(4))
}

func Test_queryHealthLoopEmitsUntilStop(t *testing.T) {
	swaps := watchLoggerSwaps(t)
	logs := captureDebugMainLog(t)
	tick := queryHealthTick
	defer func() { queryHealthTick = tick }()
	queryHealthTick = time.Millisecond

	q := newQueryHealth()
	stop := make(chan struct{})
	done := make(chan struct{})
	var once sync.Once
	stopLoop := func() {
		once.Do(func() {
			close(stop)
			<-done
		})
	}
	defer stopLoop()

	go func() {
		defer close(done)
		q.loop(stop, func() (int, bool) { return 1, true })
	}()

	waitForLogLineOrExplain(t, logs, queryHealthMessage, swaps)
	stopLoop()

	events := jsonLogEvents(t, logs, queryHealthMessage)
	if len(events) == 0 {
		t.Fatal("the loop logged no health event")
	}
	wantField(t, events[0], "journal", true)
	wantField(t, events[0], "upstreams_down", float64(1))
	wantField(t, events[0], "bypass_active", true)
}

// Test_queryHealthReportsEveryWindowAfterAnEarlyEmit proves that a class
// change in the middle of a window does not make the rest of the window
// vanish. The heartbeat follows the window, not the last report.
func Test_queryHealthReportsEveryWindowAfterAnEarlyEmit(t *testing.T) {
	q := newQueryHealth()
	if _, emit := q.evaluate(queryHealthBase, 0, false); !emit {
		t.Fatal("the first evaluate did not emit")
	}
	feedQueryHealth(q, 20, map[string]int{sampleClassResolveFailed: 20})
	if _, emit := q.evaluate(queryHealthBase.Add(5*time.Minute), 0, false); emit {
		t.Fatal("emit on the first tick of the new class")
	}
	event, emit := q.evaluate(queryHealthBase.Add(6*time.Minute), 0, false)
	if !emit || event.Class != queryHealthFailing {
		t.Fatalf("class change at 6 minutes: emit %v, class %q", emit, event.Class)
	}
	feedQueryHealth(q, 7, nil)
	event, emit = q.evaluate(queryHealthBase.Add(15*time.Minute), 0, false)
	if !emit {
		t.Fatal("the end of the window did not emit")
	}
	if event.Queries != 27 {
		t.Fatalf("queries in the window report: got %d, want 27", event.Queries)
	}
}