diff --git a/cmd/ingestor/db.go b/cmd/ingestor/db.go index cfc6ce1c1..042af9153 100644 --- a/cmd/ingestor/db.go +++ b/cmd/ingestor/db.go @@ -76,6 +76,8 @@ type Store struct { stmtGetTxByHash *sql.Stmt stmtInsertTransmission *sql.Stmt stmtUpdateTxFirstSeen *sql.Stmt + stmtOrTxRouteMask *sql.Stmt + stmtInsertRouteMaskChange *sql.Stmt stmtBumpTxLastSeen *sql.Stmt stmtInsertObservation *sql.Stmt stmtUpsertNode *sql.Stmt @@ -849,14 +851,14 @@ func applySchema(db *sql.DB) error { func (s *Store) prepareStatements() error { var err error - s.stmtGetTxByHash, err = s.db.Prepare("SELECT id, first_seen FROM transmissions WHERE hash = ?") + s.stmtGetTxByHash, err = s.db.Prepare("SELECT id, first_seen, route_mask FROM transmissions WHERE hash = ?") if err != nil { return err } s.stmtInsertTransmission, err = s.db.Prepare(` - INSERT INTO transmissions (raw_hex, hash, first_seen, route_type, payload_type, payload_version, decoded_json, channel_hash, scope_name, from_pubkey, last_seen) - VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + INSERT INTO transmissions (raw_hex, hash, first_seen, route_type, payload_type, payload_version, decoded_json, channel_hash, scope_name, from_pubkey, last_seen, route_mask) + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) `) if err != nil { return err @@ -867,6 +869,22 @@ func (s *Store) prepareStatements() error { return err } + // #89: OR a newly observed route bit into a known route_mask. The OR runs + // in SQL, so it is atomic against any other writer; NULL rows are left to + // the backfill (backfillTxRouteMask), which owns un-backfilled legacy rows. + s.stmtOrTxRouteMask, err = s.db.Prepare(`UPDATE transmissions SET route_mask = route_mask | ? + WHERE id = ? AND route_mask IS NOT NULL AND (route_mask & ?) = 0`) + if err != nil { + return err + } + // Change log for running servers (route_mask_changes): the transmission's + // full mask as it is inside the current transaction, right after the OR. + s.stmtInsertRouteMaskChange, err = s.db.Prepare(`INSERT INTO route_mask_changes (transmission_id, route_mask, created_at) + SELECT id, route_mask, ? FROM transmissions WHERE id = ? AND route_mask IS NOT NULL`) + if err != nil { + return err + } + // Ping-score highscore/leaderboard feature (see ping_triggers.go and // internal/dbschema's ensurePingTriggersTable). INSERT OR IGNORE on // tx_id (PRIMARY KEY) makes this idempotent -- only ever written once @@ -1126,7 +1144,9 @@ func (s *Store) InsertTransmission(data *PacketData) (bool, error) { // Check for existing transmission var existingID int64 var existingFirstSeen string - err := s.stmtGetTxByHash.QueryRow(hash).Scan(&existingID, &existingFirstSeen) + var existingMask sql.NullInt64 + routeBit := packetpath.RouteMaskBit(data.RouteType) + err := s.stmtGetTxByHash.QueryRow(hash).Scan(&existingID, &existingFirstSeen, &existingMask) if err == nil { // Existing transmission txID = existingID @@ -1143,6 +1163,7 @@ func (s *Store) InsertTransmission(data *PacketData) (bool, error) { scopeNameForDB(data), nilIfEmpty(data.FromPubkey), epochSecondsForLastSeen(rxTime), + routeBit, ) if err != nil { s.Stats.WriteErrors.Add(1) @@ -1203,12 +1224,22 @@ func (s *Store) InsertTransmission(data *PacketData) (bool, error) { ) resolvedJSON := marshalResolvedPath(resolved) - _, err = s.stmtInsertObservation.Exec( + obsArgs := []interface{}{ txID, observerIdx, data.Direction, data.SNR, data.RSSI, data.Score, data.PathJSON, epochTs, nilIfEmpty(data.RawHex), nilIfEmpty(resolvedJSON), - ) + } + // #89: an observation that brings a route bit its transmission does not + // have yet is written together with that bit, in one transaction: an + // observation must never be visible without its bit, and a known mask is + // never backfilled again. Skipped when the bit is already set or the row + // is still an un-backfilled legacy row (NULL), which the backfill owns. + if !isNew && routeBit != 0 && existingMask.Valid && existingMask.Int64&routeBit == 0 { + err = s.insertObservationWithRouteBit(txID, routeBit, obsArgs) + } else { + _, err = s.stmtInsertObservation.Exec(obsArgs...) + } if err != nil { s.Stats.WriteErrors.Add(1) log.Printf("[db] observation insert (non-fatal): %v", err) @@ -1233,6 +1264,36 @@ func (s *Store) InsertTransmission(data *PacketData) (bool, error) { return isNew, nil } +// insertObservationWithRouteBit ORs routeBit into the transmission's +// route_mask, inserts (or upserts) the observation and, when the mask +// actually changed, appends a route_mask_changes row with the resulting mask, +// all in one transaction: either everything becomes visible or nothing does. +// The change row is what tells a running server about a bit that arrived +// through an upsert of an existing observation row (same id, so its +// new-observation poll never sees it). Caller holds writerMu. The pool has a +// single connection, which this transaction holds until it ends: every +// statement in between must run on dbTx, never on s.db. +func (s *Store) insertObservationWithRouteBit(txID, routeBit int64, obsArgs []interface{}) error { + dbTx, err := s.db.Begin() + if err != nil { + return fmt.Errorf("begin route_mask transaction: %w", err) + } + defer dbTx.Rollback() // no-op after a successful Commit + res, err := dbTx.Stmt(s.stmtOrTxRouteMask).Exec(routeBit, txID, routeBit) + if err != nil { + return fmt.Errorf("route_mask update: %w", err) + } + if _, err := dbTx.Stmt(s.stmtInsertObservation).Exec(obsArgs...); err != nil { + return err + } + if changed, _ := res.RowsAffected(); changed > 0 { + if _, err := dbTx.Stmt(s.stmtInsertRouteMaskChange).Exec(time.Now().Unix(), txID); err != nil { + return fmt.Errorf("route_mask change row: %w", err) + } + } + return dbTx.Commit() +} + // UpsertNode inserts or updates a node. func (s *Store) UpsertNode(pubKey, name, role string, lat, lon *float64, lastSeen string) error { ingestNow := time.Now().UTC().Format(time.RFC3339) diff --git a/cmd/ingestor/decoder.go b/cmd/ingestor/decoder.go index cf27790fc..21a6bafd4 100644 --- a/cmd/ingestor/decoder.go +++ b/cmd/ingestor/decoder.go @@ -205,7 +205,7 @@ type DecodedPacket struct { } func decodeHeader(b byte) Header { - rt := int(b & 0x03) + rt := packetpath.RouteTypeFromHeader(b) pt := int((b >> 2) & 0x0F) pv := int((b >> 6) & 0x03) diff --git a/cmd/ingestor/main.go b/cmd/ingestor/main.go index 12f96355b..68a298de5 100644 --- a/cmd/ingestor/main.go +++ b/cmd/ingestor/main.go @@ -1,6 +1,7 @@ package main import ( + "context" "crypto/hmac" "crypto/sha256" "crypto/tls" @@ -281,6 +282,10 @@ func main() { log.Printf("[prune] startup pruned %d transmissions older than %d days", n, packetDays) } } + // #89: route_mask_changes rows of transmissions deleted by any path. + if _, err := store.PruneOrphanRouteMaskChanges(); err != nil { + log.Printf("[prune] route_mask_changes error: %v", err) + } // Client-RX coverage retention: bound the opt-in coverage tables (#1727). // Independent of the feature flag, so data persists are reaped even after @@ -309,6 +314,15 @@ func main() { log.Printf("[ingest-buffer] write path ready; draining backlog (0 dropped)") } + // #89: route_mask backfill runs next to live ingest, after the buffer is + // draining, so its one-time pending-index build (~20 s on a staging-sized + // DB) is absorbed by IngestBuffer instead of delaying start-up. Cancelled + // on shutdown so store.Close() does not wait for it; it resumes on the + // next start. + routeMaskCtx, stopRouteMaskBackfill := context.WithCancel(context.Background()) + defer stopRouteMaskBackfill() + store.StartRouteMaskBackfill(routeMaskCtx) + // Daily ticker for node retention retentionTicker := time.NewTicker(1 * time.Hour) go func() { @@ -352,6 +366,9 @@ func main() { } else if n > 0 { store.RunIncrementalVacuum(vacuumPages) } + if _, err := store.PruneOrphanRouteMaskChanges(); err != nil { + log.Printf("[prune] route_mask_changes error: %v", err) + } } }() log.Printf("[prune] auto-prune enabled: packets older than %d days will be removed daily", packetDays) @@ -475,6 +492,7 @@ func main() { <-sig log.Println("Shutting down...") + stopRouteMaskBackfill() retentionTicker.Stop() metricsRetentionTicker.Stop() if packetRetentionTicker != nil { diff --git a/cmd/ingestor/maintenance.go b/cmd/ingestor/maintenance.go index fbcbda716..c006d460a 100644 --- a/cmd/ingestor/maintenance.go +++ b/cmd/ingestor/maintenance.go @@ -44,11 +44,13 @@ const pruneBatchTransmissions = 250 // pins the plan. const pruneAgedTransmissionIDs = `SELECT id FROM transmissions WHERE first_seen < ? ORDER BY first_seen, id LIMIT ?` -// The two statements of one prune batch. Child observations go first (no -// CASCADE in SQLite). +// The statements of one prune batch. Child rows go first (no CASCADE in +// SQLite): observations, then the batch's route_mask_changes rows (#89; via +// idx_route_mask_changes_tx), then the transmissions themselves. const ( - pruneObservationsBatch = `DELETE FROM observations WHERE transmission_id IN (` + pruneAgedTransmissionIDs + `)` - pruneTransmissionsBatch = `DELETE FROM transmissions WHERE id IN (` + pruneAgedTransmissionIDs + `)` + pruneObservationsBatch = `DELETE FROM observations WHERE transmission_id IN (` + pruneAgedTransmissionIDs + `)` + pruneRouteMaskChangesBatch = `DELETE FROM route_mask_changes WHERE transmission_id IN (` + pruneAgedTransmissionIDs + `)` + pruneTransmissionsBatch = `DELETE FROM transmissions WHERE id IN (` + pruneAgedTransmissionIDs + `)` ) // PruneOldPackets deletes transmissions (and their child observations) @@ -80,6 +82,9 @@ func (s *Store) PruneOldPackets(days int) (int64, error) { if _, err := tx.Exec(pruneObservationsBatch, cutoff, pruneBatchTransmissions); err != nil { return fmt.Errorf("prune observations: %w", err) } + if _, err := tx.Exec(pruneRouteMaskChangesBatch, cutoff, pruneBatchTransmissions); err != nil { + return fmt.Errorf("prune route_mask_changes: %w", err) + } res, err := tx.Exec(pruneTransmissionsBatch, cutoff, pruneBatchTransmissions) if err != nil { return fmt.Errorf("prune transmissions: %w", err) @@ -104,6 +109,65 @@ func (s *Store) PruneOldPackets(days int) (int64, error) { return total, nil } +// routeMaskOrphanPruneBatch bounds one orphan-prune transaction. A var so +// tests can exercise several batches. +var routeMaskOrphanPruneBatch = 1000 + +// PruneOrphanRouteMaskChanges deletes route_mask_changes rows whose +// transmission no longer exists. PruneOldPackets already deletes a pruned +// transmission's rows in the same batch; this catches any other deletion path +// so the log never outlives its transmission. It never deletes a row of an +// existing transmission: the log carries no time-based expiry, so a slow +// server can never miss a change of a transmission it still holds. +// +// Each writer transaction examines the next routeMaskOrphanPruneBatch ids +// (a primary-key range, one transmissions primary-key probe per row) and +// deletes the orphans among them, so its work is bounded however far apart +// the orphans are. The table is small in practice (22 rows on a +// 496,798-transmission staging copy; at most three per transmission, one per +// route bit it can gain). Returns the number of rows deleted. +func (s *Store) PruneOrphanRouteMaskChanges() (int64, error) { + batch := routeMaskOrphanPruneBatch + if batch <= 0 { + batch = 1000 + } + var total, after int64 + for { + var examined, deleted int64 + err := s.WriterTx("prune_route_mask_changes", func(tx *sql.Tx) error { + var last sql.NullInt64 + if err := tx.QueryRow(`SELECT MAX(id), COUNT(*) FROM ( + SELECT id FROM route_mask_changes WHERE id > ? ORDER BY id LIMIT ?)`, + after, batch).Scan(&last, &examined); err != nil { + return fmt.Errorf("scan route_mask_changes: %w", err) + } + if examined == 0 { + return nil + } + res, err := tx.Exec(`DELETE FROM route_mask_changes WHERE id > ? AND id <= ? + AND NOT EXISTS (SELECT 1 FROM transmissions t WHERE t.id = route_mask_changes.transmission_id)`, + after, last.Int64) + if err != nil { + return fmt.Errorf("prune orphan route_mask_changes: %w", err) + } + deleted, _ = res.RowsAffected() + after = last.Int64 + return nil + }) + if err != nil { + return total, err + } + total += deleted + if examined < int64(batch) { + break + } + } + if total > 0 { + log.Printf("[prune] deleted %d route_mask_changes rows of deleted transmissions", total) + } + return total, nil +} + // PruneOldClientReceptions deletes mobile client-RX coverage rows older than // `days` (by rx_at), and client_observers (companion names) whose last_seen has // aged out. This bounds the otherwise-unbounded client_receptions table the diff --git a/cmd/ingestor/prune_chunked_test.go b/cmd/ingestor/prune_chunked_test.go index a54130b00..04d2028bd 100644 --- a/cmd/ingestor/prune_chunked_test.go +++ b/cmd/ingestor/prune_chunked_test.go @@ -248,9 +248,10 @@ func TestPruneAgedTransmissionIDsUsesFirstSeenIndex(t *testing.T) { cutoff := time.Now().UTC().AddDate(0, 0, -5).Format(time.RFC3339) for name, q := range map[string]string{ - "batch subquery": pruneAgedTransmissionIDs, - "observations delete": pruneObservationsBatch, - "transmissions delete": pruneTransmissionsBatch, + "batch subquery": pruneAgedTransmissionIDs, + "observations delete": pruneObservationsBatch, + "route_mask_changes delete": pruneRouteMaskChangesBatch, + "transmissions delete": pruneTransmissionsBatch, } { rows, err := store.db.Query("EXPLAIN QUERY PLAN "+q, cutoff, pruneBatchTransmissions) if err != nil { @@ -282,5 +283,10 @@ func TestPruneAgedTransmissionIDsUsesFirstSeenIndex(t *testing.T) { if strings.Contains(plan, "TEMP B-TREE") { t.Errorf("%s: plan sorts in a temp b-tree instead of walking the index in order: %s", name, plan) } + // #89: the change rows of a batch are found through their index, + // not by scanning the change log. + if name == "route_mask_changes delete" && (!strings.Contains(plan, "idx_route_mask_changes_tx") || strings.Contains(plan, "SCAN route_mask_changes")) { + t.Errorf("%s: plan does not delete through idx_route_mask_changes_tx: %s", name, plan) + } } } diff --git a/cmd/ingestor/route_mask_backfill.go b/cmd/ingestor/route_mask_backfill.go new file mode 100644 index 000000000..11e780c08 --- /dev/null +++ b/cmd/ingestor/route_mask_backfill.go @@ -0,0 +1,208 @@ +package main + +import ( + "context" + "database/sql" + "fmt" + "log" + "strings" + "time" + + "github.com/meshcore-analyzer/dbschema" + "github.com/meshcore-analyzer/packetpath" +) + +// Issue #89 backfill of transmissions.route_mask for rows written before the +// column existed (route_mask IS NULL). Each row gets the bit of its stored +// route_type plus every bit readable from its surviving observations.raw_hex +// headers. That is a lower bound: a route variant whose frame no longer exists +// anywhere (e.g. overwritten twice by the observation upsert) is not invented. +// +// Sizing (issue #89 cold-cache measurement on a 4.95 GB staging copy, 496,798 +// tx / 6,526,537 obs, staging-class host): +// - building the pending index: 18-19.5 s cold, one statement. It runs here, +// after MQTT subscribe, where IngestBuffer covers the write stall. +// - batches of 100 tx: writer hold p99 161 ms (max 316 ms), a concurrent +// live write waited p99 121 ms, 9.3 min in total including yields. +// +// routeMaskBackfillBatchSize and routeMaskBackfillYield are vars so tests can +// exercise multi-batch runs. +var ( + routeMaskBackfillBatchSize = 100 + routeMaskBackfillYield = 50 * time.Millisecond +) + +// StartRouteMaskBackfill schedules the backfill as an async migration. Call it +// after the MQTT subscription and ingestBuffer.Ready(): it runs next to live +// ingest and must not delay draining the startup buffer. Cancelling ctx stops +// it at the next statement; it is then recorded as failed and resumes on the +// next start. +// +// A completed migration is re-run when NULL rows exist again, which happens +// when an older ingestor (after a rollback) inserted rows without a mask. +func (s *Store) StartRouteMaskBackfill(ctx context.Context) { + name := dbschema.RouteMaskBackfillMigration + var hasIndex int + s.db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type = 'index' AND name = ?`, dbschema.RouteMaskPendingIndex).Scan(&hasIndex) + if hasIndex > 0 { + var pending int + if err := s.db.QueryRow(`SELECT EXISTS(SELECT 1 FROM transmissions WHERE route_mask IS NULL)`).Scan(&pending); err == nil && pending == 1 { + if res, err := s.db.Exec(`UPDATE _async_migrations SET status = 'pending_async' WHERE name = ? AND status = 'done'`, name); err == nil { + if n, _ := res.RowsAffected(); n > 0 { + log.Printf("[route-mask] rows without route_mask found after completion; re-running %s", name) + } + } + } + } + if err := s.RunAsyncMigration(ctx, name, s.backfillTxRouteMask); err != nil { + log.Printf("[route-mask] scheduling %s failed: %v", name, err) + } +} + +// backfillTxRouteMask builds the pending index and then fills NULL rows in +// bounded batches until none are left. +func (s *Store) backfillTxRouteMask(ctx context.Context, d *sql.DB) error { + start := time.Now() + if err := createRouteMaskPendingIndex(ctx, d); err != nil { + return err + } + log.Printf("[route-mask] pending index ready in %s; backfilling route_mask", time.Since(start).Round(time.Millisecond)) + var total int64 + for batches := 1; ; batches++ { + n, err := s.backfillTxRouteMaskBatch(ctx, d, routeMaskBackfillBatchSize) + if err != nil { + return err + } + if n == 0 { + break + } + total += n + if batches%100 == 0 { + log.Printf("[route-mask] backfilled %d rows so far", total) + } + select { + case <-ctx.Done(): + return ctx.Err() + case <-time.After(routeMaskBackfillYield): + } + } + log.Printf("[route-mask] backfill complete: %d rows in %s", total, time.Since(start).Round(time.Second)) + return nil +} + +// createRouteMaskPendingIndex builds the partial index the backfill and the +// server's status query use. It holds writerMu like every other writer, so +// the stall it causes is recorded as route_mask_index instead of showing up as +// wait time of whichever writer queues behind it on the single connection. +func createRouteMaskPendingIndex(ctx context.Context, d *sql.DB) error { + waitStart := time.Now() + writerMu.Lock() + wait := time.Since(waitStart) + holdStart := time.Now() + defer func() { + hold := time.Since(holdStart) + writerMu.Unlock() + recordWriterTiming("route_mask_index", wait, hold, dbschema.CreateRouteMaskPendingIndexSQL) + }() + // PREFLIGHT: async=true reason="partial index over transmissions; one full-table scan, measured 18-19.5 s cold on a 4.95 GB staging copy; runs after MQTT subscribe so IngestBuffer absorbs the write stall" + if _, err := d.ExecContext(ctx, dbschema.CreateRouteMaskPendingIndexSQL); err != nil { + return fmt.Errorf("create %s: %w", dbschema.RouteMaskPendingIndex, err) + } + return nil +} + +// backfillTxRouteMaskBatch fills up to limit NULL rows in one write +// transaction and returns how many it updated. It holds writerMu like +// InsertTransmission, so a live observation is either fully visible to the +// batch (its frame is read here) or arrives after it (and its OR extends the +// now-known mask). +func (s *Store) backfillTxRouteMaskBatch(ctx context.Context, d *sql.DB, limit int) (int64, error) { + waitStart := time.Now() + writerMu.Lock() + wait := time.Since(waitStart) + holdStart := time.Now() + defer func() { + hold := time.Since(holdStart) + writerMu.Unlock() + recordWriterTiming("route_mask_backfill", wait, hold, "backfillTxRouteMaskBatch") + }() + + tx, err := d.BeginTx(ctx, nil) + if err != nil { + return 0, err + } + defer tx.Rollback() // no-op after Commit + + rows, err := tx.QueryContext(ctx, `SELECT id, route_type FROM transmissions WHERE route_mask IS NULL ORDER BY id LIMIT ?`, limit) + if err != nil { + return 0, err + } + masks := map[int64]int64{} + var ids []interface{} + for rows.Next() { + var id int64 + var routeType sql.NullInt64 + if err := rows.Scan(&id, &routeType); err != nil { + rows.Close() + return 0, err + } + var mask int64 + if routeType.Valid { + mask = packetpath.RouteMaskBit(int(routeType.Int64)) + } + masks[id] = mask + ids = append(ids, id) + } + if err := rows.Err(); err != nil { + rows.Close() + return 0, err + } + rows.Close() + if len(ids) == 0 { + return 0, nil + } + + placeholders := strings.TrimSuffix(strings.Repeat("?,", len(ids)), ",") + orows, err := tx.QueryContext(ctx, `SELECT transmission_id, substr(raw_hex, 1, 2) FROM observations + WHERE transmission_id IN (`+placeholders+`) AND raw_hex IS NOT NULL`, ids...) + if err != nil { + return 0, err + } + for orows.Next() { + var id int64 + var header sql.NullString + if err := orows.Scan(&id, &header); err != nil { + orows.Close() + return 0, err + } + // Unparseable or truncated frames contribute nothing; they never stop + // the backfill. + if rt, ok := packetpath.RouteTypeFromRawHex(header.String); ok { + masks[id] |= packetpath.RouteMaskBit(rt) + } + } + if err := orows.Err(); err != nil { + orows.Close() + return 0, err + } + orows.Close() + + stmt, err := tx.PrepareContext(ctx, `UPDATE transmissions SET route_mask = ? WHERE id = ? AND route_mask IS NULL`) + if err != nil { + return 0, err + } + defer stmt.Close() + var updated int64 + for _, id := range ids { + res, err := stmt.ExecContext(ctx, masks[id.(int64)], id) + if err != nil { + return 0, err + } + n, _ := res.RowsAffected() + updated += n + } + if err := tx.Commit(); err != nil { + return 0, err + } + return updated, nil +} diff --git a/cmd/ingestor/route_mask_backfill_test.go b/cmd/ingestor/route_mask_backfill_test.go new file mode 100644 index 000000000..7b27eddb8 --- /dev/null +++ b/cmd/ingestor/route_mask_backfill_test.go @@ -0,0 +1,340 @@ +package main + +import ( + "context" + "database/sql" + "fmt" + "os" + "path/filepath" + "strings" + "sync" + "testing" + + "github.com/meshcore-analyzer/dbschema" +) + +// Issue #89 backfill: legacy rows (route_mask IS NULL) get the bit of their +// stored route_type plus every bit that can be read from the surviving +// observations.raw_hex headers. That is a lower bound: a variant whose frame +// no longer exists anywhere is not invented. + +func routeMaskShrinkBackfill(t *testing.T, batch int) { + t.Helper() + oldBatch, oldYield := routeMaskBackfillBatchSize, routeMaskBackfillYield + routeMaskBackfillBatchSize, routeMaskBackfillYield = batch, 0 + t.Cleanup(func() { routeMaskBackfillBatchSize, routeMaskBackfillYield = oldBatch, oldYield }) +} + +func routeMaskMakeLegacy(t *testing.T, s *Store) { + t.Helper() + if _, err := s.db.Exec(`UPDATE transmissions SET route_mask = NULL`); err != nil { + t.Fatal(err) + } +} + +func routeMaskAll(t *testing.T, s *Store) map[string]sql.NullInt64 { + t.Helper() + rows, err := s.db.Query(`SELECT hash, route_mask FROM transmissions ORDER BY id`) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + out := map[string]sql.NullInt64{} + for rows.Next() { + var h string + var m sql.NullInt64 + rows.Scan(&h, &m) + out[h] = m + } + return out +} + +func routeMaskInsertRaw(t *testing.T, s *Store, hash string, routeType interface{}, obsRaw ...interface{}) { + t.Helper() + res, err := s.db.Exec(`INSERT INTO transmissions (raw_hex, hash, first_seen, route_type, payload_type) VALUES ('00', ?, ?, ?, 4)`, hash, routeMaskT0, routeType) + if err != nil { + t.Fatal(err) + } + id, _ := res.LastInsertId() + for i, raw := range obsRaw { + if _, err := s.db.Exec(`INSERT INTO observations (transmission_id, observer_idx, path_json, timestamp, raw_hex) VALUES (?, ?, ?, 1790244000, ?)`, + id, i+100, fmt.Sprintf(`["%02X"]`, i), raw); err != nil { + t.Fatal(err) + } + } +} + +func TestBackfillTxRouteMask_LowerBoundFromRouteAndObservations(t *testing.T) { + routeMaskShrinkBackfill(t, 2) + s := routeMaskStore(t, filepath.Join(t.TempDir(), "bf.db")) + defer s.Close() + mixed := routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0}) + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5}) + routeMaskMakeLegacy(t, s) + + // Staging tx 1000443: stored as zero-hop, the only surviving frame is the + // 0-hop transport flood that overwrote it (same observer, same path). + overwritten := "hash-overwritten" + routeMaskInsertRaw(t, s, overwritten, 3, routeMaskFlood0HopRaw) + // A -> B -> A by one observer and path: the flood variant is gone from + // every frame. The backfill must not invent it. + lost := "hash-lost" + routeMaskInsertRaw(t, s, lost, 3, firstIngestedZeroHopRaw) + routeMaskInsertRaw(t, s, "hash-null-route", nil, firstIngestedFloodRaw) + routeMaskInsertRaw(t, s, "hash-invalid-no-obs", 7) + routeMaskInsertRaw(t, s, "hash-bad-frames", 1, "zz", "1", nil) + routeMaskInsertRaw(t, s, "hash-known", 1) + if _, err := s.db.Exec(`UPDATE transmissions SET route_mask = 4 WHERE hash = 'hash-known'`); err != nil { + t.Fatal(err) + } + + if err := s.backfillTxRouteMask(context.Background(), s.db); err != nil { + t.Fatalf("backfill: %v", err) + } + got := routeMaskAll(t, s) + want := map[string]int64{ + mixed: 0b1010, + overwritten: 0b1001, + lost: 0b1000, + "hash-null-route": 0b0010, + "hash-invalid-no-obs": 0, + "hash-bad-frames": 0b0010, + "hash-known": 0b0100, // already known rows are not touched + } + for h, w := range want { + if m := got[h]; !m.Valid || m.Int64 != w { + t.Errorf("%s: route_mask = %v, want %04b", h, m, w) + } + } + var idx, left int + s.db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type = 'index' AND name = ?`, dbschema.RouteMaskPendingIndex).Scan(&idx) + s.db.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NULL`).Scan(&left) + if idx != 1 || left != 0 { + t.Fatalf("pending index present=%d, NULL rows left=%d; want 1 and 0", idx, left) + } +} + +func routeMaskLegacyFixture(t *testing.T, path string, n int) *Store { + t.Helper() + s := routeMaskStore(t, path) + for i := 0; i < n; i++ { + payload := fmt.Sprintf("%064x", i) + firstIngestedAdvertPayload[64:] + routeMaskInsert(t, s, routeMaskObs{"11" + "02" + "a1b2" + payload, "obs-a", routeMaskT0}) + if i%3 == 0 { + routeMaskInsert(t, s, routeMaskObs{"13" + "00000000" + "00" + payload, "obs-b", routeMaskT5}) + } + } + routeMaskMakeLegacy(t, s) + return s +} + +// Interrupted after two committed batches, the ingestor restarts and resumes; +// the result equals an uninterrupted run, and a second run changes nothing. +func TestBackfillTxRouteMask_ChunkedResumableIdempotent(t *testing.T) { + routeMaskShrinkBackfill(t, 2) + ref := routeMaskLegacyFixture(t, filepath.Join(t.TempDir(), "ref.db"), 9) + if err := ref.backfillTxRouteMask(context.Background(), ref.db); err != nil { + t.Fatal(err) + } + want := routeMaskAll(t, ref) + ref.Close() + + path := filepath.Join(t.TempDir(), "resume.db") + s := routeMaskLegacyFixture(t, path, 9) + if _, err := s.db.Exec(dbschema.CreateRouteMaskPendingIndexSQL); err != nil { + t.Fatal(err) + } + for i := 0; i < 2; i++ { + if n, err := s.backfillTxRouteMaskBatch(context.Background(), s.db, routeMaskBackfillBatchSize); err != nil || n != 2 { + t.Fatalf("batch %d: n=%d err=%v", i, n, err) + } + } + var left int + s.db.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NULL`).Scan(&left) + if left != 5 { + t.Fatalf("after two batches of 2, NULL rows left = %d, want 5", left) + } + s.Close() + s = routeMaskStore(t, path) // restart + defer s.Close() + if err := s.backfillTxRouteMask(context.Background(), s.db); err != nil { + t.Fatal(err) + } + if got := routeMaskAll(t, s); fmt.Sprint(got) != fmt.Sprint(want) { + t.Fatalf("resumed result differs from an uninterrupted run:\n got %v\n want %v", got, want) + } + if n, err := s.backfillTxRouteMaskBatch(context.Background(), s.db, routeMaskBackfillBatchSize); err != nil || n != 0 { + t.Fatalf("second run updated %d rows (err=%v), want 0", n, err) + } +} + +// A batch that is cancelled before it commits leaves no partial update. +func TestBackfillTxRouteMask_CancelledBatchCommitsNothing(t *testing.T) { + s := routeMaskLegacyFixture(t, filepath.Join(t.TempDir(), "cancel.db"), 4) + defer s.Close() + if _, err := s.db.Exec(dbschema.CreateRouteMaskPendingIndexSQL); err != nil { + t.Fatal(err) + } + ctx, cancel := context.WithCancel(context.Background()) + cancel() + if _, err := s.backfillTxRouteMaskBatch(ctx, s.db, 100); err == nil { + t.Fatal("cancelled batch returned no error") + } + if err := s.backfillTxRouteMask(ctx, s.db); err == nil { + t.Fatal("cancelled backfill returned no error") + } + var left int + s.db.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NULL`).Scan(&left) + if left != 4 { + t.Fatalf("NULL rows after a cancelled batch = %d, want all 4", left) + } +} + +// Live ingest racing the backfill (batch size 1, no yield) must never lose a +// bit: each payload gets its zero-hop variant while its flood row is being +// backfilled. +func TestBackfillTxRouteMask_ConcurrentLiveIngestLosesNoBits(t *testing.T) { + routeMaskShrinkBackfill(t, 1) + const n = 60 + s := routeMaskStore(t, filepath.Join(t.TempDir(), "live.db")) + defer s.Close() + for i := 0; i < n; i++ { + payload := fmt.Sprintf("%064x", i) + firstIngestedAdvertPayload[64:] + routeMaskInsert(t, s, routeMaskObs{"11" + "02" + "a1b2" + payload, "obs-a", routeMaskT0}) + } + routeMaskMakeLegacy(t, s) + var wg sync.WaitGroup + wg.Add(2) + go func() { + defer wg.Done() + if err := s.backfillTxRouteMask(context.Background(), s.db); err != nil { + t.Error(err) + } + }() + go func() { + defer wg.Done() + for i := n - 1; i >= 0; i-- { + payload := fmt.Sprintf("%064x", i) + firstIngestedAdvertPayload[64:] + routeMaskInsert(t, s, routeMaskObs{"13" + "00000000" + "00" + payload, "obs-b", routeMaskT5}) + } + }() + wg.Wait() + // Rows the backfill finished before their zero-hop observation arrived got + // the bit from the live OR; the others from the backfill's frame read. + if err := s.backfillTxRouteMask(context.Background(), s.db); err != nil { + t.Fatal(err) + } + var wrong int + s.db.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NOT 10`).Scan(&wrong) + if wrong != 0 { + t.Fatalf("%d of %d transmissions lost a route bit while live ingest raced the backfill", wrong, n) + } +} + +func routeMaskAsyncStatus(t *testing.T, s *Store) string { + t.Helper() + var st string + if err := s.db.QueryRow(`SELECT status FROM _async_migrations WHERE name = ?`, dbschema.RouteMaskBackfillMigration).Scan(&st); err != nil { + return "missing" + } + return st +} + +func TestStartRouteMaskBackfill_CompletesAndRerunsForNewNullRows(t *testing.T) { + s := routeMaskLegacyFixture(t, filepath.Join(t.TempDir(), "start.db"), 5) + defer s.Close() + s.StartRouteMaskBackfill(context.Background()) + s.WaitForAsyncMigrations() + if st := routeMaskAsyncStatus(t, s); st != "done" { + t.Fatalf("status after first run = %s, want done", st) + } + + // An older ingestor (rollback) inserted a row without a mask; the next + // start must backfill it even though the migration is marked done. + routeMaskInsertRaw(t, s, "hash-after-rollback", 2, firstIngestedFloodRaw) + s.StartRouteMaskBackfill(context.Background()) + s.WaitForAsyncMigrations() + if m := routeMaskAll(t, s)["hash-after-rollback"]; !m.Valid || m.Int64 != 0b0110 { + t.Fatalf("row inserted after completion: route_mask = %v, want 0110", m) + } + if st := routeMaskAsyncStatus(t, s); st != "done" { + t.Fatalf("status after re-run = %s, want done", st) + } + + // Complete and nothing left: a start is a no-op (no re-run recorded). + var before string + s.db.QueryRow(`SELECT IFNULL(started_at, '') FROM _async_migrations WHERE name = ?`, dbschema.RouteMaskBackfillMigration).Scan(&before) + s.db.Exec(`UPDATE _async_migrations SET started_at = 'sentinel' WHERE name = ?`, dbschema.RouteMaskBackfillMigration) + s.StartRouteMaskBackfill(context.Background()) + s.WaitForAsyncMigrations() + var after string + s.db.QueryRow(`SELECT started_at FROM _async_migrations WHERE name = ?`, dbschema.RouteMaskBackfillMigration).Scan(&after) + if after != "sentinel" { + t.Fatalf("complete backfill was restarted (started_at %q -> %q)", before, after) + } +} + +// Shutdown cancels a running backfill; it is recorded as failed and resumes +// on the next start. +func TestStartRouteMaskBackfill_CancelledRunResumesNextStart(t *testing.T) { + s := routeMaskLegacyFixture(t, filepath.Join(t.TempDir(), "shutdown.db"), 5) + defer s.Close() + ctx, cancel := context.WithCancel(context.Background()) + cancel() + s.StartRouteMaskBackfill(ctx) + s.WaitForAsyncMigrations() + if st := routeMaskAsyncStatus(t, s); st != "failed" { + t.Fatalf("status after cancelled run = %s, want failed", st) + } + s.StartRouteMaskBackfill(context.Background()) + s.WaitForAsyncMigrations() + var left int + s.db.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NULL`).Scan(&left) + if st := routeMaskAsyncStatus(t, s); st != "done" || left != 0 { + t.Fatalf("after resume: status=%s NULL rows=%d, want done and 0", st, left) + } +} + +// The backfill must start only once the startup buffer is draining (so it +// neither delays Ready() via WaitForAsyncMigrations nor builds its index +// before MQTT subscribe), and shutdown must cancel it before disconnecting. +func TestMain_StartsRouteMaskBackfillAfterBufferReady(t *testing.T) { + src, err := os.ReadFile("main.go") + if err != nil { + t.Fatal(err) + } + s := string(src) + subscribe := strings.Index(s, "c.Subscribe(") + ready := strings.Index(s, "ingestBuffer.Ready()") + start := strings.Index(s, "store.StartRouteMaskBackfill(") + shutdown := strings.Index(s, `log.Println("Shutting down...")`) + stop := strings.LastIndex(s, "stopRouteMaskBackfill()") + disconnect := strings.LastIndex(s, "c.Disconnect(5000)") + if subscribe < 0 || ready < 0 || start < 0 || shutdown < 0 || stop < 0 || disconnect < 0 { + t.Fatalf("markers not found: subscribe=%d ready=%d start=%d shutdown=%d stop=%d disconnect=%d", subscribe, ready, start, shutdown, stop, disconnect) + } + if !(subscribe < ready && ready < start) { + t.Errorf("StartRouteMaskBackfill must come after MQTT subscribe and ingestBuffer.Ready()") + } + if !(shutdown < stop && stop < disconnect) { + t.Errorf("shutdown must cancel the route_mask backfill before disconnecting MQTT clients") + } +} + +// The pending-index build is one long write (about 18 s cold on the staging +// copy). It holds writerMu and is recorded under its own component, so the +// stall it causes is not attributed to the MQTT handler waiting behind it. +func TestStartRouteMaskBackfill_IndexBuildIsAttributed(t *testing.T) { + s := routeMaskLegacyFixture(t, filepath.Join(t.TempDir(), "attr.db"), 3) + defer s.Close() + ResetWriterStatsForTest() + s.StartRouteMaskBackfill(context.Background()) + s.WaitForAsyncMigrations() + snap := s.WriterStatsSnapshot() + if got := snap["route_mask_index"].Count; got != 1 { + t.Fatalf("route_mask_index writer samples = %d, want 1 (snapshot %v)", got, snap) + } + if got := snap["route_mask_backfill"].Count; got < 1 { + t.Fatalf("route_mask_backfill writer samples = %d, want at least 1", got) + } +} diff --git a/cmd/ingestor/route_mask_changes_test.go b/cmd/ingestor/route_mask_changes_test.go new file mode 100644 index 000000000..44683f7c5 --- /dev/null +++ b/cmd/ingestor/route_mask_changes_test.go @@ -0,0 +1,240 @@ +package main + +import ( + "context" + "fmt" + "path/filepath" + "testing" + "time" +) + +// PR #93 review: route_mask_changes notifies running servers of a new route +// bit on an existing transmission. It matters most when the observation that +// brings the bit only upserts an existing row (same observer and path): the +// row keeps its id, so a server polling new observation ids never sees it. +// One row per actual mask change, written in the same transaction as the +// mask update and the observation. + +type routeMaskChange struct { + txID int64 + mask int64 + createdAt int64 +} + +func routeMaskChanges(t *testing.T, s *Store) []routeMaskChange { + t.Helper() + rows, err := s.db.Query(`SELECT transmission_id, route_mask, created_at FROM route_mask_changes ORDER BY id`) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + var out []routeMaskChange + for rows.Next() { + var c routeMaskChange + if err := rows.Scan(&c.txID, &c.mask, &c.createdAt); err != nil { + t.Fatal(err) + } + out = append(out, c) + } + return out +} + +func routeMaskTxID(t *testing.T, s *Store, hash string) int64 { + t.Helper() + var id int64 + if err := s.db.QueryRow(`SELECT id FROM transmissions WHERE hash = ?`, hash).Scan(&id); err != nil { + t.Fatal(err) + } + return id +} + +// Same observer, same path, new route: the observation row keeps its id, the +// mask gains the bit, and exactly one change row carries the full new mask. +func TestRouteMaskChange_SameRowUpsertWritesOneEvent(t *testing.T) { + for _, tc := range []struct { + name string + first, next routeMaskObs + want int64 + }{ + {"zero-hop then 0-hop transport flood", + routeMaskObs{firstIngestedZeroHopRaw, "obs-a", routeMaskT0}, + routeMaskObs{routeMaskFlood0HopRaw, "obs-a", routeMaskT5}, 0b1001}, + {"0-hop transport flood then zero-hop", + routeMaskObs{routeMaskFlood0HopRaw, "obs-a", routeMaskT0}, + routeMaskObs{firstIngestedZeroHopRaw, "obs-a", routeMaskT5}, 0b1001}, + } { + t.Run(tc.name, func(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "upsert.db")) + defer s.Close() + hash := routeMaskInsert(t, s, tc.first) + txID := routeMaskTxID(t, s, hash) + var obsID int64 + s.db.QueryRow(`SELECT id FROM observations WHERE transmission_id = ?`, txID).Scan(&obsID) + before := time.Now().Unix() + routeMaskInsert(t, s, tc.next) + + var n, id int64 + s.db.QueryRow(`SELECT COUNT(*), MAX(id) FROM observations WHERE transmission_id = ?`, txID).Scan(&n, &id) + if n != 1 || id != obsID { + t.Fatalf("observations = %d (max id %d), want the one row %d upserted in place", n, id, obsID) + } + if mask, _ := routeMaskOf(t, s, hash); !mask.Valid || mask.Int64 != tc.want { + t.Fatalf("route_mask = %v, want %04b", mask, tc.want) + } + got := routeMaskChanges(t, s) + if len(got) != 1 || got[0].txID != txID || got[0].mask != tc.want || got[0].createdAt < before { + t.Fatalf("change rows = %+v, want one {tx %d, mask %04b, created_at >= %d}", got, txID, tc.want, before) + } + }) + } +} + +// Only actual mask changes are logged: a repeated route, a new transmission +// (the server reads its full mask when it loads the new row) and a legacy +// NULL mask (the backfill owns it) write nothing. +func TestRouteMaskChange_OnlyActualChangesAreLogged(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "only.db")) + defer s.Close() + flood := routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0} + hash := routeMaskInsert(t, s, flood) // new transmission + if got := routeMaskChanges(t, s); len(got) != 0 { + t.Fatalf("new transmission logged %+v", got) + } + routeMaskInsert(t, s, flood) // redelivery + routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-b", routeMaskT5}) // same route, other observer + if got := routeMaskChanges(t, s); len(got) != 0 { + t.Fatalf("repeated route logged %+v", got) + } + if mask, _ := routeMaskOf(t, s, hash); mask.Int64 != 0b0010 { + t.Fatalf("route_mask = %v, want 0010", mask) + } + + if _, err := s.db.Exec(`UPDATE transmissions SET route_mask = NULL`); err != nil { + t.Fatal(err) + } + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5}) + if got := routeMaskChanges(t, s); len(got) != 0 { + t.Fatalf("legacy NULL row logged %+v", got) + } +} + +// Several new bits, through both a new observation row and an upsert: one +// row per change, each with the mask as it was after that change. +func TestRouteMaskChange_EachNewBitIsLogged(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "bits.db")) + defer s.Close() + hash := routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0}) // 0010 + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5}) // new row: 1010 + routeMaskInsert(t, s, routeMaskObs{routeMaskFlood0HopRaw, "obs-b", routeMaskT0}) // upsert: 1011 + routeMaskInsert(t, s, routeMaskObs{routeMaskFlood0HopRaw, "obs-b", routeMaskT0}) // repeat: nothing + txID := routeMaskTxID(t, s, hash) + got := routeMaskChanges(t, s) + if len(got) != 2 || got[0].txID != txID || got[0].mask != 0b1010 || got[1].txID != txID || got[1].mask != 0b1011 { + t.Fatalf("change rows = %+v, want masks 1010 then 1011 for tx %d", got, txID) + } +} + +// The backfill fills NULL masks without logging: running servers pick those +// up through their own refresh of rows they loaded with an unknown mask. +func TestRouteMaskChange_BackfillWritesNoEvents(t *testing.T) { + s := routeMaskLegacyFixture(t, filepath.Join(t.TempDir(), "backfill.db"), 6) + defer s.Close() + if _, err := s.db.Exec(`DELETE FROM route_mask_changes`); err != nil { + t.Fatal(err) + } + s.StartRouteMaskBackfill(context.Background()) + s.WaitForAsyncMigrations() + if got := routeMaskChanges(t, s); len(got) != 0 { + t.Fatalf("backfill logged %d change rows", len(got)) + } +} + +// Retention deletes a pruned transmission's change rows in the same batch +// and keeps those of transmissions that still exist. +func TestPruneOldPackets_DeletesChangeRowsWithTheirTransmissions(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "prune.db")) + defer s.Close() + old := time.Now().UTC().AddDate(0, 0, -30).Format(time.RFC3339) + fresh := time.Now().UTC().Add(-time.Hour).Format(time.RFC3339) + oldHash := routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", old}) + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", old}) + payload := fmt.Sprintf("%064x", 7) + firstIngestedAdvertPayload[64:] + freshHash := routeMaskInsert(t, s, routeMaskObs{"11" + "02" + "a1b2" + payload, "obs-a", fresh}) + routeMaskInsert(t, s, routeMaskObs{"13" + "00000000" + "00" + payload, "obs-b", fresh}) + oldID, freshID := routeMaskTxID(t, s, oldHash), routeMaskTxID(t, s, freshHash) + if got := routeMaskChanges(t, s); len(got) != 2 { + t.Fatalf("setup: %+v", got) + } + if _, err := s.PruneOldPackets(7); err != nil { + t.Fatal(err) + } + got := routeMaskChanges(t, s) + if len(got) != 1 || got[0].txID != freshID { + t.Fatalf("after prune: %+v, want only the row of tx %d (tx %d was pruned)", got, freshID, oldID) + } +} + +// Change rows whose transmission was removed by any other path are pruned in +// bounded batches; rows of existing transmissions are never touched, and a +// second pass changes nothing. +func TestPruneOrphanRouteMaskChanges(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "orphan.db")) + defer s.Close() + hash := routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0}) + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5}) + keep := routeMaskTxID(t, s, hash) + for i := 0; i < 5; i++ { + if _, err := s.db.Exec(`INSERT INTO route_mask_changes (transmission_id, route_mask, created_at) VALUES (?, 2, 1)`, 900000+i); err != nil { + t.Fatal(err) + } + } + old := routeMaskOrphanPruneBatch + routeMaskOrphanPruneBatch = 2 + defer func() { routeMaskOrphanPruneBatch = old }() + ResetWriterStatsForTest() + n, err := s.PruneOrphanRouteMaskChanges() + if err != nil || n != 5 { + t.Fatalf("PruneOrphanRouteMaskChanges = %d, %v; want 5 over several batches", n, err) + } + // Six rows, examined two ids per writer transaction (the last one finds + // nothing left): the work of one transaction is bounded by the batch, not + // by how far the next orphan is. + if got := s.WriterStatsSnapshot()["prune_route_mask_changes"].Count; got != 4 { + t.Fatalf("orphan prune ran %d writer transactions, want 4 bounded batches", got) + } + got := routeMaskChanges(t, s) + if len(got) != 1 || got[0].txID != keep { + t.Fatalf("after orphan prune: %+v, want only the row of tx %d", got, keep) + } + if n, err := s.PruneOrphanRouteMaskChanges(); err != nil || n != 0 { + t.Fatalf("second pass = %d, %v; want 0", n, err) + } +} + +// The transaction logs a change only when the OR actually changed the mask: +// called with a bit the mask already has, it writes the observation and no +// change row. +func TestInsertObservationWithRouteBit_NoChangeRowWhenTheBitIsSet(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "noop.db")) + defer s.Close() + hash := routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0}) // mask 0010 + txID := routeMaskTxID(t, s, hash) + var obsIdx int64 + s.db.QueryRow(`SELECT rowid FROM observers WHERE id = 'obs-b'`).Scan(&obsIdx) + writerMu.Lock() + err := s.insertObservationWithRouteBit(txID, 0b0010, []interface{}{ + txID, obsIdx, nil, nil, nil, nil, `[]`, int64(1790244000), nil, nil, + }) + writerMu.Unlock() + if err != nil { + t.Fatal(err) + } + var n int + s.db.QueryRow(`SELECT COUNT(*) FROM observations WHERE transmission_id = ?`, txID).Scan(&n) + if n != 2 { + t.Fatalf("observations = %d, want 2 (the call still writes its observation)", n) + } + if got := routeMaskChanges(t, s); len(got) != 0 { + t.Fatalf("change rows = %+v, want none: the mask did not change", got) + } +} diff --git a/cmd/ingestor/route_mask_ingest_test.go b/cmd/ingestor/route_mask_ingest_test.go new file mode 100644 index 000000000..3863d6032 --- /dev/null +++ b/cmd/ingestor/route_mask_ingest_test.go @@ -0,0 +1,429 @@ +package main + +import ( + "database/sql" + "fmt" + "path/filepath" + "reflect" + "strings" + "sync" + "testing" + + "github.com/meshcore-analyzer/packetpath" +) + +// Issue #89: transmissions.route_mask records every raw route type (0..3) +// observed for a content hash. The first insert sets the bit of its own route; +// every later observation ORs its bit in atomically in SQL. The mask is +// monotonic, so the final value must not depend on insert order, observer, +// redelivery, restarts or concurrency. route_type keeps its legacy +// first-inserted meaning. + +var ( + // ROUTE_TYPE_TRANSPORT_FLOOD heard at 0 hops (header 0x10, codes 0000 0000, + // path_len 0): the variant staging tx 1000443 kept after the observation + // upsert overwrote a zero-hop frame from the same observer. + routeMaskFlood0HopRaw = "10" + "00000000" + "00" + firstIngestedAdvertPayload + routeMaskT0 = "2026-09-24T10:00:00Z" + routeMaskT5 = "2026-09-24T10:05:00Z" +) + +type routeMaskObs struct{ raw, observer, rx string } + +func routeMaskStore(t *testing.T, path string) *Store { + t.Helper() + s, err := OpenStore(path) + if err != nil { + t.Fatal(err) + } + s.backfillWg.Wait() + for _, id := range []string{"obs-a", "obs-b"} { + if err := s.UpsertObserver(id, id, "TST", nil); err != nil { + t.Fatal(err) + } + } + return s +} + +func routeMaskInsert(t *testing.T, s *Store, o routeMaskObs) string { + t.Helper() + decoded, err := DecodePacket(o.raw, nil, false) + if err != nil { + t.Fatalf("decode %s: %v", o.raw[:4], err) + } + pd := BuildPacketData(&MQTTPacketMessage{Raw: o.raw}, decoded, o.observer, "", nil) + pd.Timestamp = o.rx + if _, err := s.InsertTransmission(pd); err != nil { + t.Fatal(err) + } + return pd.Hash +} + +func routeMaskOf(t *testing.T, s *Store, hash string) (mask sql.NullInt64, routeType int) { + t.Helper() + if err := s.db.QueryRow(`SELECT route_mask, route_type FROM transmissions WHERE hash = ?`, hash).Scan(&mask, &routeType); err != nil { + t.Fatal(err) + } + return mask, routeType +} + +func permutations(n int) [][]int { + if n == 1 { + return [][]int{{0}} + } + var out [][]int + for _, p := range permutations(n - 1) { + for i := 0; i <= len(p); i++ { + q := append(append(append([]int{}, p[:i]...), n-1), p[i:]...) + out = append(out, q) + } + } + return out +} + +func TestInsertTransmission_RouteMaskIsOrderIndependent(t *testing.T) { + flood := routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0} + zeroHop := routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5} + scenarios := []struct { + name string + obs []routeMaskObs + want int64 + }{ + {"flood and zero-hop, different observers", []routeMaskObs{flood, zeroHop}, 0b1010}, + {"zero-hop with the later rx time", []routeMaskObs{flood, {firstIngestedZeroHopRaw, "obs-b", routeMaskT0}}, 0b1010}, + {"same observer and path: zero-hop and 0-hop transport flood", + []routeMaskObs{{firstIngestedZeroHopRaw, "obs-a", routeMaskT0}, {routeMaskFlood0HopRaw, "obs-a", routeMaskT5}}, 0b1001}, + {"redelivery of both variants", + []routeMaskObs{flood, flood, zeroHop, zeroHop}, 0b1010}, + {"three route values", []routeMaskObs{flood, zeroHop, {routeMaskFlood0HopRaw, "obs-b", routeMaskT0}}, 0b1011}, + {"single flood only", []routeMaskObs{flood}, 0b0010}, + {"single zero-hop only", []routeMaskObs{zeroHop}, 0b1000}, + } + for _, sc := range scenarios { + t.Run(sc.name, func(t *testing.T) { + for _, perm := range permutations(len(sc.obs)) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "rm.db")) + var hash string + for _, i := range perm { + hash = routeMaskInsert(t, s, sc.obs[i]) + } + mask, routeType := routeMaskOf(t, s, hash) + first, _ := DecodePacket(sc.obs[perm[0]].raw, nil, false) + s.Close() + if !mask.Valid || mask.Int64 != sc.want { + t.Fatalf("order %v: route_mask = %v, want %04b", perm, mask, sc.want) + } + if routeType != first.Header.RouteType { + t.Fatalf("order %v: route_type = %d, want the first inserted route %d (legacy contract)", perm, routeType, first.Header.RouteType) + } + } + }) + } +} + +func TestInsertTransmission_RouteMaskSurvivesRestart(t *testing.T) { + path := filepath.Join(t.TempDir(), "restart.db") + s := routeMaskStore(t, path) + hash := routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT0}) + s.Close() + s = routeMaskStore(t, path) // ingestor restart + routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT5}) + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT0}) // redelivery + mask, _ := routeMaskOf(t, s, hash) + s.Close() + if !mask.Valid || mask.Int64 != 0b1010 { + t.Fatalf("route_mask after restart = %v, want 1010", mask) + } +} + +// Both variants of each fresh payload race for writerMu; the mask must be the +// same whichever wins. +func TestInsertTransmission_RouteMaskUnderParallelIngest(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "parallel.db")) + defer s.Close() + const n = 200 + hashes := make([]string, n) + for i := 0; i < n; i++ { + payload := fmt.Sprintf("%064x", i) + firstIngestedAdvertPayload[64:] + frames := []routeMaskObs{ + {"11" + "02" + "a1b2" + payload, "obs-a", routeMaskT0}, + {"13" + "00000000" + "00" + payload, "obs-b", routeMaskT0}, + } + start := make(chan struct{}) + var wg sync.WaitGroup + var mu sync.Mutex + for _, f := range frames { + wg.Add(1) + go func(f routeMaskObs) { + defer wg.Done() + <-start + h := routeMaskInsert(t, s, f) + mu.Lock() + hashes[i] = h + mu.Unlock() + }(f) + } + close(start) + wg.Wait() + } + var wrong int + if err := s.db.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NOT 10`).Scan(&wrong); err != nil { + t.Fatal(err) + } + if wrong != 0 { + t.Fatalf("%d of %d transmissions ended with a mask other than 1010 under parallel ingest", wrong, n) + } +} + +// A route outside 0..3 sets no bit; the first insert still records a known +// (non-NULL) mask so it is not mistaken for an un-backfilled legacy row. +func TestInsertTransmission_InvalidRouteSetsNoBit(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "invalid.db")) + defer s.Close() + decoded, err := DecodePacket(firstIngestedFloodRaw, nil, false) + if err != nil { + t.Fatal(err) + } + pd := BuildPacketData(&MQTTPacketMessage{Raw: firstIngestedFloodRaw}, decoded, "obs-a", "", nil) + pd.Timestamp = routeMaskT0 + pd.RouteType = 7 + if _, err := s.InsertTransmission(pd); err != nil { + t.Fatal(err) + } + mask, _ := routeMaskOf(t, s, pd.Hash) + if !mask.Valid || mask.Int64 != 0 { + t.Fatalf("route_mask for route 7 = %v, want 0", mask) + } + pd.RouteType = -1 + pd.ObserverID = "obs-b" + if _, err := s.InsertTransmission(pd); err != nil { + t.Fatal(err) + } + if mask, _ = routeMaskOf(t, s, pd.Hash); mask.Int64 != 0 { + t.Fatalf("route_mask after route -1 = %v, want 0", mask) + } +} + +// PATH (payload 8) seen with and without transport codes keeps both raw bits +// (staging had one such hash in a 7-day census). +func TestInsertTransmission_PathKeepsBothFloodRouteBits(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "path.db")) + defer s.Close() + payload := "aabb" + strings.Repeat("cd", 20) + var hash string + for _, o := range []routeMaskObs{ + {"21" + "00" + payload, "obs-a", routeMaskT0}, // PATH, ROUTE_TYPE_FLOOD + {"20" + "11112222" + "00" + payload, "obs-b", routeMaskT5}, // PATH, ROUTE_TYPE_TRANSPORT_FLOOD + } { + hash = routeMaskInsert(t, s, o) + } + mask, _ := routeMaskOf(t, s, hash) + if !mask.Valid || mask.Int64 != 0b0011 { + t.Fatalf("PATH route_mask = %v, want 0011", mask) + } +} + +// Un-backfilled legacy rows (NULL) are left to the backfill: the live path +// only ORs into known masks, and never clears bits of a known one. +func TestInsertTransmission_RouteMaskLeavesLegacyNullAndNeverClears(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "legacy.db")) + defer s.Close() + hash := routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0}) + if _, err := s.db.Exec(`UPDATE transmissions SET route_mask = NULL WHERE hash = ?`, hash); err != nil { + t.Fatal(err) + } + routeMaskInsert(t, s, routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5}) + if mask, _ := routeMaskOf(t, s, hash); mask.Valid { + t.Fatalf("live ingest wrote %v into an un-backfilled row; the backfill owns NULL rows", mask) + } + if _, err := s.db.Exec(`UPDATE transmissions SET route_mask = 15 WHERE hash = ?`, hash); err != nil { + t.Fatal(err) + } + routeMaskInsert(t, s, routeMaskObs{firstIngestedFloodRaw, "obs-b", routeMaskT5}) + if mask, _ := routeMaskOf(t, s, hash); mask.Int64 != 15 { + t.Fatalf("route_mask = %v after a later observation, want 1111 (bits are never cleared)", mask) + } +} + +// A server poll that sees an observation row must also see its route bit in +// transmissions.route_mask; otherwise the server can store the observation +// with a mask that lacks the bit and never re-read it. A trigger records the +// mask at the moment each observation row is written (insert or upsert). +func TestInsertTransmission_ObservationIsVisibleOnlyWithItsRouteBit(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "visible.db")) + defer s.Close() + for _, q := range []string{ + `CREATE TABLE obs_mask_seen (obs_id INTEGER, raw_hex TEXT, mask INTEGER)`, + `CREATE TRIGGER obs_mask_probe_ins AFTER INSERT ON observations BEGIN + INSERT INTO obs_mask_seen SELECT NEW.id, NEW.raw_hex, route_mask FROM transmissions WHERE id = NEW.transmission_id; END`, + `CREATE TRIGGER obs_mask_probe_upd AFTER UPDATE ON observations BEGIN + INSERT INTO obs_mask_seen SELECT NEW.id, NEW.raw_hex, route_mask FROM transmissions WHERE id = NEW.transmission_id; END`, + } { + if _, err := s.db.Exec(q); err != nil { + t.Fatal(err) + } + } + for _, o := range []routeMaskObs{ + {firstIngestedFloodRaw, "obs-a", routeMaskT0}, + {firstIngestedZeroHopRaw, "obs-b", routeMaskT5}, + {firstIngestedZeroHopRaw, "obs-a", routeMaskT0}, + {routeMaskFlood0HopRaw, "obs-a", routeMaskT5}, // upserts the previous row + } { + routeMaskInsert(t, s, o) + } + rows, err := s.db.Query(`SELECT obs_id, raw_hex, mask FROM obs_mask_seen ORDER BY rowid`) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + var n int + for rows.Next() { + var id int64 + var raw string + var mask sql.NullInt64 + if err := rows.Scan(&id, &raw, &mask); err != nil { + t.Fatal(err) + } + n++ + rt, ok := packetpath.RouteTypeFromRawHex(raw) + if !ok { + t.Fatalf("obs %d: unparseable raw_hex %q", id, raw) + } + if bit := packetpath.RouteMaskBit(rt); !mask.Valid || mask.Int64&bit == 0 { + t.Fatalf("obs %d (route %d) became visible while route_mask was %v, without its bit", id, rt, mask) + } + } + if n < 4 { + t.Fatalf("probe saw %d observation writes, want at least 4", n) + } +} + +// Recording a new route bit and writing the observation that carries it +// happen together or not at all. If the route_mask update fails, the +// observation must not become visible: a known mask is never backfilled +// again, so an observation stored without its bit would leave the mask +// permanently short. If the observation write fails after the update, the +// update is rolled back too. Test-only triggers make one of the two writes +// fail deterministically. +func TestInsertTransmission_FailedRouteBitKeepsObservationOut(t *testing.T) { + type obsRow struct { + observer string + raw string + } + observations := func(t *testing.T, s *Store, hash string) []obsRow { + t.Helper() + rows, err := s.db.Query(`SELECT obs.id, o.raw_hex FROM observations o + JOIN transmissions t ON t.id = o.transmission_id + JOIN observers obs ON obs.rowid = o.observer_idx + WHERE t.hash = ? ORDER BY obs.id`, hash) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + var out []obsRow + for rows.Next() { + var r obsRow + if err := rows.Scan(&r.observer, &r.raw); err != nil { + t.Fatal(err) + } + out = append(out, r) + } + return out + } + faults := []struct { + name string + triggers []string + }{ + {"route_mask update fails", []string{ + `CREATE TRIGGER fault_route_mask BEFORE UPDATE OF route_mask ON transmissions + BEGIN SELECT RAISE(ABORT, 'injected route_mask failure'); END`, + }}, + {"observation write fails after the update", []string{ + `CREATE TRIGGER fault_obs_insert BEFORE INSERT ON observations + BEGIN SELECT RAISE(ABORT, 'injected observation failure'); END`, + `CREATE TRIGGER fault_obs_update BEFORE UPDATE ON observations + BEGIN SELECT RAISE(ABORT, 'injected observation failure'); END`, + }}, + {"change event insert fails after both writes", []string{ + `CREATE TRIGGER fault_change BEFORE INSERT ON route_mask_changes + BEGIN SELECT RAISE(ABORT, 'injected change event failure'); END`, + }}, + } + paths := []struct { + name string + first routeMaskObs + next routeMaskObs // brings a new route bit; fails, then succeeds + want int64 // mask after the successful retry + }{ + {"new observation row (insert)", + routeMaskObs{firstIngestedFloodRaw, "obs-a", routeMaskT0}, + routeMaskObs{firstIngestedZeroHopRaw, "obs-b", routeMaskT5}, 0b1010}, + {"same observer and path (upsert)", + routeMaskObs{firstIngestedZeroHopRaw, "obs-a", routeMaskT0}, + routeMaskObs{routeMaskFlood0HopRaw, "obs-a", routeMaskT5}, 0b1001}, + } + for _, fault := range faults { + for _, tc := range paths { + t.Run(fault.name+"/"+tc.name, func(t *testing.T) { + s := routeMaskStore(t, filepath.Join(t.TempDir(), "fail.db")) + defer s.Close() + hash := routeMaskInsert(t, s, tc.first) + wantMask, _ := routeMaskOf(t, s, hash) + wantObs := observations(t, s, hash) + + for _, q := range fault.triggers { + if _, err := s.db.Exec(q); err != nil { + t.Fatal(err) + } + } + writeErrs, inserted := s.Stats.WriteErrors.Load(), s.Stats.ObservationsInserted.Load() + decoded, err := DecodePacket(tc.next.raw, nil, false) + if err != nil { + t.Fatal(err) + } + pd := BuildPacketData(&MQTTPacketMessage{Raw: tc.next.raw}, decoded, tc.next.observer, "", nil) + pd.Timestamp = tc.next.rx + isNew, err := s.InsertTransmission(pd) + if err != nil || isNew { + t.Fatalf("InsertTransmission = (%v, %v), want the non-fatal (false, nil) of a failed observation write", isNew, err) + } + if got := s.Stats.WriteErrors.Load() - writeErrs; got != 1 { + t.Fatalf("WriteErrors grew by %d, want exactly 1", got) + } + if got := s.Stats.ObservationsInserted.Load() - inserted; got != 0 { + t.Fatalf("ObservationsInserted grew by %d, want 0", got) + } + if got, _ := routeMaskOf(t, s, hash); got != wantMask { + t.Fatalf("route_mask = %v after the failed update, want unchanged %v", got, wantMask) + } + if got := observations(t, s, hash); !reflect.DeepEqual(got, wantObs) { + t.Fatalf("observations after the failed update = %v, want unchanged %v", got, wantObs) + } + if got := routeMaskChanges(t, s); len(got) != 0 { + t.Fatalf("change rows after the failed update = %+v, want none", got) + } + + // Once the failure is gone, a redelivery stores both. + for _, name := range []string{"fault_route_mask", "fault_obs_insert", "fault_obs_update", "fault_change"} { + if _, err := s.db.Exec(`DROP TRIGGER IF EXISTS ` + name); err != nil { + t.Fatal(err) + } + } + routeMaskInsert(t, s, tc.next) + if got, _ := routeMaskOf(t, s, hash); !got.Valid || got.Int64 != tc.want { + t.Fatalf("route_mask after the redelivery = %v, want %04b", got, tc.want) + } + found := false + for _, o := range observations(t, s, hash) { + found = found || (o.observer == tc.next.observer && strings.EqualFold(o.raw, tc.next.raw)) + } + if !found { + t.Fatalf("redelivered observation missing: %v", observations(t, s, hash)) + } + if got := routeMaskChanges(t, s); len(got) != 1 || got[0].mask != tc.want { + t.Fatalf("change rows after the redelivery = %+v, want one with mask %04b", got, tc.want) + } + }) + } + } +} diff --git a/cmd/server/chunked_load.go b/cmd/server/chunked_load.go index db870f16f..4e6d7380f 100644 --- a/cmd/server/chunked_load.go +++ b/cmd/server/chunked_load.go @@ -172,6 +172,10 @@ func (s *PacketStore) fireChunkCallbacks(rowsThisChunk, totalRows int) { // parallelism while ensuring oldestLoaded has a valid floor when the // bg loader starts. func (s *PacketStore) RunStartupLoad(chunkSize int) error { + // #89: once this returns, on every path (including a failed or partial + // background fill), nothing more is loaded at start-up; parked + // route_mask changes for transmissions still missing can be dropped. + defer s.routeMaskLoadSettled.Store(true) // Clear any stale error from a previous invocation (single-call // invariant — see godoc above). Production never re-enters but // test fixtures may construct fresh stores that share no state; @@ -263,6 +267,8 @@ func (s *PacketStore) LoadChunked(chunkSize int) error { if neighborEdgesTableExists(s.db.conn) && s.graph.Load() == nil { panic("packet store LoadChunked(): neighbor_edges table has rows but s.graph is nil — graph must be loaded before packet load (see main.go #1643 invariant)") } + // #89: the change-log watermark is read before any row is loaded. + s.initRouteMaskChangeCursor() s.chunkedLoadInit() // Reset state for repeat calls in tests. s.loadComplete.Store(false) @@ -383,13 +389,18 @@ func (s *PacketStore) LoadChunked(chunkSize int) error { if s.db.hasScopeName() { scopeNameCol = ", t.scope_name" } + // #89: route_mask follows scope_name as the last optional column. + routeMaskCol := "" + if s.db.hasRouteMask() { + routeMaskCol = ", t.route_mask" + } var chunkSQL string if s.db.isV3() { chunkSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, obs.id, obs.name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRawHexCol + rpCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRawHexCol + rpCol + scopeNameCol + routeMaskCol + ` FROM (SELECT * FROM transmissions t2 ` + whereClause + ` ORDER BY t2.id ASC LIMIT ` + fmt.Sprintf("%d", chunkSize) + `) AS t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.rowid = o.observer_idx @@ -398,7 +409,7 @@ func (s *PacketStore) LoadChunked(chunkSize int) error { chunkSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, o.observer_id, o.observer_name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRawHexCol + rpCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRawHexCol + rpCol + scopeNameCol + routeMaskCol + ` FROM (SELECT * FROM transmissions t2 ` + whereClause + ` ORDER BY t2.id ASC LIMIT ` + fmt.Sprintf("%d", chunkSize) + `) AS t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.id = o.observer_id @@ -512,6 +523,7 @@ func (s *PacketStore) scanAndMergeChunk(rows *sql.Rows, relayPM *prefixMap, cold var obsRawHex sql.NullString var resolvedPathStr sql.NullString var scopeName sql.NullString + var routeMask sql.NullInt64 scanArgs := []interface{}{&txID, &rawHex, &hash, &firstSeen, &routeType, &payloadType, &payloadVersion, &decodedJSON, @@ -526,10 +538,18 @@ func (s *PacketStore) scanAndMergeChunk(rows *sql.Rows, relayPM *prefixMap, cold if s.db.hasScopeName() { scanArgs = append(scanArgs, &scopeName) } + if s.db.hasRouteMask() { + scanArgs = append(scanArgs, &routeMask) + } if err := rows.Scan(scanArgs...); err != nil { log.Printf("[store] LoadChunked scan error: %v", err) continue } + if s.loadScannedRowHook != nil { + hook := s.loadScannedRowHook + s.loadScannedRowHook = nil + hook() + } if int64(txID) > maxID { maxID = int64(txID) @@ -553,6 +573,7 @@ func (s *PacketStore) scanAndMergeChunk(rows *sql.Rows, relayPM *prefixMap, cold observerSet: make(map[string]bool), } s.byHash[hashStr] = tx + s.mergeRouteMaskOrQueue(tx, routeMask) s.packets = append(s.packets, tx) s.byTxID[txID] = tx if txID > s.maxTxID { diff --git a/cmd/server/db.go b/cmd/server/db.go index 0fbd4b3c4..98ec40324 100644 --- a/cmd/server/db.go +++ b/cmd/server/db.go @@ -87,8 +87,14 @@ type DB struct { hasDefaultScopeConfirmedAtFlag schemaFlag // nodes.default_scope_confirmed_at (#1865 follow-up) -- read via hasDefaultScopeConfirmedAt() hasMultibyteSupColsFlag schemaFlag // nodes.multibyte_sup (#903) -- read via hasMultibyteSupCols() hasLastSeenFlag schemaFlag // transmissions.last_seen (#1690) -- read via hasLastSeen() + hasRouteMaskFlag schemaFlag // transmissions.route_mask (#89) -- read via hasRouteMask() schemaHealerStop chan struct{} // closed by Close() to stop healSchemaFlags; nil if OpenDB never started it + // route_mask backfill status cache (#89), see route_mask.go. + routeMaskStatusMu sync.Mutex + routeMaskStatus RouteMaskBackfillStatus + routeMaskStatusExp time.Time + // Channel list cache (60s TTL) — avoids repeated GROUP BY scans (#762) channelsCacheMu sync.Mutex channelsCacheKey string @@ -110,6 +116,7 @@ func (db *DB) hasConfiguredScope() bool { return db.hasConfiguredScopeFl func (db *DB) hasDefaultScopeConfirmedAt() bool { return db.hasDefaultScopeConfirmedAtFlag.get() } func (db *DB) hasMultibyteSupCols() bool { return db.hasMultibyteSupColsFlag.get() } func (db *DB) hasLastSeen() bool { return db.hasLastSeenFlag.get() } +func (db *DB) hasRouteMask() bool { return db.hasRouteMaskFlag.get() } // OpenDB opens a read-only SQLite connection with WAL mode. func OpenDB(path string) (*DB, error) { @@ -147,7 +154,7 @@ func (db *DB) healSchemaFlags() { flags := []*schemaFlag{ &db.isV3Flag, &db.hasResolvedPathFlag, &db.hasObsRawHexFlag, &db.hasScopeNameFlag, &db.hasDefaultScopeFlag, &db.hasConfiguredScopeFlag, &db.hasDefaultScopeConfirmedAtFlag, - &db.hasMultibyteSupColsFlag, &db.hasLastSeenFlag, + &db.hasMultibyteSupColsFlag, &db.hasLastSeenFlag, &db.hasRouteMaskFlag, } allTrue := func() bool { for _, f := range flags { @@ -232,6 +239,9 @@ func (db *DB) detectSchema() { if colName == "last_seen" { db.hasLastSeenFlag.forceTrue() } + if colName == "route_mask" { + db.hasRouteMaskFlag.forceTrue() + } } } diff --git a/cmd/server/db_test.go b/cmd/server/db_test.go index afb3d46b5..19cddd7b2 100644 --- a/cmd/server/db_test.go +++ b/cmd/server/db_test.go @@ -2570,6 +2570,7 @@ func TestHealSchemaFlagsStopsOnceAllTrue(t *testing.T) { db.hasDefaultScopeConfirmedAtFlag.forceTrue() db.hasMultibyteSupColsFlag.forceTrue() db.hasLastSeenFlag.forceTrue() + db.hasRouteMaskFlag.forceTrue() db.schemaHealerStop = make(chan struct{}) done := make(chan struct{}) diff --git a/cmd/server/healthz.go b/cmd/server/healthz.go index 3d1e4c8f5..d454e0982 100644 --- a/cmd/server/healthz.go +++ b/cmd/server/healthz.go @@ -74,5 +74,13 @@ func (s *Server) handleHealthz(w http.ResponseWriter, r *http.Request) { // here. Defaults to {"initializing","",""} until a later, separate // wiring phase ever calls s.setPingScoreHistoryStatus. resp["ping_scores_history"] = s.pingScoreHistoryStatusView() + // #89: route_mask backfill status, computed read-only from the database + // and the in-memory store (never "complete" while a transmission still + // has no mask, or while this server has not read a backfilled one yet). + if s.store != nil && s.store.db != nil { + resp["route_mask_backfill"] = s.store.routeMaskBackfillStatus() + } else if s.db != nil { + resp["route_mask_backfill"] = s.db.routeMaskBackfillStatus() + } json.NewEncoder(w).Encode(resp) } diff --git a/cmd/server/main.go b/cmd/server/main.go index 7928f73c2..99c06eb4b 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -3,6 +3,7 @@ package main import ( "context" "database/sql" + "errors" "flag" "fmt" "log" @@ -18,7 +19,6 @@ import ( "time" "github.com/gorilla/mux" - "github.com/meshcore-analyzer/dbschema" ) // Set via -ldflags at build time @@ -191,7 +191,19 @@ func main() { // (#1287). The server NEVER migrates — it only reads. If a required // column/index/table is missing, the operator must restart the // ingestor (which owns dbschema.Apply) before this server can start. - if err := dbschema.AssertReady(database.conn); err != nil { + // #89 / PR #93: the ingestor creates this PR's migration while both + // processes start, so the server waits for it in-process (bounded, + // see schema_wait.go) instead of exiting until supervisord gives up. + // SIGINT/SIGTERM cancel the wait; the regular shutdown handler below is + // registered only after it, so nothing is registered twice. + schemaCtx, stopSchemaSignals := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) + _, err = waitForDBSchema(schemaCtx, database, defaultSchemaWaitPolicy, realClock{}, log.Printf) + stopSchemaSignals() + if errors.Is(err, context.Canceled) { + log.Printf("[db] shutdown requested while waiting for the ingestor's schema; exiting") + return + } + if err != nil { log.Fatalf("[db] schema not ready (ingestor must run migrations first): %v", err) } diff --git a/cmd/server/openapi.go b/cmd/server/openapi.go index b1af86407..4f3880ab1 100644 --- a/cmd/server/openapi.go +++ b/cmd/server/openapi.go @@ -122,7 +122,7 @@ func routeDescriptions() map[string]routeMeta { "GET /api/analytics/subpaths-bulk": {Summary: "Bulk subpath analysis", Tag: "analytics"}, "GET /api/analytics/subpath-detail": {Summary: "Subpath detail", Tag: "analytics"}, "GET /api/analytics/neighbor-graph": {Summary: "Neighbor graph", Description: "Full neighbor affinity graph for visualization.", Tag: "analytics"}, - "GET /api/analytics/relay-airtime-share": {Summary: "Relay airtime share per payload type", Description: "Overview tab's Relay Airtime Share. Each distinct packet (deduplicated by content hash) scores LoRa Time-on-Air of its raw bytes × distinct repeaters that relayed it, under the assumed preset returned in preset (config analytics.loraPreset); originator TX is excluded. rows[] = {payload_type, type, route_class, count, count_pct, score, airtime_pct}, sorted by airtime_pct desc. type is the numeric payload type; payload_type is a display label and may change. ADVERT is split into up to three rows that all have type 4: route_class \"flood\" (route_type 0/1, label \"ADVERT (flood)\"), \"zero_hop\" (route_type 2/3, label \"ADVERT (zero-hop)\") and \"legacy\" (NULL or out-of-range route_type, label \"ADVERT\"). route_class is null on every other row, so key rows by (type, route_class), never by type alone. The route is the one stored on the transmission: the first observation the ingestor inserted for that content hash, even if later observations of the same hash arrive on the other route class (e.g. a contact re-shared as a zero-hop advert). count_pct and airtime_pct are shares of total_count and total_score (nanoseconds). Payload Type Mix (/api/analytics/rf payloadTypes) is not split. Cached in the RF analytics cache (60s default).", Tag: "analytics", + "GET /api/analytics/relay-airtime-share": {Summary: "Relay airtime share per payload type", Description: "Overview tab's Relay Airtime Share. Each distinct packet (deduplicated by content hash) scores LoRa Time-on-Air of its raw bytes × distinct repeaters that relayed it, under the assumed preset returned in preset (config analytics.loraPreset); originator TX is excluded. rows[] = {payload_type, type, route_class, count, count_pct, score, airtime_pct}, sorted by airtime_pct desc. type is the numeric payload type; payload_type is a display label and may change. ADVERT is split into up to four rows that all have type 4, classified from transmissions.route_mask (every raw route type observed for the content hash, independent of ingest order): route_class \"flood\" (only route 0/1 seen, label \"ADVERT (flood)\"), \"zero_hop\" (only route 2/3, label \"ADVERT (zero-hop)\"), \"mixed\" (the same payload was seen on both flood and zero-hop routes, e.g. a contact re-shared as a zero-hop advert; label \"ADVERT (mixed)\"; counted once, with all of its relays) and \"legacy\" (no usable route, label \"ADVERT\"). Rows whose route_mask is not backfilled yet fall back to the legacy first-inserted route_type; route_mask_backfill {status: pending|backfilling|complete, remaining} reports whether that fallback is still in use: complete only when no transmission lacks a mask and this server has read every backfilled mask (the server picks them up while running); remaining counts rows without a mask, or, once none are left, an upper bound on the transmissions this server has not re-read yet (null while it cannot be counted). route_class is null on every other row, so key rows by (type, route_class), never by type alone. Time-on-Air uses the frame of the first inserted observation, so its length (path bytes, transport codes) can still depend on ingest order. count_pct and airtime_pct are shares of total_count and total_score (nanoseconds). Payload Type Mix (/api/analytics/rf payloadTypes) is not split. Cached in the RF analytics cache (60s default).", Tag: "analytics", QueryParams: []paramMeta{ {Name: "window", Description: "Relative window: 1h, 24h/1d, 3d, 7d/1w or 30d (default: all loaded packets)", Type: "string"}, {Name: "from", Description: "RFC3339 start; if from or to is given, window is ignored (an unparseable value leaves that bound open)", Type: "string"}, diff --git a/cmd/server/relay_airtime_share.go b/cmd/server/relay_airtime_share.go index 65000f40d..688e06af5 100644 --- a/cmd/server/relay_airtime_share.go +++ b/cmd/server/relay_airtime_share.go @@ -6,6 +6,7 @@ import ( "time" "github.com/meshcore-analyzer/lora" + "github.com/meshcore-analyzer/packetpath" ) // relay_airtime_share.go — issues #1359 + #1768 @@ -25,10 +26,11 @@ import ( // preset 869.6 MHz / BW 62.5 kHz / SF 8 / CR 4/5, with the // SF-dependent preamble pulled from internal/lora.PreambleForSF. // -// Aggregated by payload_type, except ADVERT packets which are split into flood -// and zero-hop route classes. Originator TX is deliberately excluded — a -// never-relayed direct message scores 0, which is the correct framing for a -// "relay amplification" metric. In-memory only; no SQL, no new index. +// Aggregated by payload_type, except ADVERT packets which are split into +// route classes (flood, zero-hop, mixed, legacy). Originator TX is +// deliberately excluded — a never-relayed direct message scores 0, which is +// the correct framing for a "relay amplification" metric. In-memory only; no +// SQL, no new index. // defaultLoRaPreset is the canonical fallback when config is absent. // Matches the reporter's `get radio` output `869.6179809, 62.5, 8, 5`. @@ -204,6 +206,7 @@ const ( relayAirtimeAdvertUnknown relayAirtimeAdvertRoute = iota relayAirtimeAdvertFlood relayAirtimeAdvertZeroHop + relayAirtimeAdvertMixed // #89: the same content hash was seen on flood and zero-hop routes ) type relayAirtimeBucketKey struct { @@ -211,20 +214,44 @@ type relayAirtimeBucketKey struct { advertRoute relayAirtimeAdvertRoute } -// relayAirtimeKey keeps non-ADVERT aggregation unchanged while separating the -// two ADVERT behaviours defined by MeshCore's route bits. Unknown/legacy route -// values deliberately keep the historical unsuffixed ADVERT bucket rather than -// being silently assigned to either behaviour. tx.PayloadType must be non-nil. -func relayAirtimeKey(tx *StoreTx) relayAirtimeBucketKey { - key := relayAirtimeBucketKey{payloadType: *tx.PayloadType} - if key.payloadType != PayloadADVERT || tx.RouteType == nil { - return key +// advertRouteClass is the single place that classifies an ADVERT's route. +// With a known route_mask (#89) it uses every raw route observed for the +// hash, so the result does not depend on ingest order: only routes 0/1 is +// flood, only routes 2/3 is zero-hop, both groups is mixed. Without usable +// mask bits (column absent, row not backfilled yet, or no valid route ever +// recorded) it falls back to the legacy first-inserted route_type, and +// NULL/out-of-range values stay unknown (the historical ADVERT bucket). +func advertRouteClass(tx *StoreTx) relayAirtimeAdvertRoute { + if tx.routeMaskKnown && int64(tx.routeMask)&packetpath.RouteMaskAll != 0 { + flood := int64(tx.routeMask)&packetpath.RouteMaskFlood != 0 + direct := int64(tx.routeMask)&packetpath.RouteMaskDirect != 0 + switch { + case flood && direct: + return relayAirtimeAdvertMixed + case flood: + return relayAirtimeAdvertFlood + default: + return relayAirtimeAdvertZeroHop + } + } + if tx.RouteType == nil { + return relayAirtimeAdvertUnknown } switch *tx.RouteType { case RouteTransportFlood, RouteFlood: - key.advertRoute = relayAirtimeAdvertFlood + return relayAirtimeAdvertFlood case RouteDirect, RouteTransportDirect: - key.advertRoute = relayAirtimeAdvertZeroHop + return relayAirtimeAdvertZeroHop + } + return relayAirtimeAdvertUnknown +} + +// relayAirtimeKey keeps non-ADVERT aggregation unchanged while separating the +// ADVERT route classes (see advertRouteClass). tx.PayloadType must be non-nil. +func relayAirtimeKey(tx *StoreTx) relayAirtimeBucketKey { + key := relayAirtimeBucketKey{payloadType: *tx.PayloadType} + if key.payloadType == PayloadADVERT { + key.advertRoute = advertRouteClass(tx) } return key } @@ -242,6 +269,8 @@ func relayAirtimeBucketName(key relayAirtimeBucketKey) string { return name + " (flood)" case relayAirtimeAdvertZeroHop: return name + " (zero-hop)" + case relayAirtimeAdvertMixed: + return name + " (mixed)" default: return name } @@ -253,6 +282,7 @@ func relayAirtimeBucketName(key relayAirtimeBucketKey) string { const ( relayAirtimeRouteClassFlood = "flood" relayAirtimeRouteClassZeroHop = "zero_hop" + relayAirtimeRouteClassMixed = "mixed" relayAirtimeRouteClassLegacy = "legacy" ) @@ -269,6 +299,8 @@ func relayAirtimeRouteClass(key relayAirtimeBucketKey) *string { class = relayAirtimeRouteClassFlood case relayAirtimeAdvertZeroHop: class = relayAirtimeRouteClassZeroHop + case relayAirtimeAdvertMixed: + class = relayAirtimeRouteClassMixed default: class = relayAirtimeRouteClassLegacy } @@ -276,13 +308,16 @@ func relayAirtimeRouteClass(key relayAirtimeBucketKey) *string { } // computeRelayAirtimeShare aggregates relay-airtime-share per payload_type, -// separating ADVERT rows by their flood and zero-hop route classes. +// separating ADVERT rows by their route class (see advertRouteClass). // -// The route class is the route_type stored on the transmission, which is the -// route of the first observation the ingestor inserted for that content hash. // The content hash ignores route bits, so a contact re-shared as a zero-hop -// advert has the same hash as the original flood advert; later observations -// never change the stored route (see cmd/ingestor InsertTransmission). +// advert has the same hash as the original flood advert. The route class +// comes from transmissions.route_mask, every raw route observed for the hash +// (#89): only route bits 0/1 is flood, only route bits 2/3 is zero-hop +// (direct), both groups is mixed; each hash is counted once. Only while the +// mask is not known (not backfilled yet) or has no usable route bits does it +// fall back to the legacy first-inserted route_type ("legacy" when that is +// not a valid route either). // // Returns: // @@ -290,8 +325,8 @@ func relayAirtimeRouteClass(key relayAirtimeBucketKey) *string { // "rows": [{payload_type, type, route_class, count, count_pct, score, airtime_pct}, ...] // sorted by airtime_pct desc, where type is the numeric payload type, // payload_type the display label and route_class "flood" / "zero_hop" / -// "legacy" on ADVERT rows and null otherwise; up to three ADVERT rows -// share type 4, and (type, route_class) identifies each row, +// "mixed" / "legacy" on ADVERT rows and null otherwise; up to four +// ADVERT rows share type 4, and (type, route_class) identifies each row, // "total_count": int, // "total_score": int64 (nanoseconds of LoRa Time-on-Air × repeater-count, summed across packets), // "window": window label, @@ -432,7 +467,19 @@ func (s *PacketStore) GetRelayAirtimeShareWithWindow(window TimeWindow) map[stri s.cacheMisses++ s.cacheMu.Unlock() + // #89: outside s.mu, and read before the rows so a refresh that lands + // in between errs toward "backfilling". While the route_mask backfill is + // not complete, some ADVERT rows are still classified by their legacy + // first-inserted route. + var backfill *RouteMaskBackfillStatus + if s.db != nil { + st := s.routeMaskBackfillStatus() + backfill = &st + } result := s.computeRelayAirtimeShare(window) + if backfill != nil { + result["route_mask_backfill"] = *backfill + } s.cacheMu.Lock() s.rfCache[cacheKey] = &cachedResult{data: result, expiresAt: time.Now().Add(s.rfCacheTTL)} diff --git a/cmd/server/route_mask.go b/cmd/server/route_mask.go new file mode 100644 index 000000000..a32a72349 --- /dev/null +++ b/cmd/server/route_mask.go @@ -0,0 +1,396 @@ +package main + +import ( + "database/sql" + "log" + "sort" + "strings" + "time" + + "github.com/meshcore-analyzer/dbschema" + "github.com/meshcore-analyzer/packetpath" +) + +// Issue #89: transmissions.route_mask records every raw route type observed +// for a content hash (bit r = route r). The ingestor sets it on insert, ORs +// later observations into it, and backfills legacy rows asynchronously. The +// server only reads it. + +// mergeRouteMask ORs a transmissions.route_mask value into the in-memory +// copy. NULL (not backfilled yet) leaves an unknown mask unknown; bits are +// never cleared. Caller holds s.mu for writing. +func (tx *StoreTx) mergeRouteMask(v sql.NullInt64) { + if !v.Valid { + return + } + tx.routeMask |= uint8(v.Int64 & packetpath.RouteMaskAll) + tx.routeMaskKnown = true +} + +// mergeRouteMaskOrQueue merges the mask of a transmission the store has just +// created and published in s.byTxID and, while that mask is still NULL, +// queues it so RefreshBackfilledRouteMasks reads it once the ingestor has +// backfilled it. Caller holds s.mu for writing. +func (s *PacketStore) mergeRouteMaskOrQueue(tx *StoreTx, v sql.NullInt64) { + tx.mergeRouteMask(v) + s.applyParkedRouteMask(tx) + s.queueUnknownRouteMask(tx) +} + +// queueUnknownRouteMask queues tx if its mask is still unknown. The tx must +// already be in s.byTxID: a refresh drops queued ids it cannot find there. +func (s *PacketStore) queueUnknownRouteMask(tx *StoreTx) { + if tx.routeMaskKnown || s.db == nil || !s.db.hasRouteMask() { + return + } + s.routeMaskInboxMu.Lock() + s.routeMaskInbox = append(s.routeMaskInbox, tx.ID) + s.routeMaskInboxMu.Unlock() + s.routeMaskQueuedCount.Add(1) +} + +// routeMaskPendingLen is an upper bound on the queued transmissions whose +// backfilled mask this server has not read yet (it still counts evicted or +// deleted ids until a refresh reaches them). +func (s *PacketStore) routeMaskPendingLen() int { + return int(s.routeMaskQueuedCount.Load()) +} + +// routeMaskRefreshLimit and routeMaskRefreshChunk bound one refresh: at most +// limit ids per poller tick, read in IN-lists of chunk ids. 2,000 ids per +// one-second tick stays ahead of the backfill (about 500 rows/s measured on a +// staging copy). +const ( + routeMaskRefreshLimit = 2000 + routeMaskRefreshChunk = 500 +) + +// RefreshBackfilledRouteMasks reads the route_mask of queued transmissions +// (loaded while their mask was NULL) and merges every value the ingestor's +// backfill has written since. It returns how many in-memory masks changed. +// +// The backfill fills NULL rows in ascending id order, so the queue is kept +// sorted and resolved up to the first id that is still NULL; that id and all +// later ones wait for a later tick. Ids whose row is gone (retention) or +// whose transmission was evicted are dropped. Read-only; the poller calls it +// on every tick. +func (s *PacketStore) RefreshBackfilledRouteMasks() int { + if s.db == nil || s.db.conn == nil || !s.db.hasRouteMask() { + return 0 + } + s.routeMaskRefreshMu.Lock() + defer s.routeMaskRefreshMu.Unlock() + + s.routeMaskInboxMu.Lock() + inbox := s.routeMaskInbox + s.routeMaskInbox = nil + s.routeMaskInboxMu.Unlock() + if len(inbox) > 0 { + // Sorted here, outside s.mu and the inbox lock that load paths take. + s.routeMaskQueue = append(s.routeMaskQueue, inbox...) + sort.Ints(s.routeMaskQueue) + } + ids := s.routeMaskQueue + if len(ids) > routeMaskRefreshLimit { + ids = ids[:routeMaskRefreshLimit] + } + if len(ids) == 0 { + return 0 + } + + masks := make(map[int]sql.NullInt64, len(ids)) + resolved := 0 + for start := 0; start < len(ids) && resolved == start; start += routeMaskRefreshChunk { + end := start + routeMaskRefreshChunk + if end > len(ids) { + end = len(ids) + } + if err := s.db.readRouteMasks(ids[start:end], masks); err != nil { + log.Printf("[route-mask] refresh read failed: %v", err) + break + } + for _, id := range ids[start:end] { + if v, ok := masks[id]; ok && !v.Valid { + break + } + resolved++ + } + } + if resolved == 0 { + return 0 + } + + changed := 0 + s.mu.Lock() + for _, id := range ids[:resolved] { + v, ok := masks[id] + tx := s.byTxID[id] + if !ok || tx == nil { + continue + } + known, before := tx.routeMaskKnown, tx.routeMask + tx.mergeRouteMask(v) + if !known || tx.routeMask != before { + changed++ + } + } + s.mu.Unlock() + + s.routeMaskQueue = s.routeMaskQueue[resolved:] + if len(s.routeMaskQueue) == 0 { + s.routeMaskQueue = nil + } + s.routeMaskQueuedCount.Add(-int64(resolved)) + + if changed > 0 { + // Relay Airtime Share lives in rfCache. + s.invalidateCachesFor(cacheInvalidation{hasNewObservations: true}) + } + return changed +} + +// routeMaskChangesBatch bounds how many route_mask_changes rows one poller +// tick reads. A var so tests can exercise several batches. +var routeMaskChangesBatch = 1000 + +// initRouteMaskChangeCursor sets the route_mask_changes watermark to the +// newest log row. Load and LoadChunked call it before they read any +// transmission: every change logged before the watermark is already in the +// masks they load, and every later one is read by RefreshRouteMaskChanges. +// A repeated call keeps the first watermark. Must not be called under s.mu. +func (s *PacketStore) initRouteMaskChangeCursor() { + if s.db == nil || s.db.conn == nil { + return + } + s.routeMaskChangesMu.Lock() + defer s.routeMaskChangesMu.Unlock() + s.initRouteMaskChangeCursorLocked() +} + +func (s *PacketStore) initRouteMaskChangeCursorLocked() { + if s.routeMaskChangesState != 0 { + return + } + var max sql.NullInt64 + err := s.db.conn.QueryRow(`SELECT MAX(id) FROM route_mask_changes`).Scan(&max) + switch { + case err == nil: + s.routeMaskChangesCursor = max.Int64 + s.routeMaskChangesState = 1 + case strings.Contains(err.Error(), "no such table"): + // Test schemas only: dbschema.AssertReady requires the table. + s.routeMaskChangesState = -1 + default: + // Without a watermark, read the whole log rather than start at its + // end: merges are idempotent, while starting at the end would skip + // every change logged since the load began. + log.Printf("[route-mask] reading the change-log watermark failed; reading the change log from the start: %v", err) + s.routeMaskChangesCursor = 0 + s.routeMaskChangesState = 1 + } +} + +// RefreshRouteMaskChanges applies route_mask_changes rows logged after the +// cursor, in id order, at most routeMaskChangesBatch per call. Each row +// carries the transmission's full mask after a new route bit, so no +// transmissions lookup is needed. The rows of a batch are ORed per +// transmission, read without s.mu, and merged under s.mu into transmissions +// the store holds. A change for a transmission not in the store is parked +// until the transmission is published (applyParkedRouteMask), and dropped once +// the start-up load has settled and the store has seen past its id, so an +// evicted, deleted or out-of-window transmission is never re-created. Returns +// how many in-memory masks changed; the Relay Airtime Share cache is +// invalidated only then. Read-only; the poller calls it on every tick. +func (s *PacketStore) RefreshRouteMaskChanges() int { + if s.db == nil || s.db.conn == nil { + return 0 + } + s.routeMaskChangesMu.Lock() + defer s.routeMaskChangesMu.Unlock() + if s.routeMaskChangesState == 0 { + // No load ran (tests): start from the current end of the log. + s.initRouteMaskChangeCursorLocked() + return 0 + } + if s.routeMaskChangesState < 0 { + return 0 + } + + rows, err := s.db.conn.Query(`SELECT id, transmission_id, route_mask FROM route_mask_changes + WHERE id > ? ORDER BY id LIMIT ?`, s.routeMaskChangesCursor, routeMaskChangesBatch) + if err != nil { + log.Printf("[route-mask] reading route_mask_changes failed: %v", err) + return 0 + } + masks := make(map[int]uint8) + last := s.routeMaskChangesCursor + var n int64 + for rows.Next() { + var id, mask int64 + var txID int + if err := rows.Scan(&id, &txID, &mask); err != nil { + rows.Close() + log.Printf("[route-mask] reading route_mask_changes failed: %v", err) + return 0 + } + masks[txID] |= uint8(mask & packetpath.RouteMaskAll) + last = id + n++ + } + if err := rows.Err(); err != nil { + rows.Close() + log.Printf("[route-mask] reading route_mask_changes failed: %v", err) + return 0 + } + rows.Close() + s.routeMaskChangeRowsRead.Add(n) + + settled := s.routeMaskLoadSettled.Load() + changed := 0 + s.mu.Lock() + for txID, m := range masks { + if tx := s.byTxID[txID]; tx != nil { + if mergeKnownRouteMask(tx, m) { + changed++ + } + continue + } + if s.routeMaskParked == nil { + s.routeMaskParked = make(map[int]uint8) + } + s.routeMaskParked[txID] |= m + } + for txID, m := range s.routeMaskParked { + if tx := s.byTxID[txID]; tx != nil { + if mergeKnownRouteMask(tx, m) { + changed++ + } + delete(s.routeMaskParked, txID) + } else if settled && txID <= s.maxTxID { + // Not in the store after the load settled, and the poller has + // read past its id: evicted, deleted or outside the load window. + delete(s.routeMaskParked, txID) + } + } + s.mu.Unlock() + // Advanced only after every row of the batch was applied or parked. + s.routeMaskChangesCursor = last + + if changed > 0 { + // Relay Airtime Share lives in rfCache. + s.invalidateCachesFor(cacheInvalidation{hasNewObservations: true}) + } + return changed +} + +// mergeKnownRouteMask ORs a logged (known) mask into tx and reports whether +// the in-memory mask changed. Caller holds s.mu for writing. +func mergeKnownRouteMask(tx *StoreTx, mask uint8) bool { + known, before := tx.routeMaskKnown, tx.routeMask + tx.mergeRouteMask(sql.NullInt64{Int64: int64(mask), Valid: true}) + return !known || tx.routeMask != before +} + +// applyParkedRouteMask merges a parked change into a transmission the store +// is publishing in s.byTxID. Caller holds s.mu for writing. +func (s *PacketStore) applyParkedRouteMask(tx *StoreTx) { + if m, ok := s.routeMaskParked[tx.ID]; ok { + mergeKnownRouteMask(tx, m) + delete(s.routeMaskParked, tx.ID) + } +} + +// readRouteMasks adds route_mask for each existing transmission in ids to +// out; ids without a row are left out. +func (db *DB) readRouteMasks(ids []int, out map[int]sql.NullInt64) error { + args := make([]interface{}, len(ids)) + for i, id := range ids { + args[i] = id + } + rows, err := db.conn.Query(`SELECT id, route_mask FROM transmissions WHERE id IN (`+ + strings.TrimSuffix(strings.Repeat("?,", len(ids)), ",")+`)`, args...) + if err != nil { + return err + } + defer rows.Close() + for rows.Next() { + var id int + var mask sql.NullInt64 + if err := rows.Scan(&id, &mask); err != nil { + return err + } + out[id] = mask + } + return rows.Err() +} + +// routeMaskBackfillStatus is the database status, except that "complete" +// becomes "backfilling" while this server still holds transmissions whose +// backfilled mask it has not read yet (remaining = how many). +func (s *PacketStore) routeMaskBackfillStatus() RouteMaskBackfillStatus { + st := s.db.routeMaskBackfillStatus() + if st.Status == "complete" { + if n := int64(s.routeMaskPendingLen()); n > 0 { + return RouteMaskBackfillStatus{Status: "backfilling", Remaining: &n} + } + } + return st +} + +// RouteMaskBackfillStatus is the read-only view of the ingestor's route_mask +// backfill, reported on /api/healthz and the Relay Airtime Share response. +// - pending: the column or the pending index does not exist yet, or rows +// still lack a mask while the backfill is not running +// - backfilling: rows lack a mask and the async migration is running +// - complete: no row lacks a mask +// +// Remaining is the number of rows without a mask, or null when it cannot be +// counted cheaply (no pending index yet). +type RouteMaskBackfillStatus struct { + Status string `json:"status"` + Remaining *int64 `json:"remaining"` +} + +// routeMaskStatusTTL bounds how often the status queries run; the partial +// index keeps them cheap (EXISTS 0.2-0.5 ms, COUNT 53-90 ms cold on a +// 496,798-transmission staging copy), but health endpoints are polled. +var routeMaskStatusTTL = 30 * time.Second + +func (db *DB) routeMaskBackfillStatus() RouteMaskBackfillStatus { + db.routeMaskStatusMu.Lock() + defer db.routeMaskStatusMu.Unlock() + if time.Now().Before(db.routeMaskStatusExp) { + return db.routeMaskStatus + } + db.routeMaskStatus = db.computeRouteMaskBackfillStatus() + db.routeMaskStatusExp = time.Now().Add(routeMaskStatusTTL) + return db.routeMaskStatus +} + +// computeRouteMaskBackfillStatus decides the status from the database itself, +// never from a flag that could claim completion early: "complete" requires +// that no transmission has route_mask IS NULL. +func (db *DB) computeRouteMaskBackfillStatus() RouteMaskBackfillStatus { + pending := RouteMaskBackfillStatus{Status: "pending"} + if !db.hasRouteMask() { + return pending + } + var hasIndex int + if err := db.conn.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type = 'index' AND name = ?`, + dbschema.RouteMaskPendingIndex).Scan(&hasIndex); err != nil || hasIndex == 0 { + return pending + } + var remaining int64 + if err := db.conn.QueryRow(`SELECT COUNT(*) FROM transmissions WHERE route_mask IS NULL`).Scan(&remaining); err != nil { + return pending + } + if remaining == 0 { + return RouteMaskBackfillStatus{Status: "complete", Remaining: &remaining} + } + var asyncStatus string + db.conn.QueryRow(`SELECT status FROM _async_migrations WHERE name = ?`, dbschema.RouteMaskBackfillMigration).Scan(&asyncStatus) + if asyncStatus == "pending_async" { + return RouteMaskBackfillStatus{Status: "backfilling", Remaining: &remaining} + } + return RouteMaskBackfillStatus{Status: "pending", Remaining: &remaining} +} diff --git a/cmd/server/route_mask_changes_server_test.go b/cmd/server/route_mask_changes_server_test.go new file mode 100644 index 000000000..9d72d660a --- /dev/null +++ b/cmd/server/route_mask_changes_server_test.go @@ -0,0 +1,575 @@ +package main + +import ( + "database/sql" + "fmt" + "path/filepath" + "reflect" + "sync" + "testing" + "time" + + "github.com/meshcore-analyzer/dbschema" +) + +// PR #93 review: an observation that brings a new route bit through an +// upsert of an existing observation row (same observer and path) keeps its +// id, so the poller's new-observation query never sees it. The ingestor logs +// every actual mask change in route_mask_changes, in the same transaction; +// the server applies those rows to transmissions it holds, without a restart +// and without re-creating transmissions it does not hold. + +const rmChangesDDL = dbschema.CreateRouteMaskChangesTableSQL + +// rmChangesDB is a server test DB with route_mask, the change log and the +// ingestor's observation dedup index. tx 1 "adv" is an ADVERT seen once, +// by observer 1 on path [] with the given route and mask. +func rmChangesDB(t *testing.T, route int, mask int64, raw string) *DB { + t.Helper() + db := routeMaskServerDB(t) + rmExec(t, db, rmChangesDDL) + rmExec(t, db, dbschema.CreateRouteMaskChangesIndexSQL) + rmExec(t, db, `CREATE UNIQUE INDEX idx_observations_dedup ON observations(transmission_id, observer_idx, COALESCE(path_json, ''))`) + fs := time.Now().UTC().Add(-time.Hour) + rmInsertTx(t, db, 1, "adv", route, mask, fs.Format(time.RFC3339)) + rmInsertObs(t, db, 1, 1, 1, `[]`, raw, fs.Unix()) + return db +} + +// rmIngestNewBit does what the ingestor's insertObservationWithRouteBit does +// in one transaction: OR the bit, insert or upsert the observation, and log +// the resulting mask when it changed. +func rmIngestNewBit(t *testing.T, db *DB, txID int, bit int64, observer int, path, raw string) { + t.Helper() + if err := rmIngestNewBitErr(db, txID, bit, observer, path, raw); err != nil { + t.Fatal(err) + } +} + +func rmIngestNewBitErr(db *DB, txID int, bit int64, observer int, path, raw string) error { + tx, err := db.conn.Begin() + if err != nil { + return err + } + defer tx.Rollback() + res, err := tx.Exec(`UPDATE transmissions SET route_mask = route_mask | ? WHERE id = ? AND route_mask IS NOT NULL AND (route_mask & ?) = 0`, bit, txID, bit) + if err != nil { + return err + } + if _, err := tx.Exec(`INSERT INTO observations (transmission_id, observer_idx, path_json, timestamp, raw_hex) + VALUES (?, ?, ?, ?, ?) + ON CONFLICT(transmission_id, observer_idx, COALESCE(path_json, '')) DO UPDATE SET raw_hex = COALESCE(excluded.raw_hex, raw_hex)`, + txID, observer, path, time.Now().Unix(), raw); err != nil { + return err + } + if n, _ := res.RowsAffected(); n > 0 { + if _, err := tx.Exec(`INSERT INTO route_mask_changes (transmission_id, route_mask, created_at) + SELECT id, route_mask, ? FROM transmissions WHERE id = ?`, time.Now().Unix(), txID); err != nil { + return err + } + } + return tx.Commit() +} + +// rmPoller is the production poller driven one tick at a time. +type rmPoller struct { + p *Poller + lastTx, lastOb int +} + +func newRMPoller(db *DB, s *PacketStore) *rmPoller { + p := NewPoller(db, NewHub(), time.Hour) + p.store = s + return &rmPoller{p: p, lastTx: s.MaxTransmissionID(), lastOb: s.MaxObservationID()} +} + +func (r *rmPoller) tick() { r.lastTx, r.lastOb = r.p.pollStore(r.lastTx, r.lastOb) } + +func rmRelayCached(s *PacketStore) bool { + return s.GetRelayAirtimeShareWithWindow(TimeWindow{})["cached"] == true +} + +func TestRouteMaskChanges_SameRowUpsertReachesRunningServer(t *testing.T) { + for _, tc := range []struct { + name string + route int + mask, bit, want int64 + firstRaw, raw string + before string + }{ + {"flood to mixed", 0, 0b0001, 0b1000, 0b1001, "100000000000", "130000000000", "ADVERT (flood)"}, + {"zero-hop to mixed", 3, 0b1000, 0b0001, 0b1001, "130000000000", "100000000000", "ADVERT (zero-hop)"}, + } { + t.Run(tc.name, func(t *testing.T) { + db := rmChangesDB(t, tc.route, tc.mask, tc.firstRaw) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + if got := rmAdvertRows(s); !reflect.DeepEqual(got, map[string]int{tc.before: 1}) { + t.Fatalf("before: %v", got) + } + poll := newRMPoller(db, s) + poll.tick() + + rmIngestNewBit(t, db, 1, tc.bit, 1, `[]`, tc.raw) // same observer, same path + var n, id int + db.conn.QueryRow(`SELECT COUNT(*), MAX(id) FROM observations WHERE transmission_id = 1`).Scan(&n, &id) + if n != 1 || id != 1 { + t.Fatalf("setup: observation rows=%d max id=%d, want the one row 1 upserted in place", n, id) + } + + poll.tick() + if v := rmSnapshot(s)["adv"]; v != (rmView{uint8(tc.want), true}) { + t.Fatalf("in-memory mask after one tick = %04b known=%v, want %04b", v.Mask, v.Known, tc.want) + } + if got := rmAdvertRows(s); !reflect.DeepEqual(got, map[string]int{"ADVERT (mixed)": 1}) { + t.Fatalf("Relay Airtime Share after one tick: %v, want ADVERT (mixed)=1", got) + } + }) + } +} + +// A change row whose mask adds nothing (an identical route, or a change the +// load already read) changes nothing and keeps the cached Relay Airtime +// Share; a real change invalidates it. +func TestRouteMaskChanges_InvalidateOnlyOnRealChange(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + poll := newRMPoller(db, s) + rmAdvertRows(s) // fill the cache + if !rmRelayCached(s) { + t.Fatal("setup: relay share not cached") + } + rmExec(t, db, `INSERT INTO route_mask_changes (transmission_id, route_mask, created_at) VALUES (1, 2, 1)`) + poll.tick() + if !rmRelayCached(s) { + t.Fatal("a change row that adds no bit invalidated the Relay Airtime Share cache") + } + if n := s.RefreshRouteMaskChanges(); n != 0 { + t.Fatalf("a refresh with nothing new changed %d masks", n) + } + rmIngestNewBit(t, db, 1, 0b1000, 1, `[]`, "130000000000") // same row + poll.tick() + if rmRelayCached(s) { + t.Fatal("a real mask change kept the stale cached Relay Airtime Share") + } + if got := rmAdvertRows(s); !reflect.DeepEqual(got, map[string]int{"ADVERT (mixed)": 1}) { + t.Fatalf("after the change: %v", got) + } +} + +// Several changes before the next tick, more than one refresh batch: all are +// applied in order over consecutive ticks and the final mask is complete. +func TestRouteMaskChanges_SeveralChangesAcrossBatches(t *testing.T) { + prev := routeMaskChangesBatch + routeMaskChangesBatch = 2 + defer func() { routeMaskChangesBatch = prev }() + db := rmChangesDB(t, 1, 0b0010, "110000") + fs := time.Now().UTC().Add(-time.Hour) + rmInsertTx(t, db, 2, "adv-2", 1, 0b0010, fs.Format(time.RFC3339)) + rmInsertObs(t, db, 2, 2, 1, `[]`, "110000", fs.Unix()) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + poll := newRMPoller(db, s) + // Every bit arrives through an upsert of the same row, so only the change + // log can carry it. + rmIngestNewBit(t, db, 1, 0b1000, 1, `[]`, "130000000000") + rmIngestNewBit(t, db, 1, 0b0001, 1, `[]`, "100000000000") + rmIngestNewBit(t, db, 2, 0b0100, 1, `[]`, "120000") + rmIngestNewBit(t, db, 1, 0b0100, 1, `[]`, "120000") + rmIngestNewBit(t, db, 2, 0b1000, 1, `[]`, "130000000000") + for i := 0; i < 3; i++ { + poll.tick() + } + snap := rmSnapshot(s) + if snap["adv"] != (rmView{0b1111, true}) || snap["adv-2"] != (rmView{0b1110, true}) { + t.Fatalf("after all batches: %v, want adv 1111 and adv-2 1110", snap) + } +} + +// A change for a transmission the server does not hold (evicted, outside its +// load window, or deleted) never re-creates it, and once the start-up load is +// settled the parked change is dropped. +func TestRouteMaskChanges_NeverRecreatesMissingTransmissions(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + fs := time.Now().UTC().Add(-time.Hour) + rmInsertTx(t, db, 2, "evicted", 1, 0b0010, fs.Format(time.RFC3339)) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + poll := newRMPoller(db, s) + s.mu.Lock() + delete(s.byTxID, 2) // evicted + s.mu.Unlock() + rmIngestNewBit(t, db, 2, 0b1000, 1, `[]`, "130000000000") + rmExec(t, db, `INSERT INTO route_mask_changes (transmission_id, route_mask, created_at) VALUES (999, 10, 1)`) // deleted tx + poll.tick() + s.mu.RLock() + _, back := s.byTxID[2] + _, ghost := s.byTxID[999] + parked := len(s.routeMaskParked) + s.mu.RUnlock() + if back || ghost { + t.Fatalf("refresh re-created a transmission: evicted=%v deleted=%v", back, ghost) + } + if parked != 1 { + t.Fatalf("parked = %d, want only the change of tx 999 (above every id the store has seen, so it may still arrive)", parked) + } + // A newer transmission arrives: the store has now seen past 999, so the + // change of the missing tx 999 is dropped, still without re-creating it. + rmInsertTx(t, db, 1000, "newer", 1, 0b0010, fs.Format(time.RFC3339)) + poll.tick() + s.mu.RLock() + parked = len(s.routeMaskParked) + _, ghost = s.byTxID[999] + s.mu.RUnlock() + if parked != 0 || ghost { + t.Fatalf("after the store passed tx 999: parked=%d re-created=%v", parked, ghost) + } + if n := len(s.packets); n != 3 { + t.Fatalf("store holds %d packets, want the 2 it loaded plus the new one", n) + } +} + +// Start-up: a change committed before the watermark is covered by the load +// itself; one committed after the watermark is applied (idempotently) by the +// poller; a restart with old changes in the table reads none of them. +func TestRouteMaskChanges_StartupWatermark(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + rmIngestNewBit(t, db, 1, 0b1000, 2, `[]`, "130000000000") // before the server starts + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1010, true}) { + t.Fatalf("cold load = %v, want 1010 known", v) + } + read := s.routeMaskChangeRowsRead.Load() + if n := s.RefreshRouteMaskChanges(); n != 0 || s.routeMaskChangeRowsRead.Load() != read { + t.Fatalf("restart re-read old changes: changed %d, rows read %d", n, s.routeMaskChangeRowsRead.Load()-read) + } + + // Watermark taken, then a change lands before the load reads the row. + s2 := NewPacketStore(db, nil) + s2.initRouteMaskChangeCursor() + rmIngestNewBit(t, db, 1, 0b0001, 1, `[]`, "100000000000") + if err := s2.Load(); err != nil { + t.Fatal(err) + } + if n := s2.RefreshRouteMaskChanges(); n != 0 { + t.Fatalf("change already read by the load changed %d masks again", n) + } + if got := s2.routeMaskChangeRowsRead.Load(); got != 1 { + t.Fatalf("rows read after the watermark = %d, want 1", got) + } + if v := rmSnapshot(s2)["adv"]; v != (rmView{0b1011, true}) { + t.Fatalf("after load and refresh = %v, want 1011 known", v) + } +} + +// Chunked start-up: the background loader has scanned a transmission but not +// published it when a change lands and a poller tick runs. The change is +// parked, not dropped, and applied when the transmission is published. +func TestRouteMaskChanges_ParkedUntilTheChunkIsPublished(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + s := NewPacketStore(db, nil) + s.initRouteMaskChangeCursor() + s.loadChunkScannedHook = func() { + rmIngestNewBit(t, db, 1, 0b1000, 1, `[]`, "130000000000") + rmIngestNewBit(t, db, 1, 0b0001, 2, `[]`, "100000000000") + s.RefreshRouteMaskChanges() + s.mu.RLock() + parked := s.routeMaskParked[1] + s.mu.RUnlock() + if parked != 0b1011 { + t.Errorf("parked mask while the chunk is unpublished = %04b, want 1011", parked) + } + } + if err := s.loadChunk(time.Now().Add(-48*time.Hour), time.Now().Add(time.Hour)); err != nil { + t.Fatal(err) + } + s.loadChunkScannedHook = nil + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1011, true}) { + t.Fatalf("published transmission = %v, want 1011 known", v) + } + s.mu.RLock() + parked := len(s.routeMaskParked) + s.mu.RUnlock() + if parked != 0 { + t.Fatalf("%d changes still parked after publication", parked) + } +} + +// The backfill refresh (rows loaded while NULL) and the change log are both +// monotonic merges; together they converge on the database value. +func TestRouteMaskChanges_BackfillAndLiveChangeConverge(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + rmExec(t, db, `UPDATE transmissions SET route_mask = NULL WHERE id = 1`) + rmExec(t, db, `CREATE INDEX idx_tx_route_mask_null ON transmissions(id) WHERE route_mask IS NULL`) + prev := routeMaskStatusTTL + routeMaskStatusTTL = 0 + defer func() { routeMaskStatusTTL = prev }() + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + poll := newRMPoller(db, s) + rmExec(t, db, `UPDATE transmissions SET route_mask = 2 WHERE id = 1`) // backfill, no change row + rmIngestNewBit(t, db, 1, 0b1000, 2, `[]`, "130000000000") // live change, logged + poll.tick() + poll.tick() + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1010, true}) { + t.Fatalf("after backfill and live change = %v, want 1010 known", v) + } + if st := s.routeMaskBackfillStatus(); st.Status != "complete" { + t.Fatalf("status = %+v, want complete", st) + } +} + +// Ingest and poll concurrently: after the writer stops and one more tick, +// every in-memory mask equals the database. +func TestRouteMaskChanges_ConcurrentIngestAndPoll(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + fs := time.Now().UTC().Add(-time.Hour).Format(time.RFC3339) + const n = 40 + for i := 2; i <= n; i++ { + rmInsertTx(t, db, i, fmt.Sprintf("adv-%d", i), 1, 0b0010, fs) + rmInsertObs(t, db, i, i, 1, `[]`, "110000", time.Now().Unix()) + } + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + poll := newRMPoller(db, s) + var wg sync.WaitGroup + done := make(chan struct{}) + wg.Add(1) + go func() { + defer wg.Done() + defer close(done) + for i := 1; i <= n; i++ { + for _, err := range []error{ + rmIngestNewBitErr(db, i, 0b1000, 1, `[]`, "130000000000"), + rmIngestNewBitErr(db, i, 0b0001, 1, `[]`, "100000000000"), + } { + if err != nil { + t.Error(err) + return + } + } + } + }() + for running := true; running; { + select { + case <-done: + running = false + default: + poll.tick() + } + } + wg.Wait() + for i := 0; i < 1+2*n/routeMaskChangesBatch; i++ { + poll.tick() + } + cold := NewPacketStore(db, nil) + if err := cold.Load(); err != nil { + t.Fatal(err) + } + if live, want := rmSnapshot(s), rmSnapshot(cold); !reflect.DeepEqual(live, want) { + t.Fatalf("live view differs from a cold load after concurrent ingest") + } + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1011, true}) { + t.Fatalf("adv = %v, want 1011", v) + } +} + +// Without the table (test databases; AssertReady requires it in production) +// the refresh is a no-op. +func TestRouteMaskChanges_NoTableIsNoOp(t *testing.T) { + db := routeMaskServerDB(t) + rmSeed(t, db) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + for i := 0; i < 2; i++ { + if n := s.RefreshRouteMaskChanges(); n != 0 { + t.Fatalf("refresh without the table changed %d", n) + } + } +} + +// In production the poller starts only after the first chunk is loaded. A +// change committed between the load and the poller's first tick must still +// be applied: the watermark comes from before the load, not from the first +// tick. +func TestRouteMaskChanges_ChangeBeforeFirstTickIsApplied(t *testing.T) { + for _, load := range []struct { + name string + fn func(*PacketStore) error + }{ + {"Load", func(s *PacketStore) error { return s.Load() }}, + {"LoadChunked", func(s *PacketStore) error { return s.LoadChunked(1) }}, + } { + t.Run(load.name, func(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + s := NewPacketStore(db, nil) + if err := load.fn(s); err != nil { + t.Fatal(err) + } + rmIngestNewBit(t, db, 1, 0b1000, 1, `[]`, "130000000000") // same row + newRMPoller(db, s).tick() + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1010, true}) { + t.Fatalf("after the first tick = %04b known=%v, want 1010", v.Mask, v.Known) + } + }) + } +} + +// A background fill that does not reach full coverage never sets +// backgroundLoadDone, but the start-up load is still over: changes for +// transmissions the store will never hold must not stay parked forever. +func TestRouteMaskChanges_ParkedDroppedAfterPartialStartupLoad(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + rmExec(t, db, `UPDATE transmissions SET first_seen = ? WHERE id = 1`, time.Now().UTC().AddDate(0, 0, -30).Format(time.RFC3339)) + old := time.Now().UTC().AddDate(0, 0, -30).Format(time.RFC3339) + for i := 2; i <= 19; i++ { + rmInsertTx(t, db, i, fmt.Sprintf("old-%d", i), 1, 0b0010, old) + } + rmInsertTx(t, db, 20, "recent", 1, 0b0010, time.Now().UTC().Add(-30*time.Minute).Format(time.RFC3339)) + s := NewPacketStore(db, nil) + s.hotStartupHours, s.retentionHours = 1, 2 + // A background chunk fails (its query cannot run), as a real chunk error + // would: the fill is partial and backgroundLoadDone stays false. + s.bgLoaderEntryHook = func() { rmExec(t, db, `ALTER TABLE observations RENAME TO observations_hidden`) } + if err := s.RunStartupLoad(1); err != nil { + t.Fatal(err) + } + rmExec(t, db, `ALTER TABLE observations_hidden RENAME TO observations`) + if s.backgroundLoadDone.Load() || !s.backgroundLoadFailed.Load() { + t.Fatalf("setup: want a partial background load (done=%v failed=%v)", s.backgroundLoadDone.Load(), s.backgroundLoadFailed.Load()) + } + poll := newRMPoller(db, s) + rmIngestNewBit(t, db, 5, 0b1000, 1, `[]`, "130000000000") // tx 5 is outside the loaded window + poll.tick() + s.mu.RLock() + parked := len(s.routeMaskParked) + _, back := s.byTxID[5] + s.mu.RUnlock() + if parked != 0 || back { + t.Fatalf("after a partial start-up load: parked=%d re-created=%v, want the change dropped", parked, back) + } +} + +// An older transmission the background loader is still bringing in, below +// ids the store already holds, keeps its change parked until it is published. +func TestRouteMaskChanges_OlderChunkBelowMaxIDKeepsItsChange(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + rmExec(t, db, `UPDATE transmissions SET first_seen = ? WHERE id = 1`, time.Now().UTC().Add(-5*time.Hour).Format(time.RFC3339)) + rmInsertTx(t, db, 2, "recent", 1, 0b0010, time.Now().UTC().Add(-30*time.Minute).Format(time.RFC3339)) + s := NewPacketStore(db, nil) + s.hotStartupHours = 1 + if err := s.LoadChunked(1); err != nil { + t.Fatal(err) + } + if s.MaxTransmissionID() != 2 { + t.Fatalf("setup: max tx id %d, want 2", s.MaxTransmissionID()) + } + s.loadChunkScannedHook = func() { + rmIngestNewBit(t, db, 1, 0b1000, 1, `[]`, "130000000000") + s.RefreshRouteMaskChanges() + } + if err := s.loadChunk(time.Now().Add(-6*time.Hour), time.Now().Add(-time.Hour)); err != nil { + t.Fatal(err) + } + s.loadChunkScannedHook = nil + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1010, true}) { + t.Fatalf("older transmission published as %04b known=%v, want 1010", v.Mask, v.Known) + } +} + +// If the watermark cannot be read at load time, the server must not jump to +// the end of the log on its first tick: it reads from the start instead. +func TestRouteMaskChanges_WatermarkReadErrorReadsFromTheStart(t *testing.T) { + db := rmChangesDB(t, 1, 0b0010, "110000") + rmExec(t, db, `DROP TABLE route_mask_changes`) + rmExec(t, db, `CREATE TABLE route_mask_changes (x INTEGER)`) // MAX(id) fails: no such column + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + rmExec(t, db, `DROP TABLE route_mask_changes`) + rmExec(t, db, rmChangesDDL) + rmIngestNewBit(t, db, 1, 0b1000, 1, `[]`, "130000000000") + newRMPoller(db, s).tick() + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1010, true}) { + t.Fatalf("after a failed watermark read = %04b known=%v, want 1010", v.Mask, v.Known) + } +} + +// rmFileDBs copies an in-memory test DB to a WAL file and returns a server +// view and a separate writer on it, so a test can commit a change while a +// load holds its read cursor open. +func rmFileDBs(t *testing.T, mem *DB) (server, writer *DB) { + t.Helper() + path := filepath.Join(t.TempDir(), "rm.db") + rmExec(t, mem, `VACUUM INTO '`+path+`'`) + open := func() *sql.DB { + c, err := sql.Open("sqlite", path+"?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)") + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { c.Close() }) + return c + } + server = &DB{conn: open()} + for _, f := range []*schemaFlag{&server.isV3Flag, &server.hasResolvedPathFlag, &server.hasRouteMaskFlag, &server.hasObsRawHexFlag} { + f.forceTrue() + } + w := open() + w.SetMaxOpenConns(1) + return server, &DB{conn: w} +} + +// The watermark is taken before the load reads any transmission: a change +// committed while the load is reading (after the row was read) is applied on +// the next tick, for both load paths. +func TestRouteMaskChanges_WatermarkTakenBeforeTheLoadReads(t *testing.T) { + for _, load := range []struct { + name string + fn func(*PacketStore) error + }{ + {"Load", func(s *PacketStore) error { return s.Load() }}, + {"LoadChunked", func(s *PacketStore) error { return s.LoadChunked(1) }}, + } { + t.Run(load.name, func(t *testing.T) { + server, writer := rmFileDBs(t, rmChangesDB(t, 1, 0b0010, "110000")) + s := NewPacketStore(server, nil) + fired := false + s.loadScannedRowHook = func() { + fired = true + rmIngestNewBit(t, writer, 1, 0b1000, 1, `[]`, "130000000000") + } + if err := load.fn(s); err != nil { + t.Fatal(err) + } + if !fired { + t.Fatal("setup: the load hook did not run") + } + if v := rmSnapshot(s)["adv"]; v.Mask != 0b0010 { + t.Fatalf("setup: the load saw the change (mask %04b); the hook must run after the row was read", v.Mask) + } + newRMPoller(server, s).tick() + if v := rmSnapshot(s)["adv"]; v != (rmView{0b1010, true}) { + t.Fatalf("after the first tick = %04b known=%v, want 1010", v.Mask, v.Known) + } + }) + } +} diff --git a/cmd/server/route_mask_refresh_test.go b/cmd/server/route_mask_refresh_test.go new file mode 100644 index 000000000..189937724 --- /dev/null +++ b/cmd/server/route_mask_refresh_test.go @@ -0,0 +1,294 @@ +package main + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "reflect" + "testing" + "time" + + "github.com/gorilla/mux" + "github.com/meshcore-analyzer/dbschema" +) + +// Issue #89 review: the ingestor backfills route_mask while the server is +// already running (both restart together on a deploy, and the backfill takes +// minutes). The server must pick the backfilled masks up without a restart, +// and must not report the backfill complete before its own view has them. + +func rmIndexedDB(t *testing.T) *DB { + t.Helper() + db := routeMaskServerDB(t) + rmSeed(t, db) // tx 3 "legacy": route_type 2, route_mask NULL + if _, err := db.conn.Exec(dbschema.CreateRouteMaskPendingIndexSQL); err != nil { + t.Fatal(err) + } + prev := routeMaskStatusTTL + routeMaskStatusTTL = 0 + t.Cleanup(func() { routeMaskStatusTTL = prev }) + return db +} + +func rmExec(t *testing.T, db *DB, q string, args ...interface{}) { + t.Helper() + if _, err := db.conn.Exec(q, args...); err != nil { + t.Fatal(err) + } +} + +func rmAdvertRows(s *PacketStore) map[string]int { + res := s.GetRelayAirtimeShareWithWindow(TimeWindow{}) + out := map[string]int{} + for _, r := range res["rows"].([]map[string]interface{}) { + if r["type"] == PayloadADVERT { + out[r["payload_type"].(string)] = r["count"].(int) + } + } + return out +} + +func TestRouteMask_RunningServerPicksUpBackfilledMasks(t *testing.T) { + db := rmIndexedDB(t) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + if got, want := rmAdvertRows(s), map[string]int{"ADVERT (mixed)": 1, "ADVERT (flood)": 1, "ADVERT (zero-hop)": 1}; !reflect.DeepEqual(got, want) { + t.Fatalf("before the backfill: %v, want %v", got, want) + } + + // The backfill fills the legacy row: its frames show flood and zero-hop. + rmExec(t, db, `UPDATE transmissions SET route_mask = 6 WHERE id = 3`) + if st := db.computeRouteMaskBackfillStatus(); st.Status != "complete" { + t.Fatalf("database status = %+v, want complete", st) + } + if st := s.routeMaskBackfillStatus(); st.Status != "backfilling" || st.Remaining == nil || *st.Remaining != 1 { + t.Fatalf("server status before it read the backfilled mask = %+v, want backfilling remaining=1", st) + } + + if n := s.RefreshBackfilledRouteMasks(); n != 1 { + t.Fatalf("RefreshBackfilledRouteMasks merged %d masks, want 1", n) + } + live := rmSnapshot(s) + if live["legacy"] != (rmView{0b0110, true}) { + t.Fatalf("legacy row after refresh = %v, want 0110 known", live["legacy"]) + } + cold := NewPacketStore(db, nil) + if err := cold.Load(); err != nil { + t.Fatal(err) + } + if want := rmSnapshot(cold); !reflect.DeepEqual(live, want) { + t.Fatalf("live %v != cold load %v", live, want) + } + if st := s.routeMaskBackfillStatus(); st.Status != "complete" || st.Remaining == nil || *st.Remaining != 0 { + t.Fatalf("server status after refresh = %+v, want complete remaining=0", st) + } + // The cached Relay Airtime Share result is invalidated by the refresh. + if got, want := rmAdvertRows(s), map[string]int{"ADVERT (mixed)": 2, "ADVERT (flood)": 1}; !reflect.DeepEqual(got, want) { + t.Fatalf("after the refresh: %v, want %v", got, want) + } + if n := s.RefreshBackfilledRouteMasks(); n != 0 { + t.Fatalf("a second refresh merged %d masks, want 0", n) + } +} + +// The backfill fills NULL rows in ascending id order; the refresh follows it, +// keeps rows the backfill has not reached, and drops rows that are gone. +func TestRouteMask_RefreshFollowsTheBackfill(t *testing.T) { + db := rmIndexedDB(t) + fs := time.Now().UTC().Add(-time.Hour).Format(time.RFC3339) + rmInsertTx(t, db, 5, "legacy-2", 1, nil, fs) + rmInsertTx(t, db, 6, "legacy-gone", 1, nil, fs) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + + s.RefreshBackfilledRouteMasks() // backfill not started: nothing to merge + if got := s.routeMaskPendingLen(); got != 3 { + t.Fatalf("pending = %d before the backfill, want 3", got) + } + + rmExec(t, db, `UPDATE transmissions SET route_mask = 4 WHERE id = 3`) + s.RefreshBackfilledRouteMasks() + snap := rmSnapshot(s) + if snap["legacy"] != (rmView{0b0100, true}) || snap["legacy-2"].Known { + t.Fatalf("after the first batch: %v", snap) + } + if st := s.routeMaskBackfillStatus(); st.Status == "complete" { + t.Fatalf("complete with NULL rows left: %+v", st) + } + + // Retention removed tx 6 before the backfill reached it. + rmExec(t, db, `DELETE FROM transmissions WHERE id = 6`) + rmExec(t, db, `UPDATE transmissions SET route_mask = 2 WHERE id = 5`) + s.RefreshBackfilledRouteMasks() + if v := rmSnapshot(s)["legacy-2"]; v != (rmView{0b0010, true}) { + t.Fatalf("legacy-2 = %v, want 0010 known", v) + } + if got := s.routeMaskPendingLen(); got != 0 { + t.Fatalf("pending = %d after the backfill, want 0", got) + } + if st := s.routeMaskBackfillStatus(); st.Status != "complete" { + t.Fatalf("status = %+v, want complete", st) + } +} + +// A NULL row that reaches the server through live ingest (written by an older +// ingestor after a rollback) is picked up once the backfill fills it. +func TestRouteMask_NullRowIngestedLiveIsPickedUp(t *testing.T) { + db := rmIndexedDB(t) + rmExec(t, db, `UPDATE transmissions SET route_mask = 4 WHERE id = 3`) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + rmInsertTx(t, db, 7, "rollback-null", 1, nil, time.Now().UTC().Add(-time.Minute).Format(time.RFC3339)) + s.IngestNewFromDB(3, 100) + if v := rmSnapshot(s)["rollback-null"]; v.Known { + t.Fatalf("NULL row ingested as known: %v", v) + } + rmExec(t, db, `UPDATE transmissions SET route_mask = 2 WHERE id = 7`) + if st := s.routeMaskBackfillStatus(); st.Status == "complete" { + t.Fatalf("complete before the server read the mask: %+v", st) + } + s.RefreshBackfilledRouteMasks() + if v := rmSnapshot(s)["rollback-null"]; v != (rmView{0b0010, true}) { + t.Fatalf("rollback-null = %v, want 0010 known", v) + } +} + +func TestPoller_PicksUpBackfilledRouteMasks(t *testing.T) { + db := rmIndexedDB(t) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + poller := NewPoller(db, NewHub(), 20*time.Millisecond) + poller.store = s + go poller.Start() + defer poller.Stop() + rmExec(t, db, `UPDATE transmissions SET route_mask = 6 WHERE id = 3`) + deadline := time.Now().Add(5 * time.Second) + for rmSnapshot(s)["legacy"] != (rmView{0b0110, true}) { + if time.Now().After(deadline) { + t.Fatalf("poller did not pick up the backfilled mask: %v", rmSnapshot(s)["legacy"]) + } + time.Sleep(20 * time.Millisecond) + } +} + +func TestHealthz_RouteMaskBackfillWaitsForTheServer(t *testing.T) { + db := rmIndexedDB(t) + srv := NewServer(db, &Config{Port: 3000}, NewHub()) + srv.store = NewPacketStore(db, nil) + if err := srv.store.Load(); err != nil { + t.Fatal(err) + } + router := mux.NewRouter() + srv.RegisterRoutes(router) + prev := readiness.Load() + readiness.Store(1) + defer readiness.Store(prev) + status := func() RouteMaskBackfillStatus { + w := httptest.NewRecorder() + router.ServeHTTP(w, httptest.NewRequest("GET", "/api/healthz", nil)) + if w.Code != http.StatusOK { + t.Fatalf("healthz status %d: %s", w.Code, w.Body.String()) + } + var body struct { + RouteMask *RouteMaskBackfillStatus `json:"route_mask_backfill"` + } + if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil || body.RouteMask == nil { + t.Fatalf("healthz body %s: %v", w.Body.String(), err) + } + return *body.RouteMask + } + rmExec(t, db, `UPDATE transmissions SET route_mask = 6 WHERE id = 3`) + if st := status(); st.Status != "backfilling" || st.Remaining == nil || *st.Remaining != 1 { + t.Fatalf("healthz before the server caught up = %+v, want backfilling remaining=1", st) + } + srv.store.RefreshBackfilledRouteMasks() + if st := status(); st.Status != "complete" { + t.Fatalf("healthz after the refresh = %+v, want complete", st) + } +} + +// Production start-up loads through LoadChunked and background loadChunk +// calls; both must queue NULL rows so a running server picks them up. +func TestRouteMask_ChunkedLoadPathsQueueNullRows(t *testing.T) { + for _, tc := range []struct { + name string + load func(*PacketStore) error + }{ + {"LoadChunked", func(s *PacketStore) error { return s.LoadChunked(1) }}, + {"loadChunk", func(s *PacketStore) error { + return s.loadChunk(time.Now().Add(-48*time.Hour), time.Now().Add(time.Hour)) + }}, + } { + t.Run(tc.name, func(t *testing.T) { + db := rmIndexedDB(t) + s := NewPacketStore(db, nil) + if err := tc.load(s); err != nil { + t.Fatal(err) + } + rmExec(t, db, `UPDATE transmissions SET route_mask = 6 WHERE id = 3`) + if st := s.routeMaskBackfillStatus(); st.Status == "complete" { + t.Fatalf("complete before the server read the mask: %+v", st) + } + s.RefreshBackfilledRouteMasks() + if v := rmSnapshot(s)["legacy"]; v != (rmView{0b0110, true}) { + t.Fatalf("legacy = %v, want 0110 known", v) + } + if st := s.routeMaskBackfillStatus(); st.Status != "complete" { + t.Fatalf("status = %+v, want complete", st) + } + }) + } +} + +// A poller tick that runs after the background loader scanned a chunk but +// before it merged the chunk into the store must not drop the NULL row: the +// status would then say complete while the row stays unknown. +func TestRouteMask_RefreshDuringBackgroundChunkKeepsTheRow(t *testing.T) { + db := rmIndexedDB(t) + s := NewPacketStore(db, nil) + s.loadChunkScannedHook = func() { + rmExec(t, db, `UPDATE transmissions SET route_mask = 6 WHERE id = 3`) + s.RefreshBackfilledRouteMasks() + } + if err := s.loadChunk(time.Now().Add(-48*time.Hour), time.Now().Add(time.Hour)); err != nil { + t.Fatal(err) + } + s.loadChunkScannedHook = nil + if v := rmSnapshot(s)["legacy"]; !v.Known { + if st := s.routeMaskBackfillStatus(); st.Status == "complete" { + t.Fatalf("status complete while legacy is unknown in memory: %+v", st) + } + } + s.RefreshBackfilledRouteMasks() + if v := rmSnapshot(s)["legacy"]; v != (rmView{0b0110, true}) { + t.Fatalf("legacy after the next tick = %v, want 0110 known", v) + } + if st := s.routeMaskBackfillStatus(); st.Status != "complete" { + t.Fatalf("status = %+v, want complete", st) + } +} + +// Without the route_mask column (only possible in tests; AssertReady +// requires it) nothing is queued and a refresh is a no-op. +func TestRouteMask_NoColumnQueuesNothing(t *testing.T) { + db := setupTestDB(t) + seedTestData(t, db) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + if n := s.routeMaskPendingLen(); n != 0 { + t.Fatalf("queued %d transmissions on a database without route_mask", n) + } + if n := s.RefreshBackfilledRouteMasks(); n != 0 { + t.Fatalf("refresh merged %d", n) + } +} diff --git a/cmd/server/route_mask_server_test.go b/cmd/server/route_mask_server_test.go new file mode 100644 index 000000000..720737809 --- /dev/null +++ b/cmd/server/route_mask_server_test.go @@ -0,0 +1,368 @@ +package main + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "reflect" + "testing" + "time" + "unsafe" + + "github.com/gorilla/mux" + "github.com/meshcore-analyzer/dbschema" +) + +// Issue #89: the server reads transmissions.route_mask (every raw route type +// observed for the content hash) in all load paths, classifies ADVERTs as +// flood / zero_hop / mixed from it, and reports the backfill status read-only. + +func TestStoreTxLayoutFitsRouteMaskInPadding(t *testing.T) { + if unsafe.Sizeof(uintptr(0)) != 8 { + t.Skip("layout budget is defined for 64-bit platforms") + } + if got := unsafe.Sizeof(StoreTx{}); got != 320 { + t.Fatalf("unsafe.Sizeof(StoreTx{}) = %d, want 320: route mask fields must use existing padding", got) + } +} + +func TestAdvertRouteClassFromMask(t *testing.T) { + rt := func(v int) *int { return &v } + cases := []struct { + name string + mask uint8 + known bool + route *int + want relayAirtimeAdvertRoute + }{ + {"route 0 only", 0b0001, true, rt(0), relayAirtimeAdvertFlood}, + {"routes 0 and 1", 0b0011, true, rt(1), relayAirtimeAdvertFlood}, + {"route 2 only", 0b0100, true, rt(2), relayAirtimeAdvertZeroHop}, + {"routes 2 and 3", 0b1100, true, rt(3), relayAirtimeAdvertZeroHop}, + {"flood and zero-hop", 0b1010, true, rt(3), relayAirtimeAdvertMixed}, + {"all four", 0b1111, true, rt(0), relayAirtimeAdvertMixed}, + {"mask wins over stored route", 0b0010, true, rt(3), relayAirtimeAdvertFlood}, + {"unknown mask falls back to flood route", 0, false, rt(1), relayAirtimeAdvertFlood}, + {"unknown mask falls back to zero-hop route", 0, false, rt(2), relayAirtimeAdvertZeroHop}, + {"unknown mask, NULL route", 0, false, nil, relayAirtimeAdvertUnknown}, + {"unknown mask, out-of-range route", 0, false, rt(99), relayAirtimeAdvertUnknown}, + {"known empty mask falls back to route", 0, true, rt(2), relayAirtimeAdvertZeroHop}, + {"known empty mask, invalid route", 0, true, rt(7), relayAirtimeAdvertUnknown}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + tx := &StoreTx{RouteType: tc.route, routeMask: tc.mask, routeMaskKnown: tc.known} + if got := advertRouteClass(tx); got != tc.want { + t.Fatalf("advertRouteClass = %v, want %v", got, tc.want) + } + }) + } +} + +func routeMaskServerDB(t *testing.T) *DB { + t.Helper() + db := setupTestDB(t) + if _, err := db.conn.Exec(`ALTER TABLE transmissions ADD COLUMN route_mask INTEGER`); err != nil { + t.Fatal(err) + } + db.hasRouteMaskFlag.forceTrue() + db.hasObsRawHexFlag.forceTrue() + for i, id := range []string{"obs-a", "obs-b"} { + if _, err := db.conn.Exec(`INSERT INTO observers (rowid, id, name, iata) VALUES (?, ?, ?, 'TST')`, i+1, id, id); err != nil { + t.Fatal(err) + } + } + return db +} + +func rmInsertTx(t *testing.T, db *DB, id int, hash string, routeType, mask interface{}, firstSeen string) { + t.Helper() + if _, err := db.conn.Exec(`INSERT INTO transmissions (id, raw_hex, hash, first_seen, route_type, payload_type, decoded_json, route_mask) + VALUES (?, '11020a0b', ?, ?, ?, 4, '{}', ?)`, id, hash, firstSeen, routeType, mask); err != nil { + t.Fatal(err) + } +} + +func rmInsertObs(t *testing.T, db *DB, id, txID, observer int, pathJSON, rawHex string, ts int64) { + t.Helper() + if _, err := db.conn.Exec(`INSERT INTO observations (id, transmission_id, observer_idx, path_json, timestamp, raw_hex) VALUES (?, ?, ?, ?, ?, ?)`, + id, txID, observer, pathJSON, ts, rawHex); err != nil { + t.Fatal(err) + } +} + +type rmView struct { + Mask uint8 + Known bool +} + +func rmSnapshot(s *PacketStore) map[string]rmView { + s.mu.RLock() + defer s.mu.RUnlock() + out := map[string]rmView{} + for _, tx := range s.packets { + out[tx.Hash] = rmView{tx.routeMask, tx.routeMaskKnown} + } + return out +} + +func rmSeed(t *testing.T, db *DB) { + t.Helper() + now := time.Now().UTC() + fs := now.Add(-time.Hour).Format(time.RFC3339) + ts := now.Add(-time.Hour).Unix() + rmInsertTx(t, db, 1, "mixed", 3, 0b1010, fs) + rmInsertObs(t, db, 1, 1, 1, `["A1","B2"]`, "1102a1b2", ts) + rmInsertObs(t, db, 2, 1, 2, `[]`, "130000000000", ts) + rmInsertTx(t, db, 2, "flood", 1, 0b0010, fs) + rmInsertObs(t, db, 3, 2, 1, `["A1"]`, "1101a1", ts) + rmInsertTx(t, db, 3, "legacy", 2, nil, fs) // not backfilled yet + rmInsertObs(t, db, 4, 3, 2, `[]`, "1200", ts) +} + +var rmWantSeed = map[string]rmView{ + "mixed": {0b1010, true}, + "flood": {0b0010, true}, + "legacy": {0, false}, +} + +func TestRouteMask_ColdAndChunkedLoadKeepMask(t *testing.T) { + db := routeMaskServerDB(t) + rmSeed(t, db) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + if got := rmSnapshot(s); !reflect.DeepEqual(got, rmWantSeed) { + t.Fatalf("Load: %v, want %v", got, rmWantSeed) + } + c := NewPacketStore(db, nil) + if err := c.LoadChunked(1); err != nil { + t.Fatal(err) + } + if got := rmSnapshot(c); !reflect.DeepEqual(got, rmWantSeed) { + t.Fatalf("LoadChunked: %v, want %v", got, rmWantSeed) + } + l := NewPacketStore(db, nil) + if err := l.loadChunk(time.Now().Add(-48*time.Hour), time.Now().Add(time.Hour)); err != nil { + t.Fatal(err) + } + if got := rmSnapshot(l); !reflect.DeepEqual(got, rmWantSeed) { + t.Fatalf("loadChunk: %v, want %v", got, rmWantSeed) + } +} + +// Live ingest must end with the same masks a cold load of the same database +// produces: new transmissions carry their mask, and a new observation of an +// existing transmission brings its route bit. The ingestor ORs the bit into +// transmissions.route_mask before it writes the observation row, so a poll +// that sees the observation also sees the bit. +func TestRouteMask_IncrementalIngestMatchesColdLoad(t *testing.T) { + db := routeMaskServerDB(t) + rmSeed(t, db) + s := NewPacketStore(db, nil) + if err := s.Load(); err != nil { + t.Fatal(err) + } + ts := time.Now().UTC().Add(-30 * time.Minute) + // New transmission, then a zero-hop observation of the known flood tx. + rmInsertTx(t, db, 4, "new-zero-hop", 3, 0b1000, ts.Format(time.RFC3339)) + rmInsertObs(t, db, 5, 4, 2, `[]`, "130000000000", ts.Unix()) + s.IngestNewFromDB(3, 100) + if _, err := db.conn.Exec(`UPDATE transmissions SET route_mask = route_mask | 8 WHERE id = 2`); err != nil { + t.Fatal(err) + } + rmInsertObs(t, db, 6, 2, 2, `[]`, "130000000000", ts.Unix()) + s.IngestNewObservations(5, 100) + got := rmSnapshot(s) + if got["flood"] != (rmView{0b1010, true}) || got["new-zero-hop"] != (rmView{0b1000, true}) { + t.Fatalf("after incremental ingest: %v", got) + } + cold := NewPacketStore(db, nil) + if err := cold.Load(); err != nil { + t.Fatal(err) + } + if want := rmSnapshot(cold); !reflect.DeepEqual(got, want) { + t.Fatalf("incremental %v != cold load %v", got, want) + } + // A legacy (NULL) row stays unknown until the backfill fills it, even + // when a new observation arrives. + rmInsertObs(t, db, 7, 3, 1, `["C3"]`, "1101c3", ts.Unix()) + s.IngestNewObservations(6, 100) + if v := rmSnapshot(s)["legacy"]; v.Known { + t.Fatalf("legacy row became known from a single observation: %v", v) + } + if _, err := db.conn.Exec(`UPDATE transmissions SET route_mask = 6 WHERE id = 3`); err != nil { + t.Fatal(err) + } + rmInsertObs(t, db, 8, 3, 2, `["D4"]`, "1101d4", ts.Unix()) + s.IngestNewObservations(7, 100) + if v := rmSnapshot(s)["legacy"]; v != (rmView{0b0110, true}) { + t.Fatalf("backfilled legacy row after a new observation = %v, want 0110 known", v) + } +} + +func TestRelayAirtimeShare_MixedAdvertCountsOnceOnMixedRow(t *testing.T) { + mk := func(pt int, route interface{}, mask uint8, known bool, relays int, hash string) relayAirtimeSplitFixture { + f := relayAirtimeSplitFixture{payloadType: pt, bytes: 100, relays: relays, hash: hash} + if r, ok := route.(int); ok { + f.route = intPtr(r) + } + return f + } + fixtures := []relayAirtimeSplitFixture{ + mk(PayloadADVERT, 3, 0b1010, true, 2, "mixed"), + mk(PayloadADVERT, 1, 0b0010, true, 3, "flood"), + mk(PayloadADVERT, 2, 0b0100, true, 0, "zero"), + mk(PayloadADVERT, 2, 0, false, 0, "legacy-null-route2"), + mk(PayloadADVERT, 99, 0, false, 1, "legacy-unknown"), + mk(PayloadACK, 0, 0b1010, true, 1, "ack-mixed"), + } + masks := map[string][2]interface{}{ + "mixed": {uint8(0b1010), true}, "flood": {uint8(0b0010), true}, "zero": {uint8(0b0100), true}, + "legacy-null-route2": {uint8(0), false}, "legacy-unknown": {uint8(0), false}, "ack-mixed": {uint8(0b1010), true}, + } + store := relayAirtimeSplitStore(fixtures) + for _, tx := range store.packets { + m := masks[tx.Hash] + tx.routeMask, tx.routeMaskKnown = m[0].(uint8), m[1].(bool) + } + res := store.computeRelayAirtimeShare(TimeWindow{}) + rows := res["rows"].([]map[string]interface{}) + type row struct { + label, class string + count int + score int64 + } + got := map[string]row{} + for _, r := range rows { + class := "null" + if p, ok := r["route_class"].(*string); ok && p != nil { + class = *p + } + key := r["payload_type"].(string) + if _, dup := got[key]; dup { + t.Fatalf("duplicate row %s", key) + } + got[key] = row{key, class, r["count"].(int), r["score"].(int64)} + } + want := map[string]row{ + "ADVERT (mixed)": {"ADVERT (mixed)", "mixed", 1, relayAirtimeSplitScore(100, 2)}, + "ADVERT (flood)": {"ADVERT (flood)", "flood", 1, relayAirtimeSplitScore(100, 3)}, + "ADVERT (zero-hop)": {"ADVERT (zero-hop)", "zero_hop", 2, 0}, + "ADVERT": {"ADVERT", "legacy", 1, relayAirtimeSplitScore(100, 1)}, + "ACK": {"ACK", "null", 1, relayAirtimeSplitScore(100, 1)}, + } + if !reflect.DeepEqual(got, want) { + t.Fatalf("rows:\n got %v\n want %v", got, want) + } + if res["total_count"].(int) != 6 { + t.Fatalf("total_count = %v, want 6 (a mixed hash counts once)", res["total_count"]) + } +} + +func rmStatus(t *testing.T, db *DB) RouteMaskBackfillStatus { + t.Helper() + return db.computeRouteMaskBackfillStatus() +} + +func TestRouteMaskBackfillStatus_NeverReportsFalseComplete(t *testing.T) { + db := routeMaskServerDB(t) + rmSeed(t, db) // one NULL row + if st := rmStatus(t, db); st.Status != "pending" || st.Remaining != nil { + t.Fatalf("without the pending index: %+v, want pending with unknown remaining", st) + } + if _, err := db.conn.Exec(dbschema.CreateRouteMaskPendingIndexSQL); err != nil { + t.Fatal(err) + } + if st := rmStatus(t, db); st.Status != "pending" || st.Remaining == nil || *st.Remaining != 1 { + t.Fatalf("index present, backfill not started: %+v, want pending remaining=1", st) + } + db.conn.Exec(`CREATE TABLE _async_migrations (name TEXT PRIMARY KEY, status TEXT, started_at TEXT, ended_at TEXT, error TEXT)`) + db.conn.Exec(`INSERT INTO _async_migrations (name, status) VALUES (?, 'pending_async')`, dbschema.RouteMaskBackfillMigration) + if st := rmStatus(t, db); st.Status != "backfilling" || st.Remaining == nil || *st.Remaining != 1 { + t.Fatalf("backfill running: %+v, want backfilling remaining=1", st) + } + // Marked done while a NULL row still exists (e.g. an older ingestor wrote + // it after completion): must not claim complete. + db.conn.Exec(`UPDATE _async_migrations SET status = 'done'`) + if st := rmStatus(t, db); st.Status == "complete" { + t.Fatalf("reported complete with a NULL row left: %+v", st) + } + db.conn.Exec(`UPDATE transmissions SET route_mask = 4 WHERE route_mask IS NULL`) + if st := rmStatus(t, db); st.Status != "complete" || st.Remaining == nil || *st.Remaining != 0 { + t.Fatalf("no NULL rows: %+v, want complete remaining=0", st) + } +} + +func TestRouteMaskBackfillStatus_OldSchemaIsPending(t *testing.T) { + db := setupTestDB(t) // no route_mask column + if st := db.computeRouteMaskBackfillStatus(); st.Status != "pending" || st.Remaining != nil { + t.Fatalf("old schema: %+v, want pending with unknown remaining", st) + } +} + +func TestHealthz_ReportsRouteMaskBackfill(t *testing.T) { + db := routeMaskServerDB(t) + rmSeed(t, db) + db.conn.Exec(dbschema.CreateRouteMaskPendingIndexSQL) + srv := NewServer(db, &Config{Port: 3000}, NewHub()) + srv.store = NewPacketStore(db, nil) + router := mux.NewRouter() + srv.RegisterRoutes(router) + prev := readiness.Load() + readiness.Store(1) + defer readiness.Store(prev) + w := httptest.NewRecorder() + router.ServeHTTP(w, httptest.NewRequest("GET", "/api/healthz", nil)) + if w.Code != http.StatusOK { + t.Fatalf("healthz status %d: %s", w.Code, w.Body.String()) + } + var body struct { + RouteMask *RouteMaskBackfillStatus `json:"route_mask_backfill"` + } + if err := json.Unmarshal(w.Body.Bytes(), &body); err != nil { + t.Fatal(err) + } + if body.RouteMask == nil || body.RouteMask.Status != "pending" || body.RouteMask.Remaining == nil || *body.RouteMask.Remaining != 1 { + t.Fatalf("healthz route_mask_backfill = %+v, want pending remaining=1", body.RouteMask) + } +} + +// Payload Type Mix stays one combined ADVERT entry even when the masks mark +// transmissions as flood, zero-hop and mixed. +func TestPayloadTypeMix_AdvertStaysCombinedWithRouteMasks(t *testing.T) { + store := relayAirtimeSplitStore(mixedAdvertFixtures()) + masks := []uint8{0b1010, 0b0010, 0b1000, 0b0001} + i := 0 + for _, tx := range store.packets { + if tx.PayloadType != nil && *tx.PayloadType == PayloadADVERT { + tx.routeMask, tx.routeMaskKnown = masks[i%len(masks)], true + i++ + } + } + encoded, err := json.Marshal(store.computeAnalyticsRF("", "", TimeWindow{})["payloadTypes"]) + if err != nil { + t.Fatal(err) + } + var entries []struct { + Type int `json:"type"` + Name string `json:"name"` + Count int `json:"count"` + } + if err := json.Unmarshal(encoded, &entries); err != nil { + t.Fatal(err) + } + var adverts int + for _, e := range entries { + if e.Type == PayloadADVERT { + adverts++ + if e.Name != "ADVERT" || e.Count != 6 { + t.Errorf("ADVERT entry = %+v, want name ADVERT count 6", e) + } + } + } + if adverts != 1 { + t.Fatalf("Payload Type Mix has %d ADVERT entries, want exactly 1", adverts) + } +} diff --git a/cmd/server/schema_wait.go b/cmd/server/schema_wait.go new file mode 100644 index 000000000..41a4b0354 --- /dev/null +++ b/cmd/server/schema_wait.go @@ -0,0 +1,150 @@ +package main + +import ( + "context" + "database/sql" + "errors" + "fmt" + "strings" + "time" + + "github.com/meshcore-analyzer/dbschema" +) + +// Issue #89 / PR #93: the server and the ingestor start together (one +// supervisord), and the server requires route_mask_changes, which the +// ingestor creates during its start-up Apply. Exiting on a missing table made +// supervisord restart the server with growing back-off until it gave up +// (FATAL after 64.6 s in the staging gate) and left it stopped for good. The +// server now waits in-process, bounded and cancellable, but only while +// dbschema reports that migration as in progress or SQLite reports +// BUSY/LOCKED; every other schema defect still fails at once. + +// schemaWaitPolicy is the internal start-up retry policy: Initial is the +// first wait, each later wait grows by Factor up to Max, and the whole wait +// ends Deadline after the first check. A status line is logged at most once +// per LogEvery. +type schemaWaitPolicy struct { + Initial, Max time.Duration + Factor float64 + Deadline time.Duration + LogEvery time.Duration +} + +var defaultSchemaWaitPolicy = schemaWaitPolicy{ + Initial: 250 * time.Millisecond, + Max: 2 * time.Second, + Factor: 1.5, + Deadline: 120 * time.Second, + LogEvery: 10 * time.Second, +} + +// schemaWaitClock lets tests replace real time. +type schemaWaitClock interface { + Now() time.Time + NewTimer(d time.Duration) (c <-chan time.Time, stop func() bool) +} + +type realClock struct{} + +func (realClock) Now() time.Time { return time.Now() } + +func (realClock) NewTimer(d time.Duration) (<-chan time.Time, func() bool) { + t := time.NewTimer(d) + return t.C, t.Stop +} + +// SchemaWaitTimeoutError is returned when the schema is still not ready at +// the deadline. It wraps the last check error. +type SchemaWaitTimeoutError struct { + Elapsed time.Duration + Attempts int + Last error +} + +func (e *SchemaWaitTimeoutError) Error() string { + return fmt.Sprintf("schema still not ready after %v (%d attempts): %v", e.Elapsed, e.Attempts, e.Last) +} + +func (e *SchemaWaitTimeoutError) Unwrap() error { return e.Last } + +// waitForSchema calls check until it succeeds, retrying only transient +// *dbschema.NotReadyError results with back-off. It returns the number of +// checks and nil on success, the check error at once when it is permanent, +// ctx.Err() when ctx is cancelled (never reported as a timeout), and a +// *SchemaWaitTimeoutError once p.Deadline has passed since the first check. +func waitForSchema(ctx context.Context, check func() error, p schemaWaitPolicy, clk schemaWaitClock, logf func(string, ...interface{})) (int, error) { + start := clk.Now() + delay := p.Initial + var lastLog time.Time + for attempts := 1; ; attempts++ { + if err := ctx.Err(); err != nil { + return attempts - 1, err + } + err := check() + if ctxErr := ctx.Err(); ctxErr != nil { + // A shutdown that arrived during the check wins over its result. + return attempts, ctxErr + } + now := clk.Now() + elapsed := now.Sub(start) + if err == nil { + if attempts > 1 { + logf("[db] schema ready after %v (%d attempts)", elapsed.Round(time.Millisecond), attempts) + } + return attempts, nil + } + var nr *dbschema.NotReadyError + if !errors.As(err, &nr) || !nr.Transient() { + return attempts, err + } + if elapsed >= p.Deadline { + return attempts, &SchemaWaitTimeoutError{Elapsed: elapsed, Attempts: attempts, Last: err} + } + switch { + case attempts == 1: + logf("[db] waiting for the ingestor's start-up migrations (missing: %s); retrying for up to %v", strings.Join(nr.Items(), ", "), p.Deadline) + lastLog = now + case now.Sub(lastLog) >= p.LogEvery: + logf("[db] still waiting for the schema (missing: %s): %d attempts, %v elapsed", strings.Join(nr.Items(), ", "), attempts, elapsed.Round(time.Second)) + lastLog = now + } + wait := delay + if remaining := p.Deadline - elapsed; wait > remaining { + wait = remaining + } + c, stop := clk.NewTimer(wait) + select { + case <-ctx.Done(): + stop() + return attempts, ctx.Err() + case <-c: + } + if next := time.Duration(float64(delay) * p.Factor); next < p.Max { + delay = next + } else { + delay = p.Max + } + } +} + +// waitForServerSchema waits until dbschema.AssertReady accepts the database. +func waitForServerSchema(ctx context.Context, db *sql.DB, p schemaWaitPolicy, clk schemaWaitClock, logf func(string, ...interface{})) (int, error) { + return waitForSchema(ctx, func() error { return dbschema.AssertReady(db) }, p, clk, logf) +} + +// waitForDBSchema is the server's start-up gate: it waits for the schema and +// then re-reads the optional-column flags OpenDB detected before the wait, +// because on a pre-#93 database the route_mask column only appears while +// the server waits (detectSchema only ever sets flags). +func waitForDBSchema(ctx context.Context, db *DB, p schemaWaitPolicy, clk schemaWaitClock, logf func(string, ...interface{})) (int, error) { + return waitForDBSchemaWith(ctx, db, func() error { return dbschema.AssertReady(db.conn) }, p, clk, logf) +} + +func waitForDBSchemaWith(ctx context.Context, db *DB, check func() error, p schemaWaitPolicy, clk schemaWaitClock, logf func(string, ...interface{})) (int, error) { + attempts, err := waitForSchema(ctx, check, p, clk, logf) + if err == nil { + db.detectSchema() + } + return attempts, err +} diff --git a/cmd/server/schema_wait_process_test.go b/cmd/server/schema_wait_process_test.go new file mode 100644 index 000000000..13a57d2a1 --- /dev/null +++ b/cmd/server/schema_wait_process_test.go @@ -0,0 +1,313 @@ +package main + +import ( + "bytes" + "errors" + "fmt" + "net" + "net/http" + "os" + "os/exec" + "path/filepath" + "strings" + "sync" + "syscall" + "testing" + "time" + + "github.com/meshcore-analyzer/dbschema" +) + +// Process contract of the start-up schema wait (PR #93 staging gate): the +// real server main() runs in a child process against a real SQLite file. + +const schemaWaitHelperEnv = "CORESCOPE_SCHEMA_WAIT_HELPER" + +// TestSchemaWaitServerProcess is not a test on its own: the process tests +// below re-run the test binary with schemaWaitHelperEnv set, and then it runs +// the real main() with a short wait policy. +func TestSchemaWaitServerProcess(t *testing.T) { + if os.Getenv(schemaWaitHelperEnv) != "1" { + t.Skip("helper process for the schema-wait process tests") + } + deadline, err := time.ParseDuration(os.Getenv("CORESCOPE_SCHEMA_WAIT_DEADLINE")) + if err != nil { + t.Fatal(err) + } + defaultSchemaWaitPolicy = schemaWaitPolicy{Initial: 20 * time.Millisecond, Max: 200 * time.Millisecond, Factor: 1.5, Deadline: deadline, LogEvery: 500 * time.Millisecond} + os.Args = []string{"corescope-server", + "-config-dir", os.Getenv("CORESCOPE_SCHEMA_WAIT_CFG"), + "-db", os.Getenv("CORESCOPE_SCHEMA_WAIT_DB"), + "-public", os.Getenv("CORESCOPE_SCHEMA_WAIT_PUBLIC"), + "-port", os.Getenv("CORESCOPE_SCHEMA_WAIT_PORT")} + main() +} + +// syncBuffer collects the child's output and signals every write, so tests +// wait for log lines instead of polling. +type syncBuffer struct { + mu sync.Mutex + b bytes.Buffer + written chan struct{} +} + +func newSyncBuffer() *syncBuffer { return &syncBuffer{written: make(chan struct{}, 1)} } + +func (s *syncBuffer) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + n, err := s.b.Write(p) + select { + case s.written <- struct{}{}: + default: + } + return n, err +} + +func (s *syncBuffer) String() string { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.String() +} + +type serverProc struct { + cmd *exec.Cmd + out *syncBuffer + port int + done chan struct{} + err error +} + +func startServerProc(t *testing.T, dbPath string, deadline time.Duration) *serverProc { + t.Helper() + l, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + port := l.Addr().(*net.TCPAddr).Port + l.Close() + pub := t.TempDir() + os.WriteFile(filepath.Join(pub, "index.html"), []byte("__BUST__"), 0o644) + p := &serverProc{out: newSyncBuffer(), port: port, done: make(chan struct{})} + p.cmd = exec.Command(os.Args[0], "-test.run=^TestSchemaWaitServerProcess$", "-test.count=1") + p.cmd.Env = append(os.Environ(), + schemaWaitHelperEnv+"=1", + "CORESCOPE_SCHEMA_WAIT_DEADLINE="+deadline.String(), + "CORESCOPE_SCHEMA_WAIT_CFG="+t.TempDir(), + "CORESCOPE_SCHEMA_WAIT_DB="+dbPath, + "CORESCOPE_SCHEMA_WAIT_PUBLIC="+pub, + fmt.Sprintf("CORESCOPE_SCHEMA_WAIT_PORT=%d", port)) + p.cmd.Stdout, p.cmd.Stderr = p.out, p.out + if err := p.cmd.Start(); err != nil { + t.Fatal(err) + } + go func() { p.err = p.cmd.Wait(); close(p.done) }() + t.Cleanup(func() { + select { + case <-p.done: + default: + p.cmd.Process.Kill() + <-p.done + } + }) + return p +} + +func (p *serverProc) waitLog(t *testing.T, substr string, within time.Duration) { + t.Helper() + timeout := time.NewTimer(within) + defer timeout.Stop() + for !strings.Contains(p.out.String(), substr) { + select { + case <-p.out.written: + case <-p.done: + if !strings.Contains(p.out.String(), substr) { + t.Fatalf("server exited (%v) before logging %q:\n%s", p.err, substr, p.out.String()) + } + case <-timeout.C: + t.Fatalf("no %q within %v:\n%s", substr, within, p.out.String()) + } + } +} + +// waitReady waits for the server's readiness log line, then for its HTTP +// listener to answer healthz 200 (the readiness line can precede the bind, +// so this one step polls, on a ticker, bounded). +func (p *serverProc) waitReady(t *testing.T) { + t.Helper() + p.waitLog(t, "readiness: ready=true", 60*time.Second) + tick := time.NewTicker(50 * time.Millisecond) + defer tick.Stop() + timeout := time.NewTimer(20 * time.Second) + defer timeout.Stop() + for { + if code, err := p.healthz(); err == nil && code == http.StatusOK { + return + } + select { + case <-tick.C: + case <-p.done: + t.Fatalf("server exited before answering healthz:\n%s", p.out.String()) + case <-timeout.C: + t.Fatalf("healthz not 200 within 20 s of readiness:\n%s", p.out.String()) + } + } +} + +// notListening asserts the server is alive and its port refuses connections. +func (p *serverProc) notListening(t *testing.T) { + t.Helper() + select { + case <-p.done: + t.Fatalf("server exited while waiting:\n%s", p.out.String()) + default: + } + if code, err := p.healthz(); err == nil { + t.Fatalf("healthz answered %d while the schema is missing", code) + } +} + +func (p *serverProc) healthz() (int, error) { + c := http.Client{Timeout: 2 * time.Second} + resp, err := c.Get(fmt.Sprintf("http://127.0.0.1:%d/api/healthz", p.port)) + if err != nil { + return 0, err + } + resp.Body.Close() + return resp.StatusCode, nil +} + +func (p *serverProc) waitExit(t *testing.T, within time.Duration) (int, time.Duration) { + t.Helper() + t0 := time.Now() + select { + case <-p.done: + case <-time.After(within): + t.Fatalf("server still running %v later:\n%s", within, p.out.String()) + } + code := 0 + var exitErr *exec.ExitError + if errors.As(p.err, &exitErr) { + code = exitErr.ExitCode() + } + return code, time.Since(t0) +} + +func fullSchemaDB(t *testing.T) string { + t.Helper() + path, rw := fixtureSchemaDB(t) + if err := dbschema.Apply(rw, func(string, ...interface{}) {}); err != nil { + t.Fatal(err) + } + return path +} + +func TestServerProcess_WaitsForTheSchemaThenStartsOnce(t *testing.T) { + path, rw := fixtureSchemaDB(t) + p := startServerProc(t, path, time.Minute) + p.waitLog(t, "waiting for the ingestor", 20*time.Second) + // Waiting: alive, not listening, so readiness is red, at the first + // attempt and still at the periodic status line. + p.notListening(t) + p.waitLog(t, "still waiting for the schema", 10*time.Second) + p.notListening(t) + if err := dbschema.Apply(rw, func(string, ...interface{}) {}); err != nil { // the ingestor finishes + t.Fatal(err) + } + p.waitLog(t, "schema ready after", 10*time.Second) + p.waitReady(t) + out := p.out.String() + for substr, want := range map[string]int{ + "waiting for the ingestor": 1, + "schema ready after": 1, + "listening on": 1, + "[db] transmissions=": 1, + "schema still not ready": 0, + } { + if got := strings.Count(out, substr); got != want { + t.Errorf("%q logged %d times, want %d", substr, got, want) + } + } + p.cmd.Process.Signal(syscall.SIGTERM) + if code, _ := p.waitExit(t, 30*time.Second); code != 0 { + t.Fatalf("exit code %d after SIGTERM:\n%s", code, p.out.String()) + } +} + +// A pre-#93 database: the route_mask column and the change log are both +// missing until the ingestor migrates; the server waits and then starts. +func TestServerProcess_PreRouteMaskDatabase(t *testing.T) { + path, rw := fixtureSchemaDB(t) + for _, q := range []string{`ALTER TABLE transmissions DROP COLUMN route_mask`, `DELETE FROM _migrations WHERE name = 'transmissions_route_mask_v1'`} { + if _, err := rw.Exec(q); err != nil { + t.Fatal(err) + } + } + p := startServerProc(t, path, time.Minute) + p.waitLog(t, "waiting for the ingestor", 20*time.Second) + if err := dbschema.Apply(rw, func(string, ...interface{}) {}); err != nil { + t.Fatal(err) + } + p.waitLog(t, "schema ready after", 10*time.Second) + p.waitReady(t) + p.cmd.Process.Signal(syscall.SIGTERM) + if code, _ := p.waitExit(t, 30*time.Second); code != 0 { + t.Fatalf("exit code %d after SIGTERM:\n%s", code, p.out.String()) + } +} + +func TestServerProcess_SIGTERMWhileWaitingExitsCleanly(t *testing.T) { + path, _ := fixtureSchemaDB(t) + p := startServerProc(t, path, time.Minute) + p.waitLog(t, "waiting for the ingestor", 20*time.Second) + p.cmd.Process.Signal(syscall.SIGTERM) + code, took := p.waitExit(t, 5*time.Second) + out := p.out.String() + if code != 0 { + t.Fatalf("exit code %d after SIGTERM while waiting:\n%s", code, out) + } + if took > 2*time.Second { + t.Fatalf("SIGTERM while waiting took %v", took) + } + if strings.Contains(out, "schema still not ready") || strings.Contains(out, "schema not ready") || strings.Contains(out, "listening on") { + t.Fatalf("cancellation logged a schema failure or started the server:\n%s", out) + } +} + +func TestServerProcess_DeadlineExitsNonZero(t *testing.T) { + path, _ := fixtureSchemaDB(t) + p := startServerProc(t, path, time.Second) + code, _ := p.waitExit(t, 30*time.Second) + out := p.out.String() + if code == 0 { + t.Fatalf("exit code 0 after the deadline:\n%s", out) + } + if strings.Count(out, "schema still not ready after") != 1 || strings.Contains(out, "listening on") { + t.Fatalf("want exactly one deadline error and no start:\n%s", out) + } +} + +func TestServerProcess_PermanentSchemaErrorExitsAtOnce(t *testing.T) { + path, rw := fixtureSchemaDB(t) + if _, err := rw.Exec(dbschema.CreateRouteMaskChangesTableSQL); err != nil { // malformed: no index + t.Fatal(err) + } + p := startServerProc(t, path, time.Minute) + code, _ := p.waitExit(t, 30*time.Second) + out := p.out.String() + if code == 0 || strings.Contains(out, "waiting for the ingestor") || !strings.Contains(out, "index:"+dbschema.RouteMaskChangesTxIndex) { + t.Fatalf("malformed change log: exit %d, want an immediate failure naming the index:\n%s", code, out) + } +} + +func TestServerProcess_NormalStartDoesNotWait(t *testing.T) { + p := startServerProc(t, fullSchemaDB(t), time.Minute) + p.waitReady(t) + if strings.Contains(p.out.String(), "waiting for the ingestor") { + t.Fatalf("a migrated database made the server wait:\n%s", p.out.String()) + } + p.cmd.Process.Signal(syscall.SIGTERM) + if code, _ := p.waitExit(t, 30*time.Second); code != 0 { + t.Fatalf("exit code %d after SIGTERM:\n%s", code, p.out.String()) + } +} diff --git a/cmd/server/schema_wait_test.go b/cmd/server/schema_wait_test.go new file mode 100644 index 000000000..8b6829cef --- /dev/null +++ b/cmd/server/schema_wait_test.go @@ -0,0 +1,612 @@ +package main + +import ( + "context" + "database/sql" + "errors" + "fmt" + "io" + "os" + "path/filepath" + "runtime" + "strings" + "sync" + "testing" + "time" + + "github.com/meshcore-analyzer/dbschema" +) + +// PR #93 staging gate: with the table missing, the old server exited on +// every start attempt; supervisord gave up after 64.6 s and the server stayed +// FATAL although the ingestor created the table 4 s later. The server now +// waits in-process, bounded and cancellable, and only for the ingestor's +// in-progress migration or SQLite BUSY/LOCKED. + +// fakeClock advances only when waitForSchema waits on it. +type fakeClock struct { + now time.Time + waits []time.Duration + block func(n int) bool // return true to make wait n never fire +} + +func (c *fakeClock) Now() time.Time { return c.now } + +func (c *fakeClock) NewTimer(d time.Duration) (<-chan time.Time, func() bool) { + c.waits = append(c.waits, d) + ch := make(chan time.Time, 1) + if c.block != nil && c.block(len(c.waits)) { + return ch, func() bool { return true } + } + c.now = c.now.Add(d) + ch <- c.now + return ch, func() bool { return false } +} + +type busyErr int + +func (b busyErr) Error() string { return fmt.Sprintf("sqlite code %d", int(b)) } +func (b busyErr) Code() int { return int(b) } + +var ( + missingTable = &dbschema.NotReadyError{Missing: []string{"table:route_mask_changes"}} + busyProbe = &dbschema.NotReadyError{Probes: []dbschema.ProbeFailure{{Item: "table:route_mask_changes", Err: busyErr(5)}}} + permanent = &dbschema.NotReadyError{Missing: []string{"observations.raw_hex"}} +) + +type logSink struct { + mu sync.Mutex + lines []string +} + +func (l *logSink) logf(format string, args ...interface{}) { + l.mu.Lock() + defer l.mu.Unlock() + l.lines = append(l.lines, fmt.Sprintf(format, args...)) +} + +// checks returns a check that yields errs in order, then nil forever. It +// fails the test instead of looping without bound. +func checks(t *testing.T, errs ...error) (func() error, *int) { + n := 0 + return func() error { + n++ + if n > 10000 { + t.Fatalf("check called %d times: the wait is unbounded", n) + } + if n <= len(errs) { + return errs[n-1] + } + return nil + }, &n +} + +func always(t *testing.T, err error) (func() error, *int) { + n := 0 + return func() error { + n++ + if n > 10000 { + t.Fatalf("check called %d times: the wait is unbounded", n) + } + return err + }, &n +} + +func TestWaitForSchema_TableAppearsAfterSeveralAttempts(t *testing.T) { + clk := &fakeClock{now: time.Unix(0, 0)} + check, n := checks(t, missingTable, missingTable, missingTable, missingTable) + var log logSink + attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf) + if err != nil || attempts != 5 || *n != 5 { + t.Fatalf("waitForSchema = (%d, %v) after %d checks, want success on attempt 5", attempts, err, *n) + } + want := []time.Duration{250 * time.Millisecond, 375 * time.Millisecond, 562500 * time.Microsecond, 843750 * time.Microsecond} + if fmt.Sprint(clk.waits) != fmt.Sprint(want) { + t.Fatalf("waits = %v, want %v", clk.waits, want) + } +} + +func TestWaitForSchema_BusyThenSuccess(t *testing.T) { + clk := &fakeClock{now: time.Unix(0, 0)} + check, _ := checks(t, busyProbe, busyProbe) + var log logSink + if attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf); err != nil || attempts != 3 { + t.Fatalf("waitForSchema = (%d, %v), want success on attempt 3", attempts, err) + } +} + +// Backoff grows from 250 ms by 1.5x to a 2 s cap, never waits past the +// deadline, and the deadline is measured from the first attempt. +func TestWaitForSchema_BackoffAndDeadline(t *testing.T) { + start := time.Unix(0, 0) + clk := &fakeClock{now: start} + check, n := always(t, missingTable) + var log logSink + attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf) + var timeout *SchemaWaitTimeoutError + if !errors.As(err, &timeout) { + t.Fatalf("waitForSchema = (%d, %v), want *SchemaWaitTimeoutError", attempts, err) + } + if !errors.Is(err, missingTable) { + t.Fatalf("timeout error does not wrap the last check error: %v", err) + } + elapsed := clk.now.Sub(start) + if elapsed != defaultSchemaWaitPolicy.Deadline || timeout.Elapsed != elapsed { + t.Fatalf("gave up after %v (reported %v), want exactly the %v deadline", elapsed, timeout.Elapsed, defaultSchemaWaitPolicy.Deadline) + } + if defaultSchemaWaitPolicy.Deadline < 120*time.Second { + t.Fatalf("deadline %v, want at least 120 s", defaultSchemaWaitPolicy.Deadline) + } + var sum time.Duration + for i, w := range clk.waits { + if w <= 0 || w > 2*time.Second { + t.Fatalf("wait %d = %v, want 0 < wait <= 2s", i, w) + } + if i > 0 && w < clk.waits[i-1] && i != len(clk.waits)-1 { + t.Fatalf("wait %d = %v shrank from %v before the deadline", i, w, clk.waits[i-1]) + } + sum += w + } + if clk.waits[0] != 250*time.Millisecond || clk.waits[6] != 2*time.Second { + t.Fatalf("waits start %v, 7th %v; want 250ms growing to the 2s cap", clk.waits[0], clk.waits[6]) + } + if *n != attempts || attempts != len(clk.waits)+1 { + t.Fatalf("attempts %d, checks %d, waits %d: every wait must be followed by exactly one check", attempts, *n, len(clk.waits)) + } +} + +func TestWaitForSchema_SuccessJustBeforeTheDeadline(t *testing.T) { + clk := &fakeClock{now: time.Unix(0, 0)} + n := 0 + check := func() error { + n++ + if clk.now.Sub(time.Unix(0, 0)) < defaultSchemaWaitPolicy.Deadline-3*time.Second { + return missingTable + } + return nil + } + var log logSink + if _, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf); err != nil { + t.Fatalf("schema ready %v before the deadline: %v", 3*time.Second, err) + } + if n < 60 { + t.Fatalf("only %d checks over ~117 s", n) + } +} + +func TestWaitForSchema_CancellationIsNotATimeout(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + clk := &fakeClock{now: time.Unix(0, 0), block: func(n int) bool { + if n == 3 { + cancel() + return true + } + return false + }} + check, n := always(t, missingTable) + var log logSink + _, err := waitForSchema(ctx, check, defaultSchemaWaitPolicy, clk, log.logf) + if !errors.Is(err, context.Canceled) { + t.Fatalf("waitForSchema after cancellation = %v, want context.Canceled", err) + } + var timeout *SchemaWaitTimeoutError + if errors.As(err, &timeout) { + t.Fatal("cancellation reported as a timeout") + } + if *n != 3 { + t.Fatalf("checks after cancellation: %d, want 3", *n) + } + for _, l := range log.lines { + if strings.Contains(strings.ToLower(l), "timed out") || strings.Contains(strings.ToLower(l), "fatal") { + t.Fatalf("cancellation logged a failure: %q", l) + } + } +} + +// A shutdown signal that lands while the last check runs is still a +// shutdown: not a start (the check succeeded) and not a timeout (the check +// was the last before the deadline). +func TestWaitForSchema_CancellationDuringTheLastCheck(t *testing.T) { + for _, tc := range []struct { + name string + start time.Duration // clock offset of the cancelled check + err error // what that check returns + }{ + {"during a successful check", 0, nil}, + {"during the check at the deadline", defaultSchemaWaitPolicy.Deadline, missingTable}, + } { + t.Run(tc.name, func(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + clk := &fakeClock{now: time.Unix(0, 0)} + start := clk.now + check := func() error { + if clk.now.Sub(start) >= tc.start { + cancel() + return tc.err + } + return missingTable + } + var log logSink + _, err := waitForSchema(ctx, check, defaultSchemaWaitPolicy, clk, log.logf) + if !errors.Is(err, context.Canceled) { + t.Fatalf("waitForSchema = %v, want context.Canceled", err) + } + }) + } +} + +func TestWaitForSchema_PermanentErrorsFailAtOnce(t *testing.T) { + for _, tc := range []struct { + name string + err error + }{ + {"another missing column", permanent}, + {"malformed change log", &dbschema.NotReadyError{Missing: []string{"index:idx_route_mask_changes_tx"}}}, + {"I/O error while probing", &dbschema.NotReadyError{Probes: []dbschema.ProbeFailure{{Item: "observers.iata", Err: busyErr(10)}}}}, + {"read-only / permission", &dbschema.NotReadyError{Probes: []dbschema.ProbeFailure{{Item: "observers.iata", Err: busyErr(8)}}}}, + {"marker recorded but table gone", &dbschema.NotReadyError{Missing: []string{"table:route_mask_changes (recorded in _migrations)"}}}, + {"not a NotReadyError", errors.New("sql: database is closed")}, + } { + t.Run(tc.name, func(t *testing.T) { + clk := &fakeClock{now: time.Unix(0, 0)} + check, n := always(t, tc.err) + var log logSink + attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf) + if !errors.Is(err, tc.err) || attempts != 1 || *n != 1 || len(clk.waits) != 0 { + t.Fatalf("waitForSchema = (%d, %v) after %d checks and %d waits, want the error at once", attempts, err, *n, len(clk.waits)) + } + }) + } +} + +// One line when the wait starts, one every LogEvery, one on success or +// timeout; never one per attempt. Lines name the missing items only. +func TestWaitForSchema_LoggingIsBounded(t *testing.T) { + clk := &fakeClock{now: time.Unix(0, 0)} + check, n := always(t, missingTable) + var log logSink + waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf) + maxLines := int(defaultSchemaWaitPolicy.Deadline/defaultSchemaWaitPolicy.LogEvery) + 2 + if len(log.lines) > maxLines || len(log.lines) >= *n { + t.Fatalf("%d log lines for %d attempts over %v, want at most %d", len(log.lines), *n, defaultSchemaWaitPolicy.Deadline, maxLines) + } + if !strings.Contains(log.lines[0], "waiting") || !strings.Contains(log.lines[0], "table:route_mask_changes") || strings.Contains(log.lines[0], "restart ingestor") { + t.Fatalf("first line %q must say what is awaited, without telling the operator to restart", log.lines[0]) + } + if !strings.Contains(log.lines[1], "still waiting") || !strings.Contains(log.lines[1], "table:route_mask_changes") { + t.Fatalf("status line %q does not say what is still missing", log.lines[1]) + } + for _, l := range log.lines { + if strings.Contains(l, "SELECT") || strings.Contains(l, "password") { + t.Fatalf("log line leaks SQL or credentials: %q", l) + } + } + clk2 := &fakeClock{now: time.Unix(0, 0)} + check2, _ := checks(t, missingTable, missingTable) + var log2 logSink + waitForSchema(context.Background(), check2, defaultSchemaWaitPolicy, clk2, log2.logf) + if len(log2.lines) != 2 || !strings.Contains(log2.lines[1], "ready after") { + t.Fatalf("short wait logged %q, want the start and the success line", log2.lines) + } + clk3 := &fakeClock{now: time.Unix(0, 0)} + check3, _ := checks(t) + var log3 logSink + waitForSchema(context.Background(), check3, defaultSchemaWaitPolicy, clk3, log3.logf) + if len(log3.lines) != 0 { + t.Fatalf("a schema that is ready at once logged %q", log3.lines) + } +} + +// --- real SQLite --- + +var testSchemaPolicy = schemaWaitPolicy{Initial: 10 * time.Millisecond, Max: 40 * time.Millisecond, Factor: 1.5, Deadline: 3 * time.Second, LogEvery: time.Second} + +// fixtureSchemaDB copies the e2e fixture, migrates it and removes the +// change log (and its marker), returning the path and a writer handle. +func fixtureSchemaDB(t *testing.T) (string, *sql.DB) { + t.Helper() + src, err := os.Open(filepath.Join("..", "..", "test-fixtures", "e2e-fixture.db")) + if err != nil { + t.Fatal(err) + } + defer src.Close() + path := filepath.Join(t.TempDir(), "schema.db") + dst, err := os.Create(path) + if err != nil { + t.Fatal(err) + } + if _, err := io.Copy(dst, src); err != nil { + t.Fatal(err) + } + dst.Close() + rw, err := sql.Open("sqlite", "file:"+path+"?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)") + if err != nil { + t.Fatal(err) + } + rw.SetMaxOpenConns(1) + t.Cleanup(func() { rw.Close() }) + if err := dbschema.Apply(rw, func(string, ...interface{}) {}); err != nil { + t.Fatal(err) + } + for _, q := range []string{`DROP TABLE route_mask_changes`, `DELETE FROM _migrations WHERE name = 'route_mask_changes_v1'`} { + if _, err := rw.Exec(q); err != nil { + t.Fatal(err) + } + } + return path, rw +} + +func openRO(t *testing.T, path string) *sql.DB { + t.Helper() + ro, err := sql.Open("sqlite", "file:"+path+"?mode=ro&_pragma=busy_timeout(50)") + if err != nil { + t.Fatal(err) + } + return ro +} + +// Real SQLite, fake clock: the ingestor's migration is simulated by a hook +// in the check, so the tests are deterministic and never wait in real time. + +func TestWaitForServerSchema_AlreadyReadyDoesNotWait(t *testing.T) { + path, rw := fixtureSchemaDB(t) + if err := dbschema.Apply(rw, func(string, ...interface{}) {}); err != nil { + t.Fatal(err) + } + ro := openRO(t, path) + defer ro.Close() + clk := &fakeClock{now: time.Unix(0, 0)} + var log logSink + attempts, err := waitForServerSchema(context.Background(), ro, defaultSchemaWaitPolicy, clk, log.logf) + if err != nil || attempts != 1 || len(clk.waits) != 0 || len(log.lines) != 0 { + t.Fatalf("ready schema: (%d, %v), %d waits, logs %q; want one check, no wait, no log", attempts, err, len(clk.waits), log.lines) + } +} + +// ingestorAfter returns a check that runs AssertReady and, right before +// attempt n, lets the "ingestor" run fn (e.g. its Apply). +func ingestorAfter(t *testing.T, ro *sql.DB, n int, fn func()) (func() error, *int) { + calls := 0 + return func() error { + calls++ + if calls > 1000 { + t.Fatalf("check called %d times", calls) + } + if calls == n { + fn() + } + return dbschema.AssertReady(ro) + }, &calls +} + +func TestWaitForServerSchema_ChangeLogCreatedLater(t *testing.T) { + path, rw := fixtureSchemaDB(t) + ro := openRO(t, path) + defer ro.Close() + check, calls := ingestorAfter(t, ro, 4, func() { dbschema.Apply(rw, func(string, ...interface{}) {}) }) + clk := &fakeClock{now: time.Unix(0, 0)} + var log logSink + attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf) + if err != nil || attempts != 4 || *calls != 4 || len(clk.waits) != 3 { + t.Fatalf("waitForSchema = (%d, %v) after %d checks and %d waits, want success on attempt 4", attempts, err, *calls, len(clk.waits)) + } +} + +// A pre-#93 database lacks the route_mask column and the change log; both +// appear in the same ingestor Apply. +func TestWaitForServerSchema_SeveralMissingItemsCreatedLater(t *testing.T) { + path, rw := fixtureSchemaDB(t) + for _, q := range []string{`ALTER TABLE transmissions DROP COLUMN route_mask`, `DELETE FROM _migrations WHERE name = 'transmissions_route_mask_v1'`} { + if _, err := rw.Exec(q); err != nil { + t.Fatal(err) + } + } + ro := openRO(t, path) + defer ro.Close() + var nr *dbschema.NotReadyError + if err := dbschema.AssertReady(ro); !errors.As(err, &nr) || len(nr.Missing) != 2 || !nr.Transient() { + t.Fatalf("setup: want the column and the table missing (transient), got %v", err) + } + check, _ := ingestorAfter(t, ro, 3, func() { dbschema.Apply(rw, func(string, ...interface{}) {}) }) + clk := &fakeClock{now: time.Unix(0, 0)} + var log logSink + if attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf); err != nil || attempts != 3 { + t.Fatalf("waitForSchema = (%d, %v), want success on attempt 3", attempts, err) + } +} + +// holdWriterLock holds the SQLite write lock on the ingestor's (single) +// writer connection, as a long migration or the staging gate's external lock +// does, until the returned release func is called. +func holdWriterLock(t *testing.T, rw *sql.DB) func() { + t.Helper() + conn, err := rw.Conn(context.Background()) + if err != nil { + t.Fatal(err) + } + for _, q := range []string{`BEGIN IMMEDIATE`, `INSERT INTO _migrations (name) VALUES ('lock-probe')`} { + if _, err := conn.ExecContext(context.Background(), q); err != nil { + t.Fatal(err) + } + } + var once sync.Once + release := func() { + once.Do(func() { + conn.ExecContext(context.Background(), `ROLLBACK`) + conn.Close() + }) + } + t.Cleanup(release) + return release +} + +// The ingestor holds the writer lock; only after it releases the lock can it +// create the table, and only then is the schema verified. +func TestWaitForServerSchema_RealWriterLockReleasedLater(t *testing.T) { + path, rw := fixtureSchemaDB(t) + release := holdWriterLock(t, rw) + ro := openRO(t, path) + defer ro.Close() + // The ingestor is a separate process: its own connection, short busy wait. + ingestor, err := sql.Open("sqlite", "file:"+path+"?_pragma=busy_timeout(20)") + if err != nil { + t.Fatal(err) + } + defer ingestor.Close() + ingestor.SetMaxOpenConns(1) + var releasedAt int + check, calls := ingestorAfter(t, ro, 5, func() { + if err := dbschema.Apply(ingestor, func(string, ...interface{}) {}); err == nil { + t.Error("Apply succeeded while the writer lock was held") + } + release() + releasedAt = 5 + if err := dbschema.Apply(ingestor, func(string, ...interface{}) {}); err != nil { + t.Errorf("Apply after the lock was released: %v", err) + } + }) + clk := &fakeClock{now: time.Unix(0, 0)} + var log logSink + attempts, err := waitForSchema(context.Background(), check, defaultSchemaWaitPolicy, clk, log.logf) + if err != nil || attempts != 5 || releasedAt != 5 || *calls != 5 { + t.Fatalf("waitForSchema = (%d, %v), released at %d; want success on the attempt after the release", attempts, err, releasedAt) + } + if err := dbschema.AssertReady(ro); err != nil { + t.Fatalf("schema not verified afterwards: %v", err) + } +} + +func TestWaitForServerSchema_WrongDefinitionIsRejectedAtOnce(t *testing.T) { + path, rw := fixtureSchemaDB(t) + if _, err := rw.Exec(dbschema.CreateRouteMaskChangesTableSQL); err != nil { // no index + t.Fatal(err) + } + ro := openRO(t, path) + defer ro.Close() + clk := &fakeClock{now: time.Unix(0, 0)} + var log logSink + attempts, err := waitForServerSchema(context.Background(), ro, defaultSchemaWaitPolicy, clk, log.logf) + if err == nil || attempts != 1 || len(clk.waits) != 0 { + t.Fatalf("waitForServerSchema = (%d, %v), want an immediate error for a malformed change log", attempts, err) + } +} + +func TestWaitForServerSchema_CancelledUnderRealLock(t *testing.T) { + path, rw := fixtureSchemaDB(t) + holdWriterLock(t, rw) + ro := openRO(t, path) + defer ro.Close() + ctx, cancel := context.WithCancel(context.Background()) + clk := &fakeClock{now: time.Unix(0, 0), block: func(n int) bool { + if n == 2 { + cancel() + return true + } + return false + }} + var log logSink + if _, err := waitForServerSchema(ctx, ro, defaultSchemaWaitPolicy, clk, log.logf); !errors.Is(err, context.Canceled) { + t.Fatalf("waitForServerSchema = %v, want context.Canceled", err) + } +} + +// Real clock and real SQLite with a tiny policy: after success, timeout, +// permanent failure and cancellation the wait leaves no goroutine and no +// timer behind (it starts none), and the caller's connections close cleanly. +func TestWaitForServerSchema_NoLeaks(t *testing.T) { + tiny := schemaWaitPolicy{Initial: time.Millisecond, Max: 2 * time.Millisecond, Factor: 1.5, Deadline: 20 * time.Millisecond, LogEvery: time.Second} + for _, tc := range []struct { + name string + setup func(t *testing.T, rw *sql.DB) + cancel bool + ok func(error) bool + }{ + {"success", func(t *testing.T, rw *sql.DB) { dbschema.Apply(rw, func(string, ...interface{}) {}) }, false, func(err error) bool { return err == nil }}, + {"timeout", func(t *testing.T, rw *sql.DB) {}, false, func(err error) bool { var e *SchemaWaitTimeoutError; return errors.As(err, &e) }}, + {"permanent", func(t *testing.T, rw *sql.DB) { rw.Exec(dbschema.CreateRouteMaskChangesTableSQL) }, false, func(err error) bool { return err != nil }}, + {"cancelled", func(t *testing.T, rw *sql.DB) {}, true, func(err error) bool { return errors.Is(err, context.Canceled) }}, + } { + t.Run(tc.name, func(t *testing.T) { + path, rw := fixtureSchemaDB(t) + tc.setup(t, rw) + ro := openRO(t, path) + ro.Ping() + ctx, cancel := context.WithCancel(context.Background()) + if tc.cancel { + cancel() + } + before := runtime.NumGoroutine() + var log logSink + _, err := waitForServerSchema(ctx, ro, tiny, realClock{}, log.logf) + cancel() + if !tc.ok(err) { + t.Fatalf("unexpected result %v", err) + } + // database/sql ends a read transaction's watcher goroutine just + // after Rollback returns: yield until it is gone, bounded. Counted + // before Close, which also stops the pool's own goroutine. + after := runtime.NumGoroutine() + for settle := time.Now().Add(5 * time.Second); after > before && time.Now().Before(settle); after = runtime.NumGoroutine() { + runtime.Gosched() + } + if after > before { + t.Fatalf("goroutines %d -> %d after the wait", before, after) + } + if err := ro.Close(); err != nil { + t.Fatal(err) + } + if open := ro.Stats().OpenConnections; open != 0 { + t.Fatalf("%d connections still open after Close", open) + } + }) + } +} + +// Regression (review B1): the server reads its optional-column flags when it +// opens the database. On a pre-#93 database the route_mask column appears +// only during the wait, so the flags must be refreshed after it: otherwise +// the start-up load leaves route_mask out and never queues the loaded rows +// for the backfill refresh. +func TestWaitForDBSchema_RefreshesSchemaFlagsAfterWaiting(t *testing.T) { + path, rw := fixtureSchemaDB(t) + for _, q := range []string{`ALTER TABLE transmissions DROP COLUMN route_mask`, `DELETE FROM _migrations WHERE name = 'transmissions_route_mask_v1'`} { + if _, err := rw.Exec(q); err != nil { + t.Fatal(err) + } + } + db, err := OpenDB(path) + if err != nil { + t.Fatal(err) + } + defer db.Close() + if db.hasRouteMask() { + t.Fatal("setup: route_mask detected before the ingestor added it") + } + calls := 0 + check := func() error { + calls++ + if calls == 3 { + dbschema.Apply(rw, func(string, ...interface{}) {}) // the ingestor migrates + } + return dbschema.AssertReady(db.conn) + } + clk := &fakeClock{now: time.Unix(0, 0)} + var log logSink + if _, err := waitForDBSchemaWith(context.Background(), db, check, defaultSchemaWaitPolicy, clk, log.logf); err != nil { + t.Fatal(err) + } + if !db.hasRouteMask() { + t.Fatal("route_mask flag still false after the wait: the start-up load would skip route masks") + } + s := NewPacketStore(db, nil) + if neighborEdgesTableExists(db.conn) { // main.go loads the graph before the packets + s.graph.Store(loadNeighborEdgesFromDB(db.conn)) + } + if err := s.Load(); err != nil { + t.Fatal(err) + } + if n := s.routeMaskPendingLen(); n == 0 { + t.Fatal("loaded rows with a NULL route_mask were not queued for the backfill refresh") + } +} diff --git a/cmd/server/store.go b/cmd/server/store.go index b801a36ec..d765ac354 100644 --- a/cmd/server/store.go +++ b/cmd/server/store.go @@ -55,10 +55,17 @@ type StoreTx struct { LatestSeen string // max observation timestamp (or FirstSeen if no observations) UniqueObserverCount int // cached count of distinct observer IDs // Cached parsed fields (set once, read many) - parsedPath []string // cached parsePathJSON result - pathParsed bool // whether parsedPath has been set - decodedOnce sync.Once // guards parsedDecoded - parsedDecoded map[string]interface{} // cached json.Unmarshal of DecodedJSON + parsedPath []string // cached parsePathJSON result + pathParsed bool // whether parsedPath has been set + // routeMask mirrors transmissions.route_mask (#89): bit r is set when a + // frame with raw route type r was observed for this hash. routeMaskKnown + // is false while the row is NULL (not backfilled yet) or the column is + // absent. Both fit in the padding before decodedOnce (StoreTx stays 320 + // bytes on 64-bit, see TestStoreTxLayoutFitsRouteMaskInPadding). + routeMask uint8 + routeMaskKnown bool + decodedOnce sync.Once // guards parsedDecoded + parsedDecoded map[string]interface{} // cached json.Unmarshal of DecodedJSON // Dedup map: "observerID|pathJSON" → true for O(1) duplicate checks obsKeys map[string]bool observerSet map[string]bool // unique observer IDs (for UniqueObserverCount) @@ -222,6 +229,28 @@ type PacketStore struct { lastInvalidated time.Time pendingInv *cacheInvalidation // accumulated dirty flags during cooldown invCooldown time.Duration // minimum time between invalidations + // #89: ids of transmissions loaded while their route_mask was still NULL + // (not backfilled yet). Load and ingest paths append to the unsorted + // inbox; RefreshBackfilledRouteMasks (serialised by its own mutex) moves + // the inbox into the sorted queue and re-reads it as the backfill fills + // the rows. The count covers both. + routeMaskInboxMu sync.Mutex // guards routeMaskInbox + routeMaskInbox []int + routeMaskRefreshMu sync.Mutex // serialises refreshes; guards routeMaskQueue + routeMaskQueue []int // sorted ascending + routeMaskQueuedCount atomic.Int64 + // #89: live route_mask changes from the ingestor's route_mask_changes + // log (see RefreshRouteMaskChanges). The cursor is the highest log id + // applied or parked; routeMaskChangesMu serialises refreshes and guards + // the cursor. routeMaskParked (guarded by s.mu) holds changes for + // transmissions not in the store yet, e.g. still in an unpublished + // start-up chunk; they are applied when the transmission is published. + routeMaskChangesMu sync.Mutex + routeMaskChangesCursor int64 + routeMaskChangesState int // 0 not initialised, 1 polling, -1 no change log + routeMaskParked map[int]uint8 + routeMaskLoadSettled atomic.Bool // Load() or RunStartupLoad returned: start-up loading is over + routeMaskChangeRowsRead atomic.Int64 // Short-lived cache for QueryGroupedPackets (avoids repeated full sort) groupedCacheMu sync.Mutex groupedCacheKey string @@ -506,6 +535,16 @@ type PacketStore struct { // ordering tests to capture the bg-loader entry timestamp/signal // without polling. See runstartup_load_test.go. bgLoaderEntryHook func() + // loadChunkScannedHook, if non-nil, runs in loadChunk after the chunk is + // scanned into local maps and before it is merged into the store. + // Test-only (#89 route_mask refresh race). + loadChunkScannedHook func() + // loadScannedRowHook, if non-nil, runs once in Load / LoadChunked right + // after the first transmission row is read, then is cleared. It runs + // while s.mu is held, so it must not call anything that takes s.mu + // (e.g. RefreshRouteMaskChanges). Test-only (#89 route_mask_changes + // watermark placement). + loadScannedRowHook func() } // Precomputed distance records for fast analytics aggregation. @@ -720,6 +759,10 @@ func NewPacketStore(db *DB, cfg *PacketStoreConfig, cacheTTLs ...map[string]inte // When maxMemoryMB > 0, loads only the newest N transmissions that fit // within the memory budget, avoiding OOM on large databases. func (s *PacketStore) Load() error { + // #89: the change-log watermark is read before any row is loaded, and + // before s.mu (a refresh takes routeMaskChangesMu, then s.mu). + s.initRouteMaskChangeCursor() + defer s.routeMaskLoadSettled.Store(true) s.mu.Lock() defer s.mu.Unlock() @@ -773,6 +816,11 @@ func (s *PacketStore) Load() error { if s.db.hasScopeName() { scopeNameCol = ", t.scope_name" } + // #89: route_mask follows scope_name as the last optional column. + routeMaskCol := "" + if s.db.hasRouteMask() { + routeMaskCol = ", t.route_mask" + } // Build WHERE conditions: retention cutoff (mirrors Evict logic) + optional memory-cap limit. // When hotStartupHours > 0, use it as the initial cutoff (smaller window = fast startup). @@ -817,7 +865,7 @@ func (s *PacketStore) Load() error { loadSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, obs.id, obs.name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRawHexCol + rpCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRawHexCol + rpCol + scopeNameCol + routeMaskCol + ` FROM transmissions t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.rowid = o.observer_idx` + filterClause + ` @@ -826,7 +874,7 @@ func (s *PacketStore) Load() error { loadSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, o.observer_id, o.observer_name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRawHexCol + rpCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRawHexCol + rpCol + scopeNameCol + routeMaskCol + ` FROM transmissions t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.id = o.observer_id` + filterClause + ` @@ -865,6 +913,7 @@ func (s *PacketStore) Load() error { var obsRawHex sql.NullString var resolvedPathStr sql.NullString var scopeName sql.NullString + var routeMask sql.NullInt64 scanArgs := []interface{}{&txID, &rawHex, &hash, &firstSeen, &routeType, &payloadType, &payloadVersion, &decodedJSON, @@ -879,10 +928,18 @@ func (s *PacketStore) Load() error { if s.db.hasScopeName() { scanArgs = append(scanArgs, &scopeName) } + if s.db.hasRouteMask() { + scanArgs = append(scanArgs, &routeMask) + } if err := rows.Scan(scanArgs...); err != nil { log.Printf("[store] scan error: %v", err) continue } + if s.loadScannedRowHook != nil { + hook := s.loadScannedRowHook + s.loadScannedRowHook = nil + hook() + } hashStr := nullStrVal(hash) tx := s.byHash[hashStr] @@ -901,6 +958,7 @@ func (s *PacketStore) Load() error { observerSet: make(map[string]bool), } s.byHash[hashStr] = tx + s.mergeRouteMaskOrQueue(tx, routeMask) s.packets = append(s.packets, tx) s.byTxID[txID] = tx if txID > s.maxTxID { @@ -1104,6 +1162,11 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { if s.db.hasScopeName() { scopeNameCol = ", t.scope_name" } + // #89: route_mask follows scope_name as the last optional column. + routeMaskCol := "" + if s.db.hasRouteMask() { + routeMaskCol = ", t.route_mask" + } // #1690: window on the denormalized last_seen (effective recency) // rather than first_seen. See chunked_load.go for the full rationale. @@ -1123,7 +1186,7 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { chunkSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, obs.id, obs.name, o.direction, - o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRawHexCol + rpCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRawHexCol + rpCol + scopeNameCol + routeMaskCol + ` FROM transmissions t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.rowid = o.observer_idx` + filterClause + ` @@ -1132,7 +1195,7 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { chunkSQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, o.observer_id, o.observer_name, o.direction, - o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRawHexCol + rpCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRawHexCol + rpCol + scopeNameCol + routeMaskCol + ` FROM transmissions t LEFT JOIN observations o ON o.transmission_id = t.id` + filterClause + ` ORDER BY t.first_seen ASC, o.timestamp DESC` @@ -1193,6 +1256,7 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { var obsRawHex sql.NullString var resolvedPathStr sql.NullString var scopeName sql.NullString + var routeMask sql.NullInt64 scanArgs := []interface{}{&txID, &rawHex, &hash, &firstSeen, &routeType, &payloadType, &payloadVersion, &decodedJSON, @@ -1207,6 +1271,9 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { if s.db.hasScopeName() { scanArgs = append(scanArgs, &scopeName) } + if s.db.hasRouteMask() { + scanArgs = append(scanArgs, &routeMask) + } if err := rows.Scan(scanArgs...); err != nil { log.Printf("[store] loadChunk scan error: %v", err) continue @@ -1229,6 +1296,9 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { observerSet: make(map[string]bool), } localByHash[hashStr] = tx + // Queued only once it is in s.byTxID (merge section below); + // a refresh in between would otherwise drop the id. + tx.mergeRouteMask(routeMask) localPackets = append(localPackets, tx) localByTxID[txID] = tx if txID > localMaxTxID { @@ -1341,6 +1411,9 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { // intermediate state where indexes contain a superset of s.packets // (which is harmless: nothing in s.packets dangles), or the fully // merged new state. + if s.loadChunkScannedHook != nil { + s.loadChunkScannedHook() + } const mergeBatchSize = 500 for batchStart := 0; batchStart < len(localPackets); batchStart += mergeBatchSize { @@ -1386,6 +1459,8 @@ func (s *PacketStore) loadChunk(from, to time.Time) error { for k, v := range batchTxIDs { if s.byTxID[k] == nil { s.byTxID[k] = v + s.applyParkedRouteMask(v) + s.queueUnknownRouteMask(v) } } for k, v := range batchObsIDs { @@ -2650,11 +2725,16 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac if s.db.hasScopeName() { scopeNameCol = ", t.scope_name" } + // #89: route_mask follows scope_name as the last optional column. + routeMaskCol := "" + if s.db.hasRouteMask() { + routeMaskCol = ", t.route_mask" + } if s.db.isV3() { querySQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, obs.id, obs.name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRHCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRHCol + scopeNameCol + routeMaskCol + ` FROM transmissions t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.rowid = o.observer_idx @@ -2664,7 +2744,7 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac querySQL = `SELECT t.id, t.raw_hex, t.hash, t.first_seen, t.route_type, t.payload_type, t.payload_version, t.decoded_json, o.id, o.observer_id, o.observer_name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRHCol + scopeNameCol + ` + o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRHCol + scopeNameCol + routeMaskCol + ` FROM transmissions t LEFT JOIN observations o ON o.transmission_id = t.id LEFT JOIN observers obs ON obs.id = o.observer_id @@ -2688,6 +2768,7 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac observerID, observerName, observerIATA, direction, pathJSON, obsTS string obsRawHex string scopeName string + routeMask sql.NullInt64 snr, rssi *float64 score *int } @@ -2706,6 +2787,7 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac var scoreVal sql.NullInt64 var obsRawHex sql.NullString var scopeName sql.NullString + var routeMask sql.NullInt64 scanArgs2 := []interface{}{&txID, &rawHex, &hash, &firstSeen, &routeType, &payloadType, &payloadVersion, &decodedJSON, @@ -2717,6 +2799,9 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac if s.db.hasScopeName() { scanArgs2 = append(scanArgs2, &scopeName) } + if s.db.hasRouteMask() { + scanArgs2 = append(scanArgs2, &routeMask) + } if err := rows.Scan(scanArgs2...); err != nil { continue } @@ -2745,6 +2830,7 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac obsTS: nullStrVal(obsTimestamp), obsRawHex: nullStrVal(obsRawHex), scopeName: nullStrVal(scopeName), + routeMask: routeMask, snr: nullFloatPtr(snrVal), rssi: nullFloatPtr(rssiVal), score: nullIntPtr(scoreVal), @@ -2787,6 +2873,9 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac } tx := s.byHash[r.hash] + if tx != nil { + tx.mergeRouteMask(r.routeMask) + } if tx == nil { tx = &StoreTx{ ID: r.txID, @@ -2802,6 +2891,7 @@ func (s *PacketStore) IngestNewFromDB(sinceID, limit int) ([]map[string]interfac observerSet: make(map[string]bool), } s.byHash[r.hash] = tx + s.mergeRouteMaskOrQueue(tx, r.routeMask) s.packets = append(s.packets, tx) // oldest-first; new items go to tail s.byTxID[r.txID] = tx if r.txID > s.maxTxID { @@ -3066,19 +3156,26 @@ func (s *PacketStore) IngestNewObservations(sinceObsID, limit int) []map[string] if s.db.hasObsRawHex() { obsRHCol2 = ", o.raw_hex" } + // #89: the transmission's current route_mask rides along with each new + // observation so the live view converges with a cold load. + routeMaskCol2, routeMaskJoin2 := "", "" + if s.db.hasRouteMask() { + routeMaskCol2 = ", t.route_mask" + routeMaskJoin2 = "\n\t\t\tLEFT JOIN transmissions t ON t.id = o.transmission_id" + } if s.db.isV3() { querySQL = `SELECT o.id, o.transmission_id, obs.id, obs.name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRHCol2 + ` + o.snr, o.rssi, o.score, o.path_json, strftime('%Y-%m-%dT%H:%M:%fZ', o.timestamp, 'unixepoch')` + obsRHCol2 + routeMaskCol2 + ` FROM observations o - LEFT JOIN observers obs ON obs.rowid = o.observer_idx + LEFT JOIN observers obs ON obs.rowid = o.observer_idx` + routeMaskJoin2 + ` WHERE o.id > ? ORDER BY o.id ASC LIMIT ?` } else { querySQL = `SELECT o.id, o.transmission_id, o.observer_id, o.observer_name, COALESCE(obs.iata, ''), o.direction, - o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRHCol2 + ` + o.snr, o.rssi, o.score, o.path_json, o.timestamp` + obsRHCol2 + routeMaskCol2 + ` FROM observations o - LEFT JOIN observers obs ON obs.id = o.observer_id + LEFT JOIN observers obs ON obs.id = o.observer_id` + routeMaskJoin2 + ` WHERE o.id > ? ORDER BY o.id ASC LIMIT ?` @@ -3103,6 +3200,7 @@ func (s *PacketStore) IngestNewObservations(sinceObsID, limit int) []map[string] pathJSON string rawHex string timestamp string + routeMask sql.NullInt64 } var obsRows []obsRow @@ -3112,12 +3210,16 @@ func (s *PacketStore) IngestNewObservations(sinceObsID, limit int) []map[string] var snr, rssi sql.NullFloat64 var score sql.NullInt64 var obsRawHex sql.NullString + var routeMask sql.NullInt64 scanArgs3 := []interface{}{&oid, &txID, &observerID, &observerName, &observerIATA, &direction, &snr, &rssi, &score, &pathJSON, &ts} if s.db.hasObsRawHex() { scanArgs3 = append(scanArgs3, &obsRawHex) } + if s.db.hasRouteMask() { + scanArgs3 = append(scanArgs3, &routeMask) + } if err := rows.Scan(scanArgs3...); err != nil { continue } @@ -3135,6 +3237,7 @@ func (s *PacketStore) IngestNewObservations(sinceObsID, limit int) []map[string] pathJSON: nullStrVal(pathJSON), rawHex: nullStrVal(obsRawHex), timestamp: nullStrVal(ts), + routeMask: routeMask, }) } @@ -3168,6 +3271,7 @@ func (s *PacketStore) IngestNewObservations(sinceObsID, limit int) []map[string] if tx == nil { continue // transmission not yet in store } + tx.mergeRouteMask(r.routeMask) // Dedup by observer + path (O(1) map lookup) dk := r.observerID + "|" + r.pathJSON diff --git a/cmd/server/websocket.go b/cmd/server/websocket.go index a8b177305..d470b850a 100644 --- a/cmd/server/websocket.go +++ b/cmd/server/websocket.go @@ -310,41 +310,7 @@ func (p *Poller) Start() { select { case <-ticker.C: if p.store != nil { - // Ingest new transmissions into in-memory store and broadcast - newTxs, newMax := p.store.IngestNewFromDB(lastID, 100) - if newMax > lastID { - lastID = newMax - } - // Ingest new observations for existing transmissions (fixes #174) - nextObsID := lastObsID - if err := p.db.conn.QueryRow(` - SELECT COALESCE(MAX(id), ?) FROM ( - SELECT id FROM observations - WHERE id > ? - ORDER BY id ASC - LIMIT 500 - )`, lastObsID, lastObsID).Scan(&nextObsID); err != nil { - nextObsID = lastObsID - } - newObs := p.store.IngestNewObservations(lastObsID, 500) - if nextObsID > lastObsID { - lastObsID = nextObsID - } - if len(newTxs) > 0 { - log.Printf("[broadcast] sending %d packets to %d clients (lastID now %d)", len(newTxs), p.hub.ClientCount(), lastID) - } - for _, tx := range newTxs { - p.hub.Broadcast(WSMessage{ - Type: "packet", - Data: tx, - }) - } - for _, obs := range newObs { - p.hub.Broadcast(WSMessage{ - Type: "packet", - Data: obs, - }) - } + lastID, lastObsID = p.pollStore(lastID, lastObsID) } else { // Fallback: direct DB query (used when store is nil, e.g. tests) newTxs, err := p.db.GetNewTransmissionsSince(lastID, 100) @@ -375,6 +341,54 @@ func (p *Poller) Start() { } } +// pollStore is one poller tick against the in-memory store: ingest new +// transmissions and observations, apply route_mask changes, and broadcast. +// It returns the advanced cursors. +func (p *Poller) pollStore(lastID, lastObsID int) (int, int) { + // Ingest new transmissions into in-memory store and broadcast + newTxs, newMax := p.store.IngestNewFromDB(lastID, 100) + if newMax > lastID { + lastID = newMax + } + // Ingest new observations for existing transmissions (fixes #174) + nextObsID := lastObsID + if err := p.db.conn.QueryRow(` + SELECT COALESCE(MAX(id), ?) FROM ( + SELECT id FROM observations + WHERE id > ? + ORDER BY id ASC + LIMIT 500 + )`, lastObsID, lastObsID).Scan(&nextObsID); err != nil { + nextObsID = lastObsID + } + newObs := p.store.IngestNewObservations(lastObsID, 500) + if nextObsID > lastObsID { + lastObsID = nextObsID + } + // #89: route bits that reached existing transmissions without a new + // observation id (an upserted observation row), from the change log. + p.store.RefreshRouteMaskChanges() + // #89: pick up route_mask values the ingestor backfilled + // after this server loaded the rows. + p.store.RefreshBackfilledRouteMasks() + if len(newTxs) > 0 { + log.Printf("[broadcast] sending %d packets to %d clients (lastID now %d)", len(newTxs), p.hub.ClientCount(), lastID) + } + for _, tx := range newTxs { + p.hub.Broadcast(WSMessage{ + Type: "packet", + Data: tx, + }) + } + for _, obs := range newObs { + p.hub.Broadcast(WSMessage{ + Type: "packet", + Data: obs, + }) + } + return lastID, lastObsID +} + func (p *Poller) Stop() { close(p.stop) } diff --git a/internal/dbschema/dbschema.go b/internal/dbschema/dbschema.go index 7bf3d7423..d845dd1ed 100644 --- a/internal/dbschema/dbschema.go +++ b/internal/dbschema/dbschema.go @@ -2,7 +2,9 @@ // assertions for the CoreScope SQLite DB. Per issue #1287 the writer // (cmd/ingestor) owns ALL CREATE/ALTER/INSERT/UPDATE/DELETE on schema // objects; the server (cmd/server) only ASSERTS that the schema is in -// the expected shape and refuses to start otherwise. +// the expected shape. It waits (bounded) while the ingestor's in-progress +// start-up migration is still missing (NotReadyError.Transient) and refuses +// to start otherwise. // // Apply(rw, log) runs from the ingestor at startup BEFORE subscribing to // MQTT. AssertReady(ro) runs from the server at startup and returns an @@ -118,33 +120,192 @@ func Apply(rw *sql.DB, logf Logger) error { if err := ensureTransmissionsLastSeenColumn(rw, logf); err != nil { return fmt.Errorf("ensure transmissions.last_seen: %w", err) } + if err := ensureTransmissionsRouteMaskColumn(rw, logf); err != nil { + return fmt.Errorf("ensure transmissions.route_mask: %w", err) + } + if err := ensureRouteMaskChangesTable(rw, logf); err != nil { + return fmt.Errorf("ensure route_mask_changes: %w", err) + } return nil } +// NotReadyError is AssertReady's error: the required schema items that are +// missing or malformed, and the items whose probe failed (each with its +// error, so no failure can be recorded without the error that classifies it). +type NotReadyError struct { + Missing []string // human-readable item names; never row data + Probes []ProbeFailure +} + +// ProbeFailure is a schema item AssertReady could not verify. +type ProbeFailure struct { + Item string + Err error +} + +// Items lists every item that is missing, malformed or unverified. +func (e *NotReadyError) Items() []string { + items := append([]string(nil), e.Missing...) + for _, p := range e.Probes { + items = append(items, fmt.Sprintf("%s (probe error: %v)", p.Item, p.Err)) + } + return items +} + +func (e *NotReadyError) Error() string { + return fmt.Sprintf("schema not migrated by ingestor; restart ingestor first. missing: %s", + strings.Join(e.Items(), ", ")) +} + +// Transient reports whether the ingestor resolves the problem by itself +// while it starts: the only missing items are this PR's start-up migration +// still in progress (route_mask_changes not created yet, and possibly the +// transmissions.route_mask column added just before it in the same Apply), +// and every probe failure is SQLite BUSY or LOCKED. Anything else (another +// missing item, a malformed change log, a change log whose migration is +// recorded but whose table is gone, the column missing while the table +// exists, any other SQLite error) is permanent. Classification uses SQLite +// result codes, never error text. +func (e *NotReadyError) Transient() bool { + if len(e.Missing) == 0 && len(e.Probes) == 0 { + return false + } + tableUnknown := false // not created yet, or its probe was BUSY/LOCKED + for _, p := range e.Probes { + if !isBusyOrLocked(p.Err) { + return false + } + if p.Item == "table:route_mask_changes" { + tableUnknown = true + } + } + for _, m := range e.Missing { + if m == "table:route_mask_changes" { + tableUnknown = true + } + } + for _, m := range e.Missing { + switch { + case m == "table:route_mask_changes": + case m == "transmissions.route_mask" && tableUnknown: + // Added by the same Apply, right before the table. + default: + return false + } + } + return true +} + +// isBusyOrLocked reports whether err carries SQLite primary result code +// SQLITE_BUSY (5) or SQLITE_LOCKED (6), including extended codes such as +// SQLITE_BUSY_SNAPSHOT. The driver's errors expose Code(). +func isBusyOrLocked(err error) bool { + var coded interface{ Code() int } + if !errors.As(err, &coded) { + return false + } + primary := coded.Code() & 0xff + return primary == 5 || primary == 6 +} + // AssertReady verifies the schema is in the expected shape. The server -// calls this at startup against a read-only connection; if it returns -// non-nil, the server MUST fatal-log and exit so the operator restarts -// the ingestor (which owns migrations). -func AssertReady(ro *sql.DB) error { +// calls this at startup against a read-only connection. A non-nil result is +// a *NotReadyError: the server waits (bounded) while it is Transient() and +// fails otherwise, so the operator restarts the ingestor (which owns +// migrations). +func AssertReady(ro *sql.DB) error { return assertReady(ro, nil) } + +// assertReady is AssertReady; tests pass probed to run code right after the +// probe of an item ("table:" or "."). +func assertReady(ro *sql.DB, probed func(item string)) error { + if probed == nil { + probed = func(string) {} + } + // Every probe reads one snapshot: the ingestor may commit a migration + // while this runs, and a check that saw half of it would call the + // in-progress migration permanent. + tx, err := ro.Begin() + if err != nil { + return &NotReadyError{Probes: []ProbeFailure{{Item: "read transaction", Err: err}}} + } + defer tx.Rollback() + var missing []string + var probes []ProbeFailure + probeFailed := func(item string, err error) { + probes = append(probes, ProbeFailure{Item: item, Err: err}) + } mustCol := func(table, col string) { - has, err := TableHasColumn(ro, table, col) + has, err := tableHasColumn(tx, table, col) + probed(table + "." + col) if err != nil { - missing = append(missing, fmt.Sprintf("%s.%s (probe error: %v)", table, col, err)) + probeFailed(table+"."+col, err) return } if !has { missing = append(missing, fmt.Sprintf("%s.%s", table, col)) } } - mustTable := func(name string) { + tableExists := func(name string) (bool, error) { var n int - err := ro.QueryRow(`SELECT 1 FROM sqlite_master WHERE type='table' AND name=?`, name).Scan(&n) + err := tx.QueryRow(`SELECT 1 FROM sqlite_master WHERE type='table' AND name=?`, name).Scan(&n) + probed("table:" + name) if errors.Is(err, sql.ErrNoRows) { + return false, nil + } + return err == nil, err + } + mustTable := func(name string) { + ok, err := tableExists(name) + if err != nil { + probeFailed("table:"+name, err) + } else if !ok { missing = append(missing, "table:"+name) - } else if err != nil { - missing = append(missing, fmt.Sprintf("table:%s (probe error: %v)", name, err)) + } + } + // #89: once the change log exists it must match the approved definition + // (the ingestor creates table, index and marker in one transaction). A + // missing table is the migration still to come, unless its marker is + // already recorded: the ingestor never recreates such a table. + mustRouteMaskChanges := func() { + const item = "table:route_mask_changes" + ok, err := tableExists("route_mask_changes") + if err != nil { + probeFailed(item, err) + return + } + if !ok { + recorded, err := migrationRecorded(tx, RouteMaskChangesMigration) + switch { + case err != nil: + probeFailed(item, err) + case recorded: + missing = append(missing, item+" (recorded in _migrations)") + default: + missing = append(missing, item) + } + return + } + for _, col := range []string{"id", "transmission_id", "route_mask", "created_at"} { + mustCol("route_mask_changes", col) + } + var ddl string + if err := tx.QueryRow(`SELECT sql FROM sqlite_master WHERE type='table' AND name='route_mask_changes'`).Scan(&ddl); err != nil { + probeFailed("route_mask_changes definition", err) + } else if !strings.Contains(strings.ToUpper(ddl), "AUTOINCREMENT") { + missing = append(missing, "route_mask_changes.id AUTOINCREMENT") + } + // The index covers exactly transmission_id (columns in index order). + var cols string + err = tx.QueryRow(`SELECT COALESCE(group_concat(name, ','), '') FROM ( + SELECT ii.name AS name FROM sqlite_master m, pragma_index_info(m.name) ii + WHERE m.type='index' AND m.name=? AND m.tbl_name='route_mask_changes' ORDER BY ii.seqno)`, RouteMaskChangesTxIndex).Scan(&cols) + switch { + case err != nil: + probeFailed("index:"+RouteMaskChangesTxIndex, err) + case cols != "transmission_id": + missing = append(missing, "index:"+RouteMaskChangesTxIndex) } } @@ -160,6 +321,8 @@ func AssertReady(ro *sql.DB) error { // (cmd/ingestor/db.go OpenStore: ALTER + index + async backfill); // server reads it to filter the hot-window query. mustCol("transmissions", "last_seen") + mustCol("transmissions", "route_mask") + mustRouteMaskChanges() // #1321: server's detectSchema PRAGMA-detects these and caches a // boolean. To kill the startup race they're owned + asserted here. mustCol("transmissions", "scope_name") @@ -208,16 +371,40 @@ func AssertReady(ro *sql.DB) error { mustTable("observer_neighbors") mustTable("observer_neighbor_metrics") - if len(missing) > 0 { - return fmt.Errorf("schema not migrated by ingestor; restart ingestor first. missing: %s", - strings.Join(missing, ", ")) + if len(missing) > 0 || len(probes) > 0 { + return &NotReadyError{Missing: missing, Probes: probes} } return nil } +// migrationRecorded reports whether the _migrations marker name exists. A +// database without _migrations has recorded nothing yet. +func migrationRecorded(db querier, name string) (bool, error) { + var n int + err := db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type='table' AND name='_migrations'`).Scan(&n) + if err != nil || n == 0 { + return false, err + } + err = db.QueryRow(`SELECT 1 FROM _migrations WHERE name = ?`, name).Scan(&n) + if errors.Is(err, sql.ErrNoRows) { + return false, nil + } + return err == nil, err +} + +// querier is what *sql.DB and *sql.Tx share for schema probes. +type querier interface { + Query(query string, args ...interface{}) (*sql.Rows, error) + QueryRow(query string, args ...interface{}) *sql.Row +} + // TableHasColumn reports whether the given table has the given column. // Exported because tests and the read-side need it without re-implementing. func TableHasColumn(db *sql.DB, table, column string) (bool, error) { + return tableHasColumn(db, table, column) +} + +func tableHasColumn(db querier, table, column string) (bool, error) { rows, err := db.Query(fmt.Sprintf("PRAGMA table_info(%s)", table)) if err != nil { return false, err @@ -576,6 +763,102 @@ func ensureObservationsRawHexColumn(rw *sql.DB, logf Logger) error { return nil } +// Issue #89: transmissions.route_mask records every raw route type observed +// for a content hash. Bit r (0..3) is set when a frame with route type r was +// seen; bits are only ever OR-ed in, never cleared, so the result does not +// depend on ingest order. NULL means "not backfilled yet": the column is +// added without a default, so existing rows stay NULL until the ingestor's +// async backfill fills them from route_type and observations.raw_hex (a +// lower bound; it never invents bits). +// +// RouteMaskPendingIndex tracks the rows the backfill still has to process. It +// is deliberately NOT created here: building it on a staging-sized DB takes +// 18-19.5 s cold, and Apply runs before the MQTT subscription exists. The +// ingestor builds it inside the async backfill, where IngestBuffer covers the +// write stall. The server reports the backfill as pending until it exists. +const ( + RouteMaskColumnMigration = "transmissions_route_mask_v1" + RouteMaskBackfillMigration = "tx_route_mask_backfill_v1" + RouteMaskPendingIndex = "idx_tx_route_mask_null" + CreateRouteMaskPendingIndexSQL = `CREATE INDEX IF NOT EXISTS idx_tx_route_mask_null ON transmissions(id) WHERE route_mask IS NULL` +) + +func ensureTransmissionsRouteMaskColumn(rw *sql.DB, logf Logger) error { + if err := ensureMigrationsTable(rw); err != nil { + return err + } + has, err := TableHasColumn(rw, "transmissions", "route_mask") + if err != nil { + return err + } + if !has { + // PREFLIGHT: async=false reason="nullable ADD COLUMN without a default is a metadata-only schema change in SQLite (no row scan); measured 8-15 ms on a 4.95 GB staging copy" + if _, err := rw.Exec(`ALTER TABLE transmissions ADD COLUMN route_mask INTEGER`); err != nil { + return fmt.Errorf("alter transmissions add route_mask: %w", err) + } + logf("[dbschema] added route_mask column to transmissions (#89)") + } + if _, err := rw.Exec(`INSERT OR IGNORE INTO _migrations (name) VALUES (?)`, RouteMaskColumnMigration); err != nil { + return fmt.Errorf("record %s: %w", RouteMaskColumnMigration, err) + } + return nil +} + +const ( + RouteMaskChangesMigration = "route_mask_changes_v1" + RouteMaskChangesTxIndex = "idx_route_mask_changes_tx" + // CreateRouteMaskChangesTableSQL and CreateRouteMaskChangesIndexSQL are + // exported so tests build the table exactly as Apply does. + CreateRouteMaskChangesTableSQL = `CREATE TABLE IF NOT EXISTS route_mask_changes ( + id INTEGER PRIMARY KEY AUTOINCREMENT, + transmission_id INTEGER NOT NULL, + route_mask INTEGER NOT NULL, + created_at INTEGER NOT NULL + )` + CreateRouteMaskChangesIndexSQL = `CREATE INDEX IF NOT EXISTS ` + RouteMaskChangesTxIndex + ` ON route_mask_changes(transmission_id)` +) + +// ensureRouteMaskChangesTable creates route_mask_changes, the durable change +// log from the ingestor to running servers (#89, PR #93 review). The +// ingestor appends one row, in the same transaction, whenever an observation +// adds a route bit to an existing transmission's route_mask; route_mask is +// the resulting full mask and created_at the ingest time (Unix seconds). +// Servers poll it by id, so AUTOINCREMENT keeps ids from being reused after +// retention deletes the newest rows. The full route_mask in transmissions +// stays authoritative on a cold load; this table only notifies servers that +// already hold the transmission. A new, empty table: no scan of existing data. +func ensureRouteMaskChangesTable(rw *sql.DB, logf Logger) error { + if err := ensureMigrationsTable(rw); err != nil { + return err + } + var one int + if err := rw.QueryRow(`SELECT 1 FROM _migrations WHERE name = ?`, RouteMaskChangesMigration).Scan(&one); err == nil { + return nil // already applied + } + // Table, index and marker in one transaction: a server that sees the + // table also sees its index, and a failure leaves nothing behind. + tx, err := rw.Begin() + if err != nil { + return fmt.Errorf("begin route_mask_changes: %w", err) + } + defer tx.Rollback() // no-op after a successful Commit + if _, err := tx.Exec(CreateRouteMaskChangesTableSQL); err != nil { + return fmt.Errorf("create route_mask_changes: %w", err) + } + // PREFLIGHT: async=false reason="index on a new, empty table; no scan of existing data" + if _, err := tx.Exec(CreateRouteMaskChangesIndexSQL); err != nil { + return fmt.Errorf("create %s: %w", RouteMaskChangesTxIndex, err) + } + if _, err := tx.Exec(`INSERT OR IGNORE INTO _migrations (name) VALUES (?)`, RouteMaskChangesMigration); err != nil { + return fmt.Errorf("record %s: %w", RouteMaskChangesMigration, err) + } + if err := tx.Commit(); err != nil { + return fmt.Errorf("commit route_mask_changes: %w", err) + } + logf("[dbschema] created route_mask_changes table (#89)") + return nil +} + // ensureMigrationsTable is idempotent — the ingestor's applySchema also // creates this table on legacy paths. Keeping it here lets the gated // `INSERT OR IGNORE` markers above stay self-sufficient even when Apply diff --git a/internal/dbschema/ready_classify_test.go b/internal/dbschema/ready_classify_test.go new file mode 100644 index 000000000..60f740994 --- /dev/null +++ b/internal/dbschema/ready_classify_test.go @@ -0,0 +1,314 @@ +package dbschema + +import ( + "database/sql" + "errors" + "fmt" + "strings" + "testing" +) + +// PR #93 staging gate: the server must wait (bounded) while the ingestor +// creates this PR's start-up migrations, instead of exiting until supervisord +// gives up. AssertReady therefore reports a typed *NotReadyError whose +// Transient() is true only for that in-progress migration or SQLite +// BUSY/LOCKED; every other defect is permanent and must fail at once. + +func readyDB(t *testing.T) *sql.DB { + t.Helper() + db := minimalDB(t) + t.Cleanup(func() { db.Close() }) + if err := Apply(db, nil); err != nil { + t.Fatal(err) + } + if err := AssertReady(db); err != nil { + t.Fatalf("setup: %v", err) + } + return db +} + +func dbPath(t *testing.T, db *sql.DB) string { + t.Helper() + var seq int + var name, file string + if err := db.QueryRow(`PRAGMA database_list`).Scan(&seq, &name, &file); err != nil { + t.Fatal(err) + } + return file +} + +func mustExec(t *testing.T, db *sql.DB, q string) { + t.Helper() + if _, err := db.Exec(q); err != nil { + t.Fatalf("%s: %v", q, err) + } +} + +func notReady(t *testing.T, err error) *NotReadyError { + t.Helper() + var nr *NotReadyError + if !errors.As(err, &nr) { + t.Fatalf("AssertReady = %v (%T), want *NotReadyError", err, err) + } + return nr +} + +// dropChangeLog returns a migrated database to the state before this PR's +// change-log migration: no table, no index, no marker. +func dropChangeLog(t *testing.T, db *sql.DB) { + t.Helper() + mustExec(t, db, `DROP TABLE route_mask_changes`) + mustExec(t, db, `DELETE FROM _migrations WHERE name = 'route_mask_changes_v1'`) +} + +func TestAssertReady_MissingChangeLogIsTransient(t *testing.T) { + db := readyDB(t) + dropChangeLog(t, db) + nr := notReady(t, AssertReady(db)) + if !nr.Transient() { + t.Fatalf("missing route_mask_changes is the ingestor's in-progress migration, want transient: %v", nr) + } + if !strings.Contains(nr.Error(), "table:route_mask_changes") { + t.Fatalf("error does not name the missing table: %v", nr) + } +} + +// A pre-#93 database lacks the route_mask column too: the ingestor adds the +// column and then the table in the same start-up Apply. +func TestAssertReady_PreRouteMaskMigrationIsTransient(t *testing.T) { + db := readyDB(t) + dropChangeLog(t, db) + mustExec(t, db, `ALTER TABLE transmissions DROP COLUMN route_mask`) + if nr := notReady(t, AssertReady(db)); !nr.Transient() { + t.Fatalf("pre-#93 schema (column and table not created yet) want transient: %v", nr) + } +} + +func TestAssertReady_OtherDefectsArePermanent(t *testing.T) { + for _, tc := range []struct { + name string + stmts []string + want string + }{ + {"another missing column", []string{`ALTER TABLE observations DROP COLUMN raw_hex`}, "observations.raw_hex"}, + {"another missing table", []string{`DROP TABLE node_changes`}, "table:node_changes"}, + {"missing change log plus another missing column", + []string{`DROP TABLE route_mask_changes`, `DELETE FROM _migrations WHERE name = 'route_mask_changes_v1'`, `ALTER TABLE observations DROP COLUMN raw_hex`}, "observations.raw_hex"}, + // The ingestor records the marker in the same transaction as the + // table, and never recreates a table whose marker exists. + {"change-log marker recorded but table gone", []string{`DROP TABLE route_mask_changes`}, "table:route_mask_changes (recorded in _migrations)"}, + {"route_mask column missing although the change log exists", + []string{`ALTER TABLE transmissions DROP COLUMN route_mask`}, "transmissions.route_mask"}, + } { + t.Run(tc.name, func(t *testing.T) { + db := readyDB(t) + for _, q := range tc.stmts { + mustExec(t, db, q) + } + nr := notReady(t, AssertReady(db)) + if nr.Transient() { + t.Fatalf("want permanent: %v", nr) + } + if !strings.Contains(nr.Error(), tc.want) { + t.Fatalf("error does not name %q: %v", tc.want, nr) + } + }) + } +} + +// A change log that exists but does not match the approved definition is a +// broken schema, not a migration in progress: the ingestor creates the table, +// its index and its marker in one transaction. +func TestAssertReady_MalformedChangeLogIsPermanent(t *testing.T) { + for _, tc := range []struct { + name string + ddl []string + want string + }{ + {"no index", []string{CreateRouteMaskChangesTableSQL}, "index:" + RouteMaskChangesTxIndex}, + {"missing column", []string{`CREATE TABLE route_mask_changes (id INTEGER PRIMARY KEY AUTOINCREMENT, transmission_id INTEGER NOT NULL, route_mask INTEGER NOT NULL)`, + CreateRouteMaskChangesIndexSQL}, "route_mask_changes.created_at"}, + {"ids can be reused (no AUTOINCREMENT)", []string{`CREATE TABLE route_mask_changes (id INTEGER PRIMARY KEY, transmission_id INTEGER NOT NULL, route_mask INTEGER NOT NULL, created_at INTEGER NOT NULL)`, + CreateRouteMaskChangesIndexSQL}, "route_mask_changes.id AUTOINCREMENT"}, + {"index on the wrong column", []string{CreateRouteMaskChangesTableSQL, + `CREATE INDEX ` + RouteMaskChangesTxIndex + ` ON route_mask_changes(created_at)`}, "index:" + RouteMaskChangesTxIndex}, + {"composite index", []string{CreateRouteMaskChangesTableSQL, + `CREATE INDEX ` + RouteMaskChangesTxIndex + ` ON route_mask_changes(transmission_id, created_at)`}, "index:" + RouteMaskChangesTxIndex}, + } { + t.Run(tc.name, func(t *testing.T) { + db := readyDB(t) + dropChangeLog(t, db) + for _, q := range tc.ddl { + mustExec(t, db, q) + } + nr := notReady(t, AssertReady(db)) + if nr.Transient() { + t.Fatalf("malformed change log want permanent: %v", nr) + } + if !strings.Contains(nr.Error(), tc.want) { + t.Fatalf("error does not name %q: %v", tc.want, nr) + } + }) + } +} + +// A reader that hits SQLite BUSY while the writer holds an exclusive lock is +// waiting for the ingestor, not looking at a broken schema. +func TestAssertReady_BusyProbeIsTransient(t *testing.T) { + db := readyDB(t) + path := dbPath(t, db) + writer, err := sql.Open("sqlite", "file:"+path) + if err != nil { + t.Fatal(err) + } + defer writer.Close() + writer.SetMaxOpenConns(1) + mustExec(t, writer, `PRAGMA locking_mode=EXCLUSIVE`) + mustExec(t, writer, `BEGIN EXCLUSIVE`) + mustExec(t, writer, `INSERT INTO _migrations (name) VALUES ('busy-probe')`) + reader, err := sql.Open("sqlite", "file:"+path+"?mode=ro&_pragma=busy_timeout(20)") + if err != nil { + t.Fatal(err) + } + defer reader.Close() + nr := notReady(t, AssertReady(reader)) + if !nr.Transient() || len(nr.Probes) == 0 { + t.Fatalf("probe under an exclusive writer lock want transient with probe errors: %v", nr) + } + mustExec(t, writer, `ROLLBACK`) + mustExec(t, writer, `PRAGMA locking_mode=NORMAL`) + mustExec(t, writer, `SELECT 1 FROM _migrations LIMIT 1`) // releases the exclusive lock + writer.Close() + if err := AssertReady(reader); err != nil { + t.Fatalf("after the lock is released: %v", err) + } +} + +// The ingestor creates the route_mask column, the change log and its marker +// while the server checks. Every probe must read one snapshot: a check that +// sees half of a migration (table gone but marker recorded, or column missing +// but table present) calls the in-progress migration permanent, and the +// server exits. +func TestAssertReady_MigrationCommittingMidCheckStaysTransient(t *testing.T) { + for _, tc := range []struct { + name string + preRouteMask bool + commitAfter string + }{ + {"change log committed between the table and marker probes", false, "table:route_mask_changes"}, + {"column and change log committed between the column and table probes", true, "transmissions.route_mask"}, + } { + t.Run(tc.name, func(t *testing.T) { + db := readyDB(t) + // As in production (the ingestor opens with journal_mode(WAL)): + // the writer commits while the server's read snapshot is open. + var mode string + if err := db.QueryRow(`PRAGMA journal_mode=WAL`).Scan(&mode); err != nil || mode != "wal" { + t.Fatalf("journal_mode=WAL: %q, %v", mode, err) + } + dropChangeLog(t, db) + if tc.preRouteMask { + mustExec(t, db, `ALTER TABLE transmissions DROP COLUMN route_mask`) + mustExec(t, db, `DELETE FROM _migrations WHERE name = 'transmissions_route_mask_v1'`) + } + reader, err := sql.Open("sqlite", "file:"+dbPath(t, db)+"?mode=ro") + if err != nil { + t.Fatal(err) + } + defer reader.Close() + committed := false + err = assertReady(reader, func(item string) { + if item != tc.commitAfter || committed { + return + } + committed = true + if err := Apply(db, nil); err != nil { // the ingestor commits mid-check + t.Fatalf("Apply during the check: %v", err) + } + }) + if !committed { + t.Fatalf("probe %q never ran", tc.commitAfter) + } + if nr := notReady(t, err); !nr.Transient() { + t.Fatalf("a migration committing during the check was called permanent: %v", nr) + } + if err := AssertReady(reader); err != nil { + t.Fatalf("next check after the migration: %v", err) + } + }) + } +} + +type codeErr int + +func (c codeErr) Error() string { return fmt.Sprintf("sqlite code %d", int(c)) } +func (c codeErr) Code() int { return int(c) } + +func TestNotReadyError_ProbeErrorClassification(t *testing.T) { + for _, tc := range []struct { + err error + want bool + }{ + {codeErr(5), true}, // SQLITE_BUSY + {codeErr(6), true}, // SQLITE_LOCKED + {codeErr(517), true}, // SQLITE_BUSY_SNAPSHOT + {codeErr(262), true}, // SQLITE_LOCKED_SHAREDCACHE + {fmt.Errorf("probe: %w", codeErr(5)), true}, // wrapped + {codeErr(10), false}, // SQLITE_IOERR + {codeErr(8), false}, // SQLITE_READONLY + {codeErr(3), false}, // SQLITE_PERM + {codeErr(14), false}, // SQLITE_CANTOPEN + {codeErr(11), false}, // SQLITE_CORRUPT + {codeErr(26), false}, // SQLITE_NOTADB + {errors.New("database is locked (5)"), false}, // text only: never classified by string + {sql.ErrConnDone, false}, + } { + nr := &NotReadyError{Missing: []string{"table:route_mask_changes"}, Probes: []ProbeFailure{{Item: "observers.iata", Err: tc.err}}} + if got := nr.Transient(); got != tc.want { + t.Errorf("probe error %v: Transient() = %v, want %v", tc.err, got, tc.want) + } + } + if (&NotReadyError{}).Transient() { + t.Error("an empty NotReadyError must not be transient") + } + // BUSY while probing the change log, column not added yet: still the + // ingestor's in-progress migration. + nr := &NotReadyError{Missing: []string{"transmissions.route_mask"}, Probes: []ProbeFailure{{Item: "table:route_mask_changes", Err: codeErr(5)}}} + if !nr.Transient() { + t.Errorf("column missing and change-log probe BUSY: want transient: %v", nr) + } + // A probe failure is always reported with its item. + if !strings.Contains(nr.Error(), "table:route_mask_changes (probe error: sqlite code 5)") { + t.Errorf("error text %q does not report the probe failure", nr.Error()) + } +} + +// A closed or unusable handle is a permanent failure, not a wait. +func TestAssertReady_ClosedDatabaseIsPermanent(t *testing.T) { + db := readyDB(t) + db.Close() + if nr := notReady(t, AssertReady(db)); nr.Transient() { + t.Fatalf("closed database want permanent: %v", nr) + } +} + +// The change log, its index and its marker appear together: a server never +// sees the table without its index while the ingestor is migrating, and a +// failed creation leaves nothing behind. +func TestApply_ChangeLogCreatedAtomically(t *testing.T) { + db := minimalDB(t) + defer db.Close() + mustExec(t, db, `CREATE TABLE `+RouteMaskChangesTxIndex+` (x INTEGER)`) // the index name is taken + if err := Apply(db, nil); err == nil { + t.Fatal("Apply succeeded although the change-log index could not be created") + } + var n int + db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE name = 'route_mask_changes'`).Scan(&n) + if n != 0 { + t.Fatal("route_mask_changes was left behind without its index") + } + db.QueryRow(`SELECT COUNT(*) FROM _migrations WHERE name = ?`, RouteMaskChangesMigration).Scan(&n) + if n != 0 { + t.Fatal("the change-log marker was recorded although creation failed") + } +} diff --git a/internal/dbschema/route_mask_changes_test.go b/internal/dbschema/route_mask_changes_test.go new file mode 100644 index 000000000..22a237585 --- /dev/null +++ b/internal/dbschema/route_mask_changes_test.go @@ -0,0 +1,89 @@ +package dbschema + +import "testing" + +// PR #93 review: route_mask_changes is the durable change log from the +// ingestor to running servers. A new route bit on an existing transmission +// whose observation row is only upserted (same observer and path, same id) +// is otherwise invisible to a server that polls new ids. + +func TestApplyCreatesRouteMaskChangesTable(t *testing.T) { + db := minimalDB(t) + defer db.Close() + if _, err := db.Exec(`INSERT INTO transmissions (raw_hex, hash, first_seen, route_type) VALUES ('11', 'h1', '2026-09-24T00:00:00Z', 1)`); err != nil { + t.Fatal(err) + } + for i := 0; i < 2; i++ { // idempotent + if err := Apply(db, nil); err != nil { + t.Fatalf("Apply run %d: %v", i+1, err) + } + } + for _, col := range []string{"id", "transmission_id", "route_mask", "created_at"} { + if has, err := TableHasColumn(db, "route_mask_changes", col); err != nil || !has { + t.Fatalf("route_mask_changes.%s missing (err=%v)", col, err) + } + } + var idx int + db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type = 'index' AND name = ?`, RouteMaskChangesTxIndex).Scan(&idx) + if idx != 1 { + t.Fatalf("index %s missing", RouteMaskChangesTxIndex) + } + var marker string + if err := db.QueryRow(`SELECT name FROM _migrations WHERE name = ?`, RouteMaskChangesMigration).Scan(&marker); err != nil { + t.Errorf("migration marker %q not recorded: %v", RouteMaskChangesMigration, err) + } + var n int + db.QueryRow(`SELECT COUNT(*) FROM route_mask_changes`).Scan(&n) + if n != 0 { + t.Errorf("Apply wrote %d change rows; the table must start empty (no backfill of events)", n) + } + var mask interface{} + db.QueryRow(`SELECT route_mask FROM transmissions WHERE hash = 'h1'`).Scan(&mask) + if mask != nil { + t.Errorf("Apply changed an existing transmission: route_mask = %v", mask) + } +} + +// Servers poll the log with an id cursor, so an id must never be reused +// after retention deletes the newest rows. +func TestRouteMaskChangesIDsAreNeverReused(t *testing.T) { + db := minimalDB(t) + defer db.Close() + if err := Apply(db, nil); err != nil { + t.Fatal(err) + } + ins := func() int64 { + res, err := db.Exec(`INSERT INTO route_mask_changes (transmission_id, route_mask, created_at) VALUES (1, 2, 1790244000)`) + if err != nil { + t.Fatal(err) + } + id, _ := res.LastInsertId() + return id + } + ins() + ins() + last := ins() + if _, err := db.Exec(`DELETE FROM route_mask_changes`); err != nil { + t.Fatal(err) + } + if next := ins(); next <= last { + t.Fatalf("id %d reused after deleting up to %d; a server cursor at %d would skip it", next, last, last) + } +} + +func TestAssertReady_RequiresRouteMaskChangesTable(t *testing.T) { + db := minimalDB(t) + defer db.Close() + if err := Apply(db, nil); err != nil { + t.Fatal(err) + } + if err := AssertReady(db); err != nil { + t.Fatalf("AssertReady after Apply: %v", err) + } + if _, err := db.Exec(`DROP TABLE route_mask_changes`); err != nil { + t.Fatal(err) + } + if err := AssertReady(db); err == nil || !contains(err.Error(), "table:route_mask_changes") { + t.Fatalf("AssertReady must name the missing route_mask_changes table, got %v", err) + } +} diff --git a/internal/dbschema/route_mask_test.go b/internal/dbschema/route_mask_test.go new file mode 100644 index 000000000..6190d23bc --- /dev/null +++ b/internal/dbschema/route_mask_test.go @@ -0,0 +1,90 @@ +package dbschema + +import "testing" + +// Issue #89: transmissions.route_mask records every raw route type (0..3) +// observed for a content hash. Apply only adds the column (metadata-only +// ALTER). The partial index that tracks un-backfilled rows is built by the +// ingestor's async backfill after MQTT subscribe, never inside Apply: on a +// staging-sized DB the index build takes 18-19.5 s cold and would otherwise +// run before the subscription exists. + +func TestApplyAddsRouteMaskColumn(t *testing.T) { + db := minimalDB(t) + defer db.Close() + if _, err := db.Exec(`INSERT INTO transmissions (raw_hex, hash, first_seen, route_type) VALUES ('11', 'h1', '2026-09-24T00:00:00Z', 1)`); err != nil { + t.Fatal(err) + } + for i := 0; i < 2; i++ { // idempotent + if err := Apply(db, nil); err != nil { + t.Fatalf("Apply run %d: %v", i+1, err) + } + } + has, err := TableHasColumn(db, "transmissions", "route_mask") + if err != nil || !has { + t.Fatalf("transmissions.route_mask missing after Apply (err=%v)", err) + } + var mask interface{} + if err := db.QueryRow(`SELECT route_mask FROM transmissions WHERE hash = 'h1'`).Scan(&mask); err != nil { + t.Fatal(err) + } + if mask != nil { + t.Errorf("existing row route_mask = %v, want NULL (not yet backfilled; Apply must not invent bits)", mask) + } + var marker string + if err := db.QueryRow(`SELECT name FROM _migrations WHERE name = ?`, RouteMaskColumnMigration).Scan(&marker); err != nil { + t.Errorf("migration marker %q not recorded: %v", RouteMaskColumnMigration, err) + } + var idx int + db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type = 'index' AND name = ?`, RouteMaskPendingIndex).Scan(&idx) + if idx != 0 { + t.Errorf("Apply built %s; the partial index must be built by the async backfill, not at start-up", RouteMaskPendingIndex) + } +} + +func TestAssertReady_RequiresRouteMaskColumn(t *testing.T) { + db := minimalDB(t) + defer db.Close() + if err := Apply(db, nil); err != nil { + t.Fatal(err) + } + if err := AssertReady(db); err != nil { + t.Fatalf("AssertReady after Apply: %v", err) + } + // A DB whose ingestor never added the column: AssertReady must refuse. + if _, err := db.Exec(`ALTER TABLE transmissions DROP COLUMN route_mask`); err != nil { + t.Fatal(err) + } + err := AssertReady(db) + if err == nil || !contains(err.Error(), "transmissions.route_mask") { + t.Fatalf("AssertReady must name the missing transmissions.route_mask, got %v", err) + } +} + +func TestRouteMaskPendingIndexSQL(t *testing.T) { + db := minimalDB(t) + defer db.Close() + if err := Apply(db, nil); err != nil { + t.Fatal(err) + } + for i := 0; i < 2; i++ { // IF NOT EXISTS + if _, err := db.Exec(CreateRouteMaskPendingIndexSQL); err != nil { + t.Fatalf("create pending index run %d: %v", i+1, err) + } + } + var plan string + rows, err := db.Query(`EXPLAIN QUERY PLAN SELECT id FROM transmissions WHERE route_mask IS NULL ORDER BY id LIMIT 100`) + if err != nil { + t.Fatal(err) + } + for rows.Next() { + var id, parent, notused int + var detail string + rows.Scan(&id, &parent, ¬used, &detail) + plan += detail + ";" + } + rows.Close() + if !contains(plan, RouteMaskPendingIndex) { + t.Errorf("pending-row lookup does not use %s: %s", RouteMaskPendingIndex, plan) + } +} diff --git a/internal/packetpath/route.go b/internal/packetpath/route.go index 0ba557bd1..b3e4879d3 100644 --- a/internal/packetpath/route.go +++ b/internal/packetpath/route.go @@ -22,3 +22,52 @@ func IsTransportRoute(routeType int) bool { func PathBytesAreHops(payloadType byte) bool { return payloadType != PayloadTRACE } + +// Route mask bits for transmissions.route_mask (#89): bit r is set when a +// frame carrying raw route type r (header bits 1-0) was observed for the +// transmission's content hash. The mask is monotonic: bits are OR-ed in and +// never cleared. +const ( + RouteMaskFlood = int64(1)<= '0' && c <= '9': + v = c - '0' + case c >= 'a' && c <= 'f': + v = c - 'a' + 10 + case c >= 'A' && c <= 'F': + v = c - 'A' + 10 + default: + return 0, false + } + header = header<<4 | v + } + return RouteTypeFromHeader(header), true +} + +// RouteMaskBit returns the transmissions.route_mask bit for a raw route type, +// or 0 for values outside 0..3 (which must not set any bit). +func RouteMaskBit(routeType int) int64 { + if routeType < RouteTransportFlood || routeType > RouteTransportDirect { + return 0 + } + return int64(1) << uint(routeType) +} diff --git a/internal/packetpath/route_mask_test.go b/internal/packetpath/route_mask_test.go new file mode 100644 index 000000000..8b74cb9a2 --- /dev/null +++ b/internal/packetpath/route_mask_test.go @@ -0,0 +1,60 @@ +package packetpath + +import "testing" + +func TestRouteTypeFromHeader(t *testing.T) { + cases := map[byte]int{ + 0x10: RouteTransportFlood, // ADVERT, transport flood + 0x11: RouteFlood, // ADVERT, flood + 0x12: RouteDirect, // ADVERT, direct + 0x13: RouteTransportDirect, + 0x0c: RouteTransportFlood, // ACK + 0xff: RouteTransportDirect, + } + for header, want := range cases { + if got := RouteTypeFromHeader(header); got != want { + t.Errorf("RouteTypeFromHeader(0x%02x) = %d, want %d", header, got, want) + } + } +} + +func TestRouteTypeFromRawHex(t *testing.T) { + cases := []struct { + raw string + want int + wantOK bool + }{ + {"11", RouteFlood, true}, + {"1302aabb", RouteTransportDirect, true}, + {"1A00", RouteDirect, true}, // upper-case hex + {"10", RouteTransportFlood, true}, + {"", 0, false}, // empty + {"1", 0, false}, // truncated header byte + {"zz", 0, false}, // not hex + {"g1", 0, false}, + } + for _, tc := range cases { + got, ok := RouteTypeFromRawHex(tc.raw) + if ok != tc.wantOK || (ok && got != tc.want) { + t.Errorf("RouteTypeFromRawHex(%q) = (%d, %v), want (%d, %v)", tc.raw, got, ok, tc.want, tc.wantOK) + } + } +} + +func TestRouteMaskBit(t *testing.T) { + want := map[int]int64{0: 1, 1: 2, 2: 4, 3: 8, -1: 0, 4: 0, 99: 0} + for rt, bit := range want { + if got := RouteMaskBit(rt); got != bit { + t.Errorf("RouteMaskBit(%d) = %d, want %d", rt, got, bit) + } + } + if RouteMaskFlood != RouteMaskBit(RouteTransportFlood)|RouteMaskBit(RouteFlood) { + t.Errorf("RouteMaskFlood = %b, want routes 0 and 1", RouteMaskFlood) + } + if RouteMaskDirect != RouteMaskBit(RouteDirect)|RouteMaskBit(RouteTransportDirect) { + t.Errorf("RouteMaskDirect = %b, want routes 2 and 3", RouteMaskDirect) + } + if RouteMaskFlood&RouteMaskDirect != 0 || RouteMaskFlood|RouteMaskDirect != RouteMaskAll { + t.Errorf("flood %b and direct %b must partition all %b", RouteMaskFlood, RouteMaskDirect, RouteMaskAll) + } +} diff --git a/public/analytics.js b/public/analytics.js index c482a8ffc..40c84bca6 100644 --- a/public/analytics.js +++ b/public/analytics.js @@ -566,7 +566,10 @@ var cpct = Number(r.count_pct || 0); var apct = Number(r.airtime_pct || 0); var score = Number(r.score || 0); - var color = palette[i % palette.length]; + // #89: a payload seen on both flood and zero-hop routes is one mixed + // row; it gets a fixed theme colour so it reads the same in any position. + var isMixed = r.route_class === 'mixed'; + var color = isMixed ? 'var(--status-purple)' : palette[i % palette.length]; // Rows are rendered positionally; (type, route_class) is the stable row // identity. The three ADVERT rows share type 4, so type alone is not. var identityAttrs = ' data-payload-type="' + esc(String(Number(r.type))) + '"' + @@ -583,6 +586,7 @@ : scoreMs.toFixed(2) + ' ms'; var tip = name + '\n' + + (isMixed ? 'Same payload observed on both flood and zero-hop routes; counted once.\n' : '') + 'Count: ' + cnt.toLocaleString() + ' (' + cpct.toFixed(2) + '%)\n' + 'Airtime: ' + apct.toFixed(2) + '% (score ' + scoreStr + ' · airtime × repeaters)\n' + 'Score = LoRa Time-on-Air × distinct repeaters. Within-mesh only.'; diff --git a/test-analytics-relay-airtime-dumbbell.js b/test-analytics-relay-airtime-dumbbell.js index 262af5cce..e83a22252 100644 --- a/test-analytics-relay-airtime-dumbbell.js +++ b/test-analytics-relay-airtime-dumbbell.js @@ -151,6 +151,51 @@ if (typeof render === 'function') { assert.deepStrictEqual(rows.map(r => attrOf(r, 'data-route-class')), [null, null, null, null]); }); + // #89: a payload seen on both flood and zero-hop routes is one mixed row. + const mixedResponse = { + rows: [ + { payload_type: 'ADVERT (flood)', type: 4, route_class: 'flood', count: 30, count_pct: 60, score: 6e9, airtime_pct: 75 }, + { payload_type: 'ADVERT (mixed)', type: 4, route_class: 'mixed', count: 5, count_pct: 10, score: 2e9, airtime_pct: 25 }, + { payload_type: 'ADVERT (zero-hop)', type: 4, route_class: 'zero_hop', count: 15, count_pct: 30, score: 0, airtime_pct: 0 }, + ], + total_count: 50, + total_score: 8e9, + }; + + test('mixed ADVERT row renders with its own stable identity', () => { + const rows = rowsOf(render(mixedResponse)); + assert.deepStrictEqual(rows.map(labelOf), ['ADVERT (flood)', 'ADVERT (mixed)', 'ADVERT (zero-hop)']); + assert.deepStrictEqual(rows.map(identityOf), ['4/flood', '4/mixed', '4/zero_hop']); + }); + + test('mixed row uses the theme colour and explains the route mix', () => { + const rows = rowsOf(render(mixedResponse)); + const mixed = rows[1]; + assert.strictEqual(airtimeColourOf(mixed), 'var(--status-purple)'); + assert.ok(!['flood', 'zero_hop'].some((_, i) => airtimeColourOf(rows[i * 2]) === 'var(--status-purple)'), + 'only the mixed row uses the mixed colour'); + const tip = titleOf(mixed); + assert.ok(/both flood and zero-hop routes/.test(tip), 'tooltip explains both routes: ' + tip); + assert.ok(/counted once/.test(tip), 'tooltip says it is counted once: ' + tip); + assert.ok(!/both flood and zero-hop routes/.test(titleOf(rows[0])), 'flood row has no mixed explanation'); + }); + + test('mixed colour and tooltip come from route_class, not the display label', () => { + const relabelled = { rows: [Object.assign({}, mixedResponse.rows[1], { payload_type: 'Advert, both routes' })], total_count: 5, total_score: 2e9 }; + const rows = rowsOf(render(relabelled)); + assert.strictEqual(airtimeColourOf(rows[0]), 'var(--status-purple)'); + assert.ok(/counted once/.test(titleOf(rows[0]))); + const labelOnly = { rows: [Object.assign({}, mixedResponse.rows[0], { payload_type: 'ADVERT (mixed)' })], total_count: 30, total_score: 6e9 }; + assert.notStrictEqual(airtimeColourOf(rowsOf(render(labelOnly))[0]), 'var(--status-purple)', 'a flood row labelled "(mixed)" is not mixed'); + }); + + test('mixed colour does not depend on the row position', () => { + const onlyMixed = { rows: [mixedResponse.rows[1]], total_count: 5, total_score: 2e9 }; + const rows = rowsOf(render(onlyMixed)); + assert.deepStrictEqual(rows.map(identityOf), ['4/mixed']); + assert.strictEqual(airtimeColourOf(rows[0]), 'var(--status-purple)'); + }); + test('rendered chart introduces no element ids', () => { const html = render(splitResponse); assert.ok(!/\sid="/.test(html), 'dumbbell markup must not contain id attributes'); diff --git a/test-e2e-playwright.js b/test-e2e-playwright.js index a307959af..c41685224 100644 --- a/test-e2e-playwright.js +++ b/test-e2e-playwright.js @@ -848,6 +848,71 @@ async function run() { assert(noWinFor(/\/api\/analytics\/hash-collisions/), `hash-collisions must NOT carry window param, saw: ${seen.join(', ')}`); }); + // #89: Relay Airtime Share rows mirror the API rows, and a mixed ADVERT row + // (same payload seen on flood and zero-hop routes) has its own identity, + // fixed colour and tooltip. The fixture DB has no mixed rows, so the second + // half injects one via page.route. + await test('#89 Relay Airtime Share renders API rows and the mixed ADVERT row', async () => { + const relayUrl = '**/api/analytics/relay-airtime-share*'; + const readRows = () => page.$$eval('.dumbbell-row', els => els.map(e => ({ + type: e.getAttribute('data-payload-type'), + routeClass: e.getAttribute('data-route-class'), + label: e.querySelector('.dumbbell-label').textContent, + dot: e.querySelector('.dumbbell-dot-airtime').style.background, + title: e.getAttribute('title'), + }))); + + await page.goto(`${BASE}/#/analytics?tab=overview`, { waitUntil: 'domcontentloaded' }); + await page.reload({ waitUntil: 'load' }); + await page.waitForSelector('.dumbbell-chart, .analytics-card .text-muted', { timeout: 15000 }); + // Re-read exactly the URL the page rendered from (window param included); + // the server caches it and the fixture DB is static. + const api = await page.evaluate(async () => { + const hit = performance.getEntriesByType('resource').map(e => e.name) + .filter(u => /\/api\/analytics\/relay-airtime-share(\?|$)/.test(u)).pop(); + return (await fetch(hit || '/api/analytics/relay-airtime-share')).json(); + }); + assert(api.route_mask_backfill && ['pending', 'backfilling', 'complete'].includes(api.route_mask_backfill.status), + `route_mask_backfill must report a status, got ${JSON.stringify(api.route_mask_backfill)}`); + const real = await readRows(); + if (api.total_score > 0) { + assert(real.length === api.rows.length, `DOM rows ${real.length} != API rows ${api.rows.length}`); + api.rows.forEach((r, i) => { + assert(real[i].type === String(r.type) && real[i].routeClass === r.route_class && real[i].label === (r.payload_type || 'UNK'), + `row ${i}: DOM ${JSON.stringify(real[i])} != API ${JSON.stringify(r)}`); + }); + } + + await page.route(relayUrl, route => route.fulfill({ + status: 200, + contentType: 'application/json', + body: JSON.stringify({ + total_count: 3, total_score: 3000, window: '', cached: false, + route_mask_backfill: { status: 'complete', remaining: 0 }, + rows: [ + { payload_type: 'ADVERT (flood)', type: 4, route_class: 'flood', count: 1, count_pct: 33.3, score: 2000, airtime_pct: 66.7 }, + { payload_type: 'ADVERT (mixed)', type: 4, route_class: 'mixed', count: 1, count_pct: 33.3, score: 1000, airtime_pct: 33.3 }, + { payload_type: 'ADVERT (zero-hop)', type: 4, route_class: 'zero_hop', count: 1, count_pct: 33.3, score: 0, airtime_pct: 0 }, + ], + }), + })); + try { + await page.reload({ waitUntil: 'load' }); + await page.waitForSelector('.dumbbell-row[data-route-class="mixed"]', { timeout: 15000 }); + const rows = await readRows(); + assert(rows.length === 3, `expected 3 injected rows, got ${rows.length}`); + const mixed = rows.find(r => r.routeClass === 'mixed'); + assert(mixed.label === 'ADVERT (mixed)' && mixed.type === '4', `mixed row identity: ${JSON.stringify(mixed)}`); + assert(mixed.dot === 'var(--status-purple)', `mixed row colour must be var(--status-purple), got ${mixed.dot}`); + assert(/observed on both flood and zero-hop routes; counted once/.test(mixed.title), `mixed tooltip: ${mixed.title}`); + rows.filter(r => r.routeClass !== 'mixed').forEach(r => { + assert(!/counted once/.test(r.title), `non-mixed row ${r.label} must not carry the mixed tooltip`); + }); + } finally { + await page.unroute(relayUrl); + } + }); + // Analytics sub-tab tests await test('Analytics RF tab renders content', async () => { await page.click('[data-tab="rf"]');