Files
meshcore-analyzer/cmd/server/analytics_warmup_1659_test.go
T
efitenandClaude Opus 5 2d4019f719 fix(analytics): recompute once the store has fully loaded (#2025)
Refs #2023, #1659, #1724

### Problem
`main.go:258` waits only for the first load chunk, then `main.go:402`
starts the analytics recomputers. `Start()` computes immediately on that
chunk (`analytics_recomputer.go:86` on master) and the next compute
waits a full interval (`:93`, 5 min default). The chunk loader walks by
ascending id, so that chunk holds the oldest transmissions.

- RF, topology, channels: the #1659 gate checked `LoadComplete()` after
the compute (`analytics_warmup_1659.go:122`). `LoadComplete` flips at
the end of the hot window (`chunked_load.go:489`), before the background
fill (`store.go:1455`), so the gate could open on a snapshot without the
background fill, and the 60 s force timeout (`:73`, `:162`) opened it on
the first-chunk snapshot. In an end-to-end test on master,
`/api/analytics/rf` returned 200 with 8 of 100 packets before the
background fill ran.
- Distance, hash-collisions, hash-sizes, roles, observers-clock-skew,
nodes-clock-skew: no gate, partial snapshot served from the start.
- Distance additionally served a snapshot from the previous index for up
to one interval after each lazy index build.

On a staging instance, a default analytics request returned 5,911
packets with hours-old last buckets until the next recompute (about
74k).

### Change
- `StartupLoadDone()` (`chunked_load.go:108`): closed when
`RunStartupLoad` returns, on every path (`chunked_load.go:202`). Closing
it drops the hash-size info cache (15 s TTL) and the clock-skew engine
throttle (30 s, `clock_skew.go:225`), both read by the post-load
computes.
- `recomputeWhenLoaded` (`analytics_recomputer.go:172`): on that signal,
recompute each recomputer once, sequentially, via `RecomputeNow`
(`:154`), which runs on the recomputer's own loop and restarts its
ticker (`:106`). Order (`:255`): rf, topology, channels, distance,
hash-collisions, hash-sizes, observers-clock-skew, nodes-clock-skew,
roles (roles reads the nodes-clock-skew snapshot). Logs one line with
per-recomputer durations.
- Warm-up gate: now the same signal (`:343-354`), sampled before the
compute starts (`:129`), so a pass that began on partial data never
opens it. 503 + `Retry-After: 5` and the force timeout are unchanged; a
forced-open snapshot is replaced by the post-load recompute.
- Ungated endpoints: no new 503s (their API has none); snapshot replaced
right after the load.
- Distance: the lazy index build refreshes the distance recomputer
before reporting built (`store.go:4476`).
- Recompute intervals and config unchanged.

### Performance
One extra compute per recomputer per process start, run sequentially so
they do not all hold the store read lock at once. Ticker phases
afterwards are offset by the cumulative post-load compute durations
instead of all starting within the first-chunk compute window (relevant
to #1724; the effect on lock waves is not measured).

### Tests
`analytics_recompute_after_load_test.go`: signal open during background
fill, closed after success and failure; cache drops; immediate and
ordered post-load recompute; gate not opened by a pass started before
the load; forced-open snapshot replaced on load; ticker restart;
distance refresh before 202 ends; end to end with recomputers started
before the background fill (RF 503 until load, then `totalTransmissions`
equals the full store; six ungated endpoints 200 during load; all nine
recomputed after load). 9 of these failed on master with stubs; 8
single-line mutations each caught. `go test ./...` in `cmd/server`
passes.

### Staging validation
Deployed together with the review follow-ups of #2015-#2023 (build
`c646310f`), container restart:

```
16:35:20 [store] first chunk ready (chunkSize=10000)
16:35:25 [store] LoadChunked complete ... starting background fill loader
16:36:58 [store] background load complete: 121120/121282 packets in memory (coverage=99.9%)
16:37:03 [analytics-recompute] startup load done: recomputed 10 snapshots in 5.155s (rf=955ms topology=1.684s channels=43ms distance=49ms hash-collisions=30ms hash-sizes=338ms observers-clock-skew=369ms nodes-clock-skew=692ms roles=2ms retransmissions=994ms)
```

Right after that line, `/api/analytics/rf` reported `totalTransmissions`
121,121 against 120,700 packets in memory, and the retransmissions
default shape from #2023 covered the full 7 days. Before this change
both waited for the next 5 minute tick.

### Merge order with #2023
#2023 adds a tenth recomputer. Whichever of the two merges second has to
add `recompRetransmissions` to `analyticsRecomputersLocked`, wire it to
`loadedGate` instead of `LoadComplete`, and change 9 to 10 in
`TestAnalyticsRecomputers_PostLoadOrder`; the retransmissions gate test
then calls `signalStartupLoadDone()` instead of setting `loadComplete`.
That resolution is what ran on staging above.

### Not verified
- Repeater-enrich recomputer and the region/window TTL caches
(hash-collisions region results have a 1 h TTL) may also keep partial
results after the load; not changed here.
- Recompute order is tested structurally, not with roles/clock-skew
data.
- Whether this reduces the #1724 stalls; not measured.

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-13 19:59:37 +02:00

332 lines
11 KiB
Go

// Package main: issue #1659 — analytics warmup gating.
//
// After a server restart, the analytics recomputer caches the FIRST
// computation (a small in-RAM slice) and serves it via the default
// region="", zero-window shortcut in GetAnalyticsRFWithWindow until the
// next periodic recompute fires. The client-side CLIENT_TTL.analyticsRF
// then pins that small slice on the page even after the server flips
// to steady-state.
//
// Fix: each recomputer carries a firstPassDoneAt timestamp set ONLY
// after a full-range compute completes. While firstPassDoneAt is zero
// AND the request is the default-shape (region="" && area="" &&
// window.IsZero()), the handler returns 503 + Retry-After: 5 with a
// JSON body the client recognizes and retries with backoff.
//
// These tests are the RED contract: they must FAIL on the assertion
// (not a build error) when the warmup gate is absent, and PASS once
// the fix lands.
package main
import (
"encoding/json"
"net/http"
"net/http/httptest"
"testing"
"time"
"github.com/gorilla/mux"
)
// TestAnalyticsRF_WarmupReturns503 asserts that immediately after the
// server starts — before any analytics recomputer has finished its
// first full-range pass — GET /api/analytics/rf returns 503 with
// Retry-After: 5 and a JSON body shaped as
// {"error":"analytics warming up","retry_after_s":5}.
//
// This is the core acceptance criterion (c) from #1659.
func TestAnalyticsRF_WarmupReturns503(t *testing.T) {
db := setupTestDB(t)
defer db.Close()
store := NewPacketStore(db, nil)
// Register recomputers but DO NOT let them complete a first pass.
// We install a compute func that blocks until we release it, so the
// recomputer's firstPassDoneAt stays zero.
block := make(chan struct{})
defer close(block)
store.installWarmupBlocker_1659(block) // helper added in GREEN
cfg := &Config{Port: 3000}
hub := NewHub()
srv := NewServer(db, cfg, hub)
srv.store = store
router := mux.NewRouter()
srv.RegisterRoutes(router)
req := httptest.NewRequest("GET", "/api/analytics/rf", nil)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
if w.Code != http.StatusServiceUnavailable {
t.Fatalf("expected 503 during warmup, got %d (body=%s)", w.Code, w.Body.String())
}
if got := w.Header().Get("Retry-After"); got != "5" {
t.Fatalf("expected Retry-After: 5, got %q", got)
}
var resp map[string]interface{}
if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil {
t.Fatalf("invalid JSON body: %v (raw=%s)", err, w.Body.String())
}
if resp["error"] != "analytics warming up" {
t.Fatalf("expected error='analytics warming up', got %v", resp["error"])
}
if v, ok := resp["retry_after_s"].(float64); !ok || v != 5 {
t.Fatalf("expected retry_after_s=5, got %v", resp["retry_after_s"])
}
}
// TestAnalyticsRF_AfterFirstPassReturns200 asserts the post-warmup
// happy path: once the recomputer's first full-range compute completes,
// the handler serves the cached snapshot as 200.
func TestAnalyticsRF_AfterFirstPassReturns200(t *testing.T) {
db := setupTestDB(t)
defer db.Close()
store := NewPacketStore(db, nil)
// #1688 r1: the warmup gate ALSO requires the startup load (hot
// window and background fill) to be done before first-pass-done
// flips (munger #5). Tests that don't exercise the loader must
// signal it manually to model a production server that has
// finished cold-loading.
store.signalStartupLoadDone()
stop := store.StartAnalyticsRecomputers(50 * time.Millisecond)
defer stop()
// Wait for the synchronous first-pass to complete. Start() runs
// the initial compute synchronously, so by the time it returns
// firstPassDoneAt should be set. We poll a brief moment to keep
// the test robust to scheduling.
deadline := time.Now().Add(3 * time.Second)
for time.Now().Before(deadline) {
if store.recompRF != nil && !store.recompRF.FirstPassDoneAt_1659().IsZero() {
break
}
time.Sleep(10 * time.Millisecond)
}
if store.recompRF == nil || store.recompRF.FirstPassDoneAt_1659().IsZero() {
t.Fatal("recompRF.firstPassDoneAt never flipped after Start()")
}
cfg := &Config{Port: 3000}
hub := NewHub()
srv := NewServer(db, cfg, hub)
srv.store = store
router := mux.NewRouter()
srv.RegisterRoutes(router)
req := httptest.NewRequest("GET", "/api/analytics/rf", nil)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
if w.Code != http.StatusOK {
t.Fatalf("expected 200 after first pass, got %d (body=%s)", w.Code, w.Body.String())
}
if got := w.Header().Get("Retry-After"); got != "" {
t.Fatalf("expected no Retry-After header on 200, got %q", got)
}
// Body should be a valid JSON object (the RF analytics map).
var resp map[string]interface{}
if err := json.Unmarshal(w.Body.Bytes(), &resp); err != nil {
t.Fatalf("invalid JSON body: %v", err)
}
if len(resp) == 0 {
t.Fatal("expected non-empty RF analytics response after first pass")
}
}
// TestAnalyticsRF_WindowedRequestNotGated asserts that even during
// warmup, a request with an explicit time window (?since=/?until=) or
// region/area filter is NOT gated by the warmup flag — those queries
// bypass the recomputer entirely and hit the legacy compute-then-cache
// path, which is unaffected by the first-pass bug.
func TestAnalyticsRF_WindowedRequestNotGated(t *testing.T) {
db := setupTestDB(t)
defer db.Close()
store := NewPacketStore(db, nil)
block := make(chan struct{})
defer close(block)
store.installWarmupBlocker_1659(block)
cfg := &Config{Port: 3000}
hub := NewHub()
srv := NewServer(db, cfg, hub)
srv.store = store
router := mux.NewRouter()
srv.RegisterRoutes(router)
// Explicit window — should bypass warmup gate.
req := httptest.NewRequest("GET", "/api/analytics/rf?window=1h", nil)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
if w.Code == http.StatusServiceUnavailable {
t.Fatalf("windowed request must NOT be gated by warmup (got 503)")
}
}
// === PR #1688 r1 — new test cases ===
// TestAnalyticsTopology_WarmupReturns503 — kent-beck #1: topology
// gate is symmetric with RF; assert the same 503 contract.
func TestAnalyticsTopology_WarmupReturns503(t *testing.T) {
db := setupTestDB(t)
defer db.Close()
store := NewPacketStore(db, nil)
block := make(chan struct{})
defer close(block)
store.installWarmupBlocker_1659(block)
cfg := &Config{Port: 3000}
hub := NewHub()
srv := NewServer(db, cfg, hub)
srv.store = store
router := mux.NewRouter()
srv.RegisterRoutes(router)
req := httptest.NewRequest("GET", "/api/analytics/topology", nil)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
if w.Code != http.StatusServiceUnavailable {
t.Fatalf("topology: expected 503 during warmup, got %d", w.Code)
}
if got := w.Header().Get("Retry-After"); got != "5" {
t.Fatalf("topology: expected Retry-After: 5, got %q", got)
}
}
// TestAnalyticsChannels_WarmupReturns503 — kent-beck #1: channels
// gate is symmetric with RF; assert the same 503 contract.
func TestAnalyticsChannels_WarmupReturns503(t *testing.T) {
db := setupTestDB(t)
defer db.Close()
store := NewPacketStore(db, nil)
block := make(chan struct{})
defer close(block)
store.installWarmupBlocker_1659(block)
cfg := &Config{Port: 3000}
hub := NewHub()
srv := NewServer(db, cfg, hub)
srv.store = store
router := mux.NewRouter()
srv.RegisterRoutes(router)
req := httptest.NewRequest("GET", "/api/analytics/channels", nil)
w := httptest.NewRecorder()
router.ServeHTTP(w, req)
if w.Code != http.StatusServiceUnavailable {
t.Fatalf("channels: expected 503 during warmup, got %d", w.Code)
}
if got := w.Header().Get("Retry-After"); got != "5" {
t.Fatalf("channels: expected Retry-After: 5, got %q", got)
}
}
// TestWarmup_GateBlockedUntilLoadComplete — munger #5 correctness:
// the chunked loader readiness MUST gate first-pass-done. A recomputer
// pass that completes while LoadComplete() is false must NOT lift the
// gate; a SUBSEQUENT pass after LoadComplete() flips true must lift it.
func TestWarmup_GateBlockedUntilLoadComplete(t *testing.T) {
db := setupTestDB(t)
defer db.Close()
store := NewPacketStore(db, nil)
// LoadComplete starts false — chunked loader still running.
called := make(chan struct{}, 16)
rc := newAnalyticsRecomputer("test-rf", time.Hour, func() interface{} {
called <- struct{}{}
return map[string]int{"x": 1}
})
rc.setWarmupReadyGate_1659(store.LoadComplete)
rc.Start()
defer rc.Stop()
// First pass already ran synchronously in Start(). Gate must still
// be warming up because LoadComplete() is false.
<-called
if !rc.IsWarmingUp_1659() {
t.Fatalf("expected IsWarmingUp_1659=true while LoadComplete()=false (munger #5 bug)")
}
if !rc.FirstPassDoneAt_1659().IsZero() {
t.Fatalf("expected FirstPassDoneAt zero while LoadComplete()=false")
}
// Now flip the loader and trigger another pass.
store.loadComplete.Store(true)
rc.runOnce()
if rc.IsWarmingUp_1659() {
t.Fatalf("expected gate to lift after LoadComplete()=true + another pass")
}
}
// TestWarmup_NilResultStillLiftsGate — munger #2 / kent-beck #2:
// a compute that returns nil but doesn't panic must still flip the
// gate (the cache stays empty but the banner does NOT get stuck).
func TestWarmup_NilResultStillLiftsGate(t *testing.T) {
rc := newAnalyticsRecomputer("test-nil", time.Hour, func() interface{} {
return nil
})
rc.Start()
defer rc.Stop()
if rc.IsWarmingUp_1659() {
t.Fatalf("nil-result compute must still lift warmup gate after first pass")
}
}
// TestWarmup_PanicEventuallyLiftsGate — munger #2 / kent-beck #2:
// a compute that ALWAYS panics must not leave the gate stuck forever.
// The fallback timeout (warmupForceTimeout) is the safety net.
func TestWarmup_PanicEventuallyLiftsGate(t *testing.T) {
prev := warmupForceTimeout
warmupForceTimeout = 50 * time.Millisecond
defer func() { warmupForceTimeout = prev }()
rc := newAnalyticsRecomputer("test-panic", time.Hour, func() interface{} {
panic("compute boom")
})
rc.Start()
defer rc.Stop()
// Panic was recovered inside runOnce; firstPassDoneNs is still 0.
if rc.FirstPassDoneAt_1659().IsZero() == false {
t.Fatalf("panicking compute should not have set firstPassDoneNs")
}
// But after warmupForceTimeout elapses, the gate must lift.
time.Sleep(80 * time.Millisecond)
if rc.IsWarmingUp_1659() {
t.Fatalf("expected fallback timeout to lift gate after warmupForceTimeout (got still-warming)")
}
}
// TestWarmup_TimeoutLiftsHangingCompute — munger #2 / kent-beck #2:
// hung compute (blocks indefinitely on a channel) must not result in
// permanent 503. Fallback timeout lifts it.
func TestWarmup_TimeoutLiftsHangingCompute(t *testing.T) {
prev := warmupForceTimeout
warmupForceTimeout = 50 * time.Millisecond
defer func() { warmupForceTimeout = prev }()
block := make(chan struct{})
defer close(block)
rc := newAnalyticsRecomputer("test-hang", time.Hour, func() interface{} {
<-block
return nil
})
// Don't call Start (would block forever on synchronous initial
// compute). Just simulate "we noted warmup start, compute is
// hanging in another goroutine".
rc.noteWarmupStart_1659()
go rc.runOnce()
if !rc.IsWarmingUp_1659() {
t.Fatalf("expected initial state to be warming-up")
}
time.Sleep(80 * time.Millisecond)
if rc.IsWarmingUp_1659() {
t.Fatalf("expected fallback timeout to lift hung-compute warmup")
}
}