package database import ( "bytes" "context" "database/sql" "encoding/json" "errors" "fmt" "log/slog" "net/netip" "os" "sync" "testing" "time" "git.eeqj.de/sneak/routewatch/internal/config" "git.eeqj.de/sneak/routewatch/internal/logger" "git.eeqj.de/sneak/routewatch/internal/ristypes" "git.eeqj.de/sneak/routewatch/internal/routetable" "git.eeqj.de/sneak/routewatch/pkg/asinfo" ) // tempStoreMemory is the PRAGMA temp_store value meaning "hold temp B-trees in // memory"; the DSN change must leave temp_store below this so they spill to disk. const tempStoreMemory = 2 // autoVacuumIncremental is the PRAGMA auto_vacuum value meaning "incremental". const autoVacuumIncremental = 2 // vacuumTestRoutes is how many rows of the routes table the vacuum test writes // and then deletes, enough to leave many free pages in the file. const vacuumTestRoutes = 2000 // heldConnections is how many pooled connections the pragma test holds open at // once so each is a distinct SQLite connection that parsed the DSN. const heldConnections = 5 // bytesPerKiB turns a cache_size in KiB into bytes. const bytesPerKiB = 1024 // testPeerIP is the address of the BGP peer the peer write tests store. const testPeerIP = "192.0.2.254" // Parameters for the checkpoint-contention regression test. const ( // contentionIterations is how many batch writes race the checkpoint loop. contentionIterations = 400 // contendedASNCount is the small set of ASNs the batches reuse, so most // batches update existing rows and exercise the read-before-write path. contendedASNCount = 16 // asnSecondBand offsets a second ASN per batch so each batch writes more // than one row. asnSecondBand = 100 ) // Parameters for the tests of maintenance and the database lock. const ( // lockMessageBuffer is how many lock messages a test database's logger // holds before logging waits for the test to read them. lockMessageBuffer = 64 // operationKey is the log attribute that names the operation taking the // lock. operationKey = "operation" // testBatchWrite is the operation name the tests take the lock under. testBatchWrite = "test batch write" // lockWaitTimeout is the context timeout of a maintenance call that the // tests let run out while it waits for the lock. lockWaitTimeout = time.Millisecond // lockTestASN is the AS the batch write in the lock tests stores. lockTestASN = 64500 // lockTestPrefix is the prefix the batch writes in the checkpoint tests // store. lockTestPrefix = "192.0.2.0/24" // readerCheckpointLimit is how long a checkpoint, and a batch write // waiting for it, may take while a reader is open: well under the busy // timeout, which a checkpoint that waits for the reader takes. readerCheckpointLimit = time.Second // truncateCheckpointLimit is how long a checkpoint of a WAL file over // sqliteWALSizeLimitBytes may take to give up while a reader is open: its // wait for the reader plus a second, well under the busy timeout. truncateCheckpointLimit = truncateBusyTimeoutMs*time.Millisecond + time.Second ) // TestConnectionPoolPragmas holds several pooled connections open at once and // checks each one carries the per-connection settings from the DSN, plus the // process-wide heap limits, and sees the new file with auto_vacuum // incremental. func TestConnectionPoolPragmas(t *testing.T) { t.Parallel() cfg := &config.Config{StateDir: t.TempDir()} db, err := New(cfg, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ctx := context.Background() // Hold distinct connections open simultaneously so the pool must open a new // one (each parsing the DSN) rather than hand back the same connection. conns := make([]*sql.Conn, 0, heldConnections) defer func() { for _, c := range conns { _ = c.Close() } }() for i := range heldConnections { c, err := db.db.Conn(ctx) if err != nil { t.Fatalf("failed to open connection %d: %v", i, err) } conns = append(conns, c) } for i, c := range conns { cacheSize := readPragma(ctx, t, c, i, "cache_size") if cacheSize != sqliteReadCacheSizeKiB { t.Errorf("conn %d: cache_size = %d, want %d", i, cacheSize, sqliteReadCacheSizeKiB) } busyTimeout := readPragma(ctx, t, c, i, "busy_timeout") if busyTimeout != sqliteBusyTimeoutMs { t.Errorf("conn %d: busy_timeout = %d, want %d", i, busyTimeout, sqliteBusyTimeoutMs) } tempStore := readPragma(ctx, t, c, i, "temp_store") if tempStore == tempStoreMemory { t.Errorf("conn %d: temp_store = %d, want anything but %d (MEMORY)", i, tempStore, tempStoreMemory) } softHeapLimit := readPragma(ctx, t, c, i, "soft_heap_limit") if softHeapLimit != sqliteSoftHeapLimitBytes { t.Errorf("conn %d: soft_heap_limit = %d, want %d", i, softHeapLimit, sqliteSoftHeapLimitBytes) } hardHeapLimit := readPragma(ctx, t, c, i, "hard_heap_limit") if hardHeapLimit != sqliteHardHeapLimitBytes { t.Errorf("conn %d: hard_heap_limit = %d, want %d", i, hardHeapLimit, sqliteHardHeapLimitBytes) } autoVacuum := readPragma(ctx, t, c, i, "auto_vacuum") if autoVacuum != autoVacuumIncremental { t.Errorf("conn %d: auto_vacuum = %d, want %d (incremental)", i, autoVacuum, autoVacuumIncremental) } } } // TestWritingConnectionCache checks that the connection kept for writing has // the large cache, and that the soft heap limit is above the caches of all the // connections together: SQLite shrinks the caches to stay under it. func TestWritingConnectionCache(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ctx := t.Context() var writeCacheSize, readCacheSize, softHeapLimit int64 err = db.writer.QueryRowContext(ctx, "PRAGMA cache_size"). Scan(&writeCacheSize) if err != nil { t.Fatalf("failed to read the writing connection's cache_size: %v", err) } if writeCacheSize != sqliteWriteCacheSizeKiB { t.Errorf("writing connection: cache_size = %d, want %d", writeCacheSize, sqliteWriteCacheSizeKiB) } err = db.db.QueryRowContext(ctx, "PRAGMA cache_size").Scan(&readCacheSize) if err != nil { t.Fatalf("failed to read a reading connection's cache_size: %v", err) } err = db.db.QueryRowContext(ctx, "PRAGMA soft_heap_limit"). Scan(&softHeapLimit) if err != nil { t.Fatalf("failed to read soft_heap_limit: %v", err) } cachesBytes := -bytesPerKiB * (writeCacheSize + (maxConns-1)*readCacheSize) if softHeapLimit <= cachesBytes { t.Errorf("soft_heap_limit = %d, not above the %d bytes of the caches", softHeapLimit, cachesBytes) } } // TestWritingConnectionWALSizeLimit checks that the connection kept for // writing, the one that writes the WAL, has the WAL size limit, which cuts the // WAL file back when SQLite starts the WAL again from the beginning. func TestWritingConnectionWALSizeLimit(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() var limit int64 err = db.writer.QueryRowContext(t.Context(), "PRAGMA journal_size_limit"). Scan(&limit) if err != nil { t.Fatalf("failed to read the writing connection's journal_size_limit: %v", err) } if limit != sqliteWALSizeLimitBytes { t.Errorf("writing connection: journal_size_limit = %d, want %d", limit, sqliteWALSizeLimitBytes) } } // readPragma reads the integer value of PRAGMA name on connection i, c. func readPragma( ctx context.Context, t *testing.T, c *sql.Conn, i int, name string, ) int64 { t.Helper() var value int64 err := c.QueryRowContext(ctx, "PRAGMA "+name).Scan(&value) if err != nil { t.Fatalf("conn %d: failed to read %s: %v", i, name, err) } return value } // TestVacuumReturnsFreePages checks that after the rows of the routes table // are deleted from a new database, one Vacuum call returns every page they // used. The deletes leave fewer free pages than the 1000 Vacuum frees per // call, so none may remain. With auto_vacuum off (issue // https://git.eeqj.de/sneak/routewatch/issues/43) the free pages stayed in the // file, and with the PRAGMA run by ExecContext Vacuum freed only one page per // call. func TestVacuumReturnsFreePages(t *testing.T) { t.Parallel() cfg := &config.Config{StateDir: t.TempDir()} db, err := New(cfg, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ctx := context.Background() table := routetable.New(routetable.Params{}) for i := range vacuumTestRoutes { announceTo(table, fmt.Sprintf("10.%d.%d.0/24", i/256, i%256), asA, peerA, 0) } writeTableChanges(t, db, table) // The peer going down removes every prefix, and so every row. table.PeerDown(peerA) writeTableChanges(t, db, table) var before int err = db.db.QueryRowContext(ctx, "PRAGMA freelist_count").Scan(&before) if err != nil { t.Fatalf("failed to read freelist_count: %v", err) } if before == 0 { t.Fatalf("no free pages after deleting %d rows", vacuumTestRoutes) } err = db.Vacuum(ctx) if err != nil { t.Fatalf("Vacuum failed: %v", err) } var after int err = db.db.QueryRowContext(ctx, "PRAGMA freelist_count").Scan(&after) if err != nil { t.Fatalf("failed to read freelist_count: %v", err) } if after != 0 { t.Errorf("free pages after Vacuum = %d of %d, want 0", after, before) } } // TestBatchWriteDuringCheckpoint runs checkpoints back to back while batch // writes run and checks that every batch write succeeds: a checkpoint holds the // database lock as a batch write does, and checkpoints must not keep batch // writes from getting it. func TestBatchWriteDuringCheckpoint(t *testing.T) { t.Parallel() cfg := &config.Config{StateDir: t.TempDir()} db, err := New(cfg, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ctx, cancel := context.WithCancel(context.Background()) var wg sync.WaitGroup wg.Go(func() { for { select { case <-ctx.Done(): return default: _ = db.Checkpoint(ctx) // errors are the checkpoint's own to absorb } } }) ts := time.Now().UTC() seen := SeenTimes{First: ts, Last: ts} for i := range contentionIterations { asns := map[int]SeenTimes{ i % contendedASNCount: seen, (i % contendedASNCount) + asnSecondBand: seen, } err := db.GetOrCreateASNBatch(asns) if err != nil { cancel() wg.Wait() t.Fatalf("batch write failed under checkpoint contention: %v", err) } } cancel() wg.Wait() } // lockMessage is a debug message the database lock logged, and the name of the // operation that logged it. type lockMessage struct { text string operation string } // lockMessages is a log handler that passes on each message the database lock // logs. The lock tests read it to know that an operation waits for the lock or // holds it, instead of guessing how long that takes. type lockMessages chan lockMessage // Enabled lets every message through, so the lock's debug messages arrive. func (m lockMessages) Enabled(context.Context, slog.Level) bool { return true } // Handle passes on a message that names an operation and drops the others. func (m lockMessages) Handle(_ context.Context, record slog.Record) error { record.Attrs(func(attr slog.Attr) bool { if attr.Key != operationKey { return true } m <- lockMessage{text: record.Message, operation: attr.Value.String()} return false }) return nil } // WithAttrs returns m: the tests need no attributes added. func (m lockMessages) WithAttrs([]slog.Attr) slog.Handler { return m } // WithGroup returns m: the tests need no groups. func (m lockMessages) WithGroup(string) slog.Handler { return m } // newDatabaseWithLockMessages opens a new database whose logger passes the lock's // messages to the returned channel. func newDatabaseWithLockMessages(t *testing.T) (*Database, lockMessages) { t.Helper() messages := make(lockMessages, lockMessageBuffer) cfg := &config.Config{StateDir: t.TempDir()} db, err := New(cfg, &logger.Logger{Logger: slog.New(messages)}) if err != nil { t.Fatalf("failed to create database: %v", err) } t.Cleanup(func() { _ = db.Close() }) return db, messages } // waitForLockMessage waits until operation logs text, and fails the test if // returned delivers first: the call running operation returned without logging // text. func waitForLockMessage( t *testing.T, messages lockMessages, text, operation string, returned <-chan error, ) { t.Helper() for { select { case message := <-messages: if message.text == text && message.operation == operation { return } case err := <-returned: t.Fatalf("%s returned (error: %v) without logging %q", operation, err, text) } } } // TestVacuumWaitsForBatchWrite holds the database lock as a batch write does and // checks that Vacuum waits for it and then succeeds. Vacuum ran without the // lock, met the batch writes at SQLite's write lock and failed with "database // is locked" (https://git.eeqj.de/sneak/routewatch/issues/94). func TestVacuumWaitsForBatchWrite(t *testing.T) { t.Parallel() db, messages := newDatabaseWithLockMessages(t) db.lock(testBatchWrite) vacuumed := make(chan error, 1) go func() { vacuumed <- db.Vacuum(context.Background()) }() waitForLockMessage(t, messages, lockWaitMessage, "Vacuum", vacuumed) db.unlock() err := <-vacuumed if err != nil { t.Fatalf("Vacuum after the batch write: %v", err) } } // TestBatchWriteWaitsForAnalyze keeps Analyze waiting for SQLite's write lock, // which another connection holds, and checks that a batch write started // meanwhile waits for Analyze to give up the database lock, that both then // succeed, and that Analyze stored statistics. ANALYZE ran without the database // lock, and a batch write that waited longer than the busy timeout for it failed // with "database is locked". func TestBatchWriteWaitsForAnalyze(t *testing.T) { t.Parallel() db, messages := newDatabaseWithLockMessages(t) ctx := context.Background() now := time.Now().UTC() asns := map[int]SeenTimes{lockTestASN: {First: now, Last: now}} // A stored AS gives ANALYZE a table to analyze and statistics to write. err := db.GetOrCreateASNBatch(asns) if err != nil { t.Fatalf("failed to store an AS: %v", err) } // With _txlock=immediate this transaction takes SQLite's write lock at // BEGIN, so ANALYZE has to wait for it while Analyze holds the database lock. writer, err := db.db.BeginTx(ctx, nil) if err != nil { t.Fatalf("failed to begin the transaction ANALYZE waits for: %v", err) } defer func() { _ = writer.Rollback() }() analyzed := make(chan error, 1) go func() { analyzed <- db.Analyze(ctx) }() waitForLockMessage(t, messages, lockHeldMessage, "Analyze", analyzed) written := make(chan error, 1) go func() { written <- db.GetOrCreateASNBatch(asns) }() waitForLockMessage(t, messages, lockWaitMessage, "GetOrCreateASNBatch", written) err = writer.Rollback() if err != nil { t.Fatalf("failed to end the transaction ANALYZE waits for: %v", err) } err = <-analyzed if err != nil { t.Errorf("Analyze: %v", err) } err = <-written if err != nil { t.Errorf("batch write after Analyze: %v", err) } var statistics int err = db.db.QueryRowContext(ctx, "SELECT count(*) FROM sqlite_stat1 WHERE tbl = 'asns'").Scan(&statistics) if err != nil { t.Fatalf("failed to read the statistics: %v", err) } if statistics == 0 { t.Error("Analyze stored no statistics for the asns table") } } // TestCheckpointLockWaitEndsWithContext holds the database lock while the // context of a waiting Checkpoint times out, and checks that Checkpoint then // returns the context's error and leaves the lock free. func TestCheckpointLockWaitEndsWithContext(t *testing.T) { t.Parallel() db, messages := newDatabaseWithLockMessages(t) db.lock(testBatchWrite) ctx, cancel := context.WithTimeout(context.Background(), lockWaitTimeout) defer cancel() checkpointed := make(chan error, 1) go func() { checkpointed <- db.Checkpoint(ctx) }() waitForLockMessage(t, messages, lockWaitMessage, "Checkpoint", checkpointed) <-ctx.Done() db.unlock() err := <-checkpointed if !errors.Is(err, context.DeadlineExceeded) { t.Fatalf("Checkpoint = %v, want %v", err, context.DeadlineExceeded) } if !db.mu.TryLock() { t.Fatal("Checkpoint kept the database lock after its context ended") } db.mu.Unlock() } // TestCheckpointDoesNotWaitForReader keeps a read transaction on prefixes_v4 // open while a prefix is committed, then starts Checkpoint and a batch write // together. It checks that both end within readerCheckpointLimit, whichever of // them takes the database lock first, and that Checkpoint reports the part of // the WAL the reader still needs as left uncopied. A TRUNCATE checkpoint // waited the busy timeout for the reader while holding the lock // (https://git.eeqj.de/sneak/routewatch/issues/102). func TestCheckpointDoesNotWaitForReader(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ctx := context.Background() ts := time.Now().UTC() err = db.UpdatePrefixesBatch(map[string]time.Time{"198.51.100.0/24": ts}) if err != nil { t.Fatalf("failed to store the prefix the reader reads: %v", err) } reader, err := db.db.Conn(ctx) if err != nil { t.Fatalf("failed to open the reading connection: %v", err) } defer func() { _ = reader.Close() }() // A plain BEGIN starts a transaction that only reads, unlike the BEGIN // IMMEDIATE of _txlock. It keeps the snapshot its first read takes until // it ends. _, err = reader.ExecContext(ctx, "BEGIN") if err != nil { t.Fatalf("failed to begin the read transaction: %v", err) } defer func() { _, _ = reader.ExecContext(ctx, "ROLLBACK") }() var prefixes int err = reader.QueryRowContext(ctx, "SELECT count(*) FROM prefixes_v4").Scan(&prefixes) if err != nil { t.Fatalf("failed to read the prefixes: %v", err) } err = db.UpdatePrefixesBatch(map[string]time.Time{"203.0.113.0/24": ts}) if err != nil { t.Fatalf("failed to store a prefix after the read: %v", err) } started := time.Now() checkpointed := make(chan error, 1) go func() { checkpointed <- db.Checkpoint(ctx) }() // A prefix write, not an AS write: the first new AS loads the embedded AS // names, which takes seconds under -race. written := make(chan error, 1) go func() { written <- db.UpdatePrefixesBatch(map[string]time.Time{lockTestPrefix: ts}) }() err = <-checkpointed if !errors.Is(err, ErrCheckpointIncomplete) { t.Errorf("Checkpoint = %v with a reader open, want %v", err, ErrCheckpointIncomplete) } took := time.Since(started) if took >= readerCheckpointLimit { t.Errorf("Checkpoint took %v with a reader open, want under %v", took, readerCheckpointLimit) } err = <-written if err != nil { t.Errorf("batch write during Checkpoint: %v", err) } took = time.Since(started) if took >= readerCheckpointLimit { t.Errorf("batch write during Checkpoint ended after %v, want under %v", took, readerCheckpointLimit) } } // TestCheckpointEmptiesWALOnceNoReadIsOpen fills the WAL file past // sqliteWALSizeLimitBytes while the test holds a read open. With the read // open, it checks that Checkpoint gives up within truncateCheckpointLimit and // reports the checkpoint incomplete, and that a batch write still succeeds. // After the test closes the read, it checks that the next Checkpoint brings // the WAL file under the limit and gives the writing connection its busy // timeout back (https://git.eeqj.de/sneak/routewatch/issues/102). func TestCheckpointEmptiesWALOnceNoReadIsOpen(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ctx := t.Context() reader, err := db.db.Conn(ctx) if err != nil { t.Fatalf("failed to open the reading connection: %v", err) } defer func() { _ = reader.Close() }() // A plain BEGIN starts a transaction that only reads, unlike the BEGIN // IMMEDIATE of _txlock. It keeps the snapshot its first read takes until // it ends, so no checkpoint can copy what is written after that read. _, err = reader.ExecContext(ctx, "BEGIN") if err != nil { t.Fatalf("failed to begin the read transaction: %v", err) } var prefixes int err = reader.QueryRowContext(ctx, "SELECT count(*) FROM prefixes_v4").Scan(&prefixes) if err != nil { t.Fatalf("failed to read the prefixes: %v", err) } fillWALPastLimit(ctx, t, db) started := time.Now() err = db.Checkpoint(ctx) if !errors.Is(err, ErrCheckpointIncomplete) { t.Errorf("Checkpoint = %v with a read open, want %v", err, ErrCheckpointIncomplete) } took := time.Since(started) if took >= truncateCheckpointLimit { t.Errorf("Checkpoint took %v with a read open, want under %v", took, truncateCheckpointLimit) } err = db.UpdatePrefixesBatch( map[string]time.Time{lockTestPrefix: time.Now().UTC()}) if err != nil { t.Errorf("batch write after Checkpoint gave up: %v", err) } _, err = reader.ExecContext(ctx, "ROLLBACK") if err != nil { t.Fatalf("failed to end the read transaction: %v", err) } err = db.Checkpoint(ctx) if err != nil { t.Errorf("Checkpoint with no read open: %v", err) } size := walFileSize(t, db) if size >= sqliteWALSizeLimitBytes { t.Errorf("WAL file of %d bytes after Checkpoint with no read open, "+ "want under %d", size, sqliteWALSizeLimitBytes) } busyTimeout := readPragma(ctx, t, db.writer, 0, "busy_timeout") if busyTimeout != sqliteBusyTimeoutMs { t.Errorf("writing connection: busy_timeout = %d after the checkpoints, "+ "want %d", busyTimeout, sqliteBusyTimeoutMs) } } // fillWALPastLimit writes sqliteWALSizeLimitBytes of random bytes to a table // of the test's own, which with SQLite's page and frame headers leaves the WAL // file of db over the limit, and checks that it does. func fillWALPastLimit(ctx context.Context, t *testing.T, db *Database) { t.Helper() _, err := db.writer.ExecContext(ctx, "CREATE TABLE wal_fill (data BLOB)") if err != nil { t.Fatalf("failed to create the table the test writes to: %v", err) } _, err = db.writer.ExecContext(ctx, "INSERT INTO wal_fill VALUES (randomblob(?))", sqliteWALSizeLimitBytes) if err != nil { t.Fatalf("failed to fill the WAL: %v", err) } size := walFileSize(t, db) if size <= sqliteWALSizeLimitBytes { t.Fatalf("WAL file of %d bytes after the test's write, want over %d", size, sqliteWALSizeLimitBytes) } } // walFileSize returns the size of the WAL file of db. func walFileSize(t *testing.T, db *Database) int64 { t.Helper() wal, err := os.Stat(db.path + walFileSuffix) if err != nil { t.Fatalf("failed to read the WAL file's size: %v", err) } return wal.Size() } // TestStartupCheckpointLogsItsFigures opens a new database, writes a prefix, // and opens the same file again while the first stays open, so that its WAL // file stays. The first open finds no WAL file: it logs a size of 0 and no // warning. The second logs the size of the WAL file the first left, and the // checkpoint's busy flag and frame counts, each under its own name; the // counts read 0 once the checkpoint has emptied the file. // Initialize logged the busy flag as wal_pages and the counts under each // other's names (https://git.eeqj.de/sneak/routewatch/issues/117). func TestStartupCheckpointLogsItsFigures(t *testing.T) { t.Parallel() cfg := &config.Config{StateDir: t.TempDir()} db, lines := openLogged(t, cfg) for _, line := range lines { if line[slog.LevelKey] == slog.LevelWarn.String() { t.Errorf("opening a new database logged a warning: %v", line) } } line := findLine(t, lines, startupCheckpointMessage) if line["wal_bytes"] != 0.0 { t.Errorf("new database: start-up checkpoint logged wal_bytes = %v, "+ "want 0", line["wal_bytes"]) } err := db.UpdatePrefixesBatch( map[string]time.Time{lockTestPrefix: time.Now().UTC()}) if err != nil { t.Fatalf("failed to store a prefix: %v", err) } walBytes := walFileSize(t, db) if walBytes == 0 { t.Fatal("WAL file empty after the prefix write, want frames in it") } _, lines = openLogged(t, cfg) line = findLine(t, lines, startupCheckpointMessage) for _, key := range []string{"busy", "wal_frames", "checkpointed_frames"} { if line[key] != 0.0 { t.Errorf("start-up checkpoint logged %s = %v, want 0", key, line[key]) } } if line["wal_bytes"] != float64(walBytes) { t.Errorf("start-up checkpoint logged wal_bytes = %v, want the %d "+ "bytes the first database left", line["wal_bytes"], walBytes) } } // TestStartupCheckpointWarnsWhenIncomplete keeps a read open on a database // while a prefix is written after the read began, then opens the same file // again. The second open's start-up checkpoint cannot copy the frames written // after the read began, and gives up once the busy timeout has passed. It // checks that the checkpoint is logged as a warning with busy 1 and fewer // frames copied than the WAL holds. func TestStartupCheckpointWarnsWhenIncomplete(t *testing.T) { t.Parallel() cfg := &config.Config{StateDir: t.TempDir()} db, _ := openLogged(t, cfg) ctx := context.Background() reader, err := db.db.Conn(ctx) if err != nil { t.Fatalf("failed to open the reading connection: %v", err) } defer func() { _ = reader.Close() }() // A plain BEGIN starts a transaction that only reads, unlike the BEGIN // IMMEDIATE of _txlock. It keeps the snapshot its first read takes until // it ends. _, err = reader.ExecContext(ctx, "BEGIN") if err != nil { t.Fatalf("failed to begin the read transaction: %v", err) } defer func() { _, _ = reader.ExecContext(ctx, "ROLLBACK") }() var prefixes int err = reader.QueryRowContext(ctx, "SELECT count(*) FROM prefixes_v4").Scan(&prefixes) if err != nil { t.Fatalf("failed to read the prefixes: %v", err) } err = db.UpdatePrefixesBatch( map[string]time.Time{lockTestPrefix: time.Now().UTC()}) if err != nil { t.Fatalf("failed to store a prefix after the read: %v", err) } _, lines := openLogged(t, cfg) line := findLine(t, lines, startupCheckpointIncompleteMessage) if line[slog.LevelKey] != slog.LevelWarn.String() { t.Errorf("start-up checkpoint logged at level %v, want %s", line[slog.LevelKey], slog.LevelWarn) } if line["busy"] != 1.0 { t.Errorf("start-up checkpoint logged busy = %v, want 1", line["busy"]) } walFrames, _ := line["wal_frames"].(float64) checkpointedFrames, _ := line["checkpointed_frames"].(float64) if checkpointedFrames >= walFrames { t.Errorf("start-up checkpoint logged checkpointed_frames = %v and "+ "wal_frames = %v with a read open, want fewer copied than the WAL "+ "holds", line["checkpointed_frames"], line["wal_frames"]) } } // openLogged opens the database of cfg with a logger that writes JSON, and // returns it with the lines it logged while it opened, decoded. func openLogged(t *testing.T, cfg *config.Config) (*Database, []map[string]any) { t.Helper() var logged bytes.Buffer db, err := New(cfg, &logger.Logger{Logger: slog.New(slog.NewJSONHandler(&logged, nil))}) if err != nil { t.Fatalf("failed to open the database: %v", err) } t.Cleanup(func() { _ = db.Close() }) var lines []map[string]any decoder := json.NewDecoder(&logged) for decoder.More() { var line map[string]any err := decoder.Decode(&line) if err != nil { t.Fatalf("failed to decode the log: %v", err) } lines = append(lines, line) } return db, lines } // findLine returns the first of lines logged with message. func findLine( t *testing.T, lines []map[string]any, message string, ) map[string]any { t.Helper() for _, line := range lines { if line[slog.MessageKey] == message { return line } } t.Fatalf("no line %q in the log", message) return nil } // TestGetASReadsTheRecordOrTheBuiltInList asks GetAS for an AS the asns table // holds, one only the AS info lookup holds, and one neither holds. The first // gets its record's seen times, the second its handle and description from the // lookup, and only the third is not known. func TestGetASReadsTheRecordOrTheBuiltInList(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() const ( storedASN = 64500 // a documentation AS, not in the lookup listedASN = 15169 // in the lookup, not stored unknownASN = 4200000001 // in neither ) ts := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) _, err = db.GetOrCreateASN(storedASN, ts) if err != nil { t.Fatalf("GetOrCreateASN: %v", err) } listed, ok := asinfo.Get(listedASN) if !ok { t.Fatalf("AS%d is not in the AS info data", listedASN) } tests := []struct { asn int want ASN wantKnown bool }{ {storedASN, ASN{ASN: storedASN, FirstSeen: ts, LastSeen: ts}, true}, {listedASN, ASN{ ASN: listedASN, Handle: listed.Handle, Description: listed.Description, }, true}, {unknownASN, ASN{ASN: unknownASN}, false}, } for _, tt := range tests { got, known, err := db.GetAS(t.Context(), tt.asn) if err != nil { t.Errorf("GetAS(%d): %v", tt.asn, err) continue } if !got.FirstSeen.Equal(tt.want.FirstSeen) || !got.LastSeen.Equal(tt.want.LastSeen) { t.Errorf("GetAS(%d) seen %v to %v, want %v to %v", tt.asn, got.FirstSeen, got.LastSeen, tt.want.FirstSeen, tt.want.LastSeen) } got.FirstSeen, got.LastSeen = tt.want.FirstSeen, tt.want.LastSeen if *got != tt.want || known != tt.wantKnown { t.Errorf("GetAS(%d) = %+v, known %t; want %+v, known %t", tt.asn, *got, known, tt.want, tt.wantKnown) } } } // TestGetASWHOISReadsTheStoredDetails stores an AS with WHOIS details and asks // GetASWHOIS for it and for an AS the asns table does not hold. The first gets // its stored handle, description and details, and the time they were fetched. // The second gets only its number, although the AS info lookup holds it. func TestGetASWHOISReadsTheStoredDetails(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() const storedASN, unstoredASN = 15169, 13335 _, err = db.GetOrCreateASN(storedASN, time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC)) if err != nil { t.Fatalf("GetOrCreateASN: %v", err) } update := &ASNWHOISUpdate{ ASN: storedASN, ASName: "TEST-AS", OrgName: "Test Org", OrgID: "ORG-1", Address: "1 Test Street", CountryCode: "DE", AbuseEmail: "abuse@test", RIR: "RIPE", } err = db.UpdateASNWHOIS(t.Context(), update) if err != nil { t.Fatalf("UpdateASNWHOIS: %v", err) } got, err := db.GetASWHOIS(t.Context(), storedASN) if err != nil { t.Fatalf("GetASWHOIS(%d): %v", storedASN, err) } want := ASN{ ASN: storedASN, Handle: asinfo.GetHandle(storedASN), Description: asinfo.GetDescription(storedASN), ASName: update.ASName, OrgName: update.OrgName, OrgID: update.OrgID, Address: update.Address, CountryCode: update.CountryCode, AbuseEmail: update.AbuseEmail, RIR: update.RIR, } if got.WHOISUpdatedAt == nil { t.Errorf("GetASWHOIS(%d) has no time the details were fetched", storedASN) } got.WHOISUpdatedAt = nil if *got != want { t.Errorf("GetASWHOIS(%d) = %+v, want %+v", storedASN, *got, want) } got, err = db.GetASWHOIS(t.Context(), unstoredASN) if err != nil || *got != (ASN{ASN: unstoredASN}) { t.Errorf("GetASWHOIS(%d) = %+v, %v; want only the number", unstoredASN, got, err) } } // TestGetPrefixFirstSeenReadsThePrefixTables stores an IPv4 and an IPv6 // prefix and expects GetPrefixFirstSeen to give each its first-seen time, and // the zero time for a prefix that is not stored. func TestGetPrefixFirstSeenReadsThePrefixTables(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() ts := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) stored := map[string]time.Time{ "192.0.2.0/24": ts, testV6Prefix: ts.Add(time.Hour), } err = db.UpdatePrefixesBatch(stored) if err != nil { t.Fatalf("UpdatePrefixesBatch: %v", err) } stored["198.51.100.0/24"] = time.Time{} for prefix, want := range stored { got, err := db.GetPrefixFirstSeen(t.Context(), netip.MustParsePrefix(prefix)) if err != nil || !got.Equal(want) { t.Errorf("GetPrefixFirstSeen(%s) = %v, %v; want %v", prefix, got, err, want) } } } // TestUpdatePrefixesBatchKeepsFirstSeen writes a prefix, then a batch with it // and a new prefix. Only the new prefix is inserted and counted, and the known // one keeps its first_seen time. func TestUpdatePrefixesBatchKeepsFirstSeen(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() const known = "198.51.100.0/24" first := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) later := first.Add(time.Hour) err = db.UpdatePrefixesBatch(map[string]time.Time{known: first}) if err != nil { t.Fatalf("UpdatePrefixesBatch: %v", err) } err = db.UpdatePrefixesBatch(map[string]time.Time{ known: later, testV6Prefix: later, }) if err != nil { t.Fatalf("UpdatePrefixesBatch: %v", err) } stats, err := db.GetStats() if err != nil { t.Fatalf("GetStats: %v", err) } if stats.IPv4Prefixes != 1 || stats.IPv6Prefixes != 1 { t.Errorf("prefix counts = (v4 %d, v6 %d), want (1, 1)", stats.IPv4Prefixes, stats.IPv6Prefixes) } for _, tt := range []struct { query, prefix string firstSeen time.Time }{ { query: "SELECT first_seen FROM prefixes_v4 WHERE prefix = ?", prefix: known, firstSeen: first, }, { query: "SELECT first_seen FROM prefixes_v6 WHERE prefix = ?", prefix: testV6Prefix, firstSeen: later, }, } { var firstSeen time.Time err := db.db.QueryRowContext(t.Context(), tt.query, tt.prefix). Scan(&firstSeen) if err != nil { t.Fatalf("reading %s: %v", tt.prefix, err) } if !firstSeen.Equal(tt.firstSeen) { t.Errorf("%s: first seen %s, want %s", tt.prefix, firstSeen, tt.firstSeen) } } } // TestUpdatePeerBatchStoresTheEarliestAndLatestTimesOfANewPeer writes a new // peer whose updates span 5 seconds. Its row is first seen at the earliest time // and last seen at the latest. func TestUpdatePeerBatchStoresTheEarliestAndLatestTimesOfANewPeer( t *testing.T, ) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() first := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) last := first.Add(5 * time.Second) err = db.UpdatePeerBatch(map[string]PeerUpdate{ testPeerIP: { PeerIP: testPeerIP, PeerASN: 64500, MessageType: "UPDATE", Seen: SeenTimes{First: first, Last: last}, }, }) if err != nil { t.Fatalf("UpdatePeerBatch: %v", err) } var firstSeen, lastSeen time.Time err = db.db.QueryRowContext(t.Context(), "SELECT first_seen, last_seen FROM bgp_peers WHERE peer_ip = ?", testPeerIP).Scan(&firstSeen, &lastSeen) if err != nil { t.Fatalf("reading peer %s: %v", testPeerIP, err) } if !firstSeen.Equal(first) || !lastSeen.Equal(last) { t.Errorf("peer %s: first seen %s, last seen %s; want %s, %s", testPeerIP, firstSeen, lastSeen, first, last) } } // backlogAge is how much older one write is than the other in the tests of // first_seen and last_seen, as when a collector catches up on a backlog. const backlogAge = 24 * time.Hour // batchSpan is how much earlier a batch's First is than its Last in the tests // of first_seen and last_seen. const batchSpan = time.Hour // TestWritesKeepEarliestFirstSeenAndLatestLastSeen writes a row of each of // asns, peerings and bgp_peers through each function that writes one, at a // newer time and at an older one. Each row takes the older write's First as // first_seen and the newer write's Last as last_seen. The test writes in both // orders, each in a database of its own. Newer then older is a collector // catching up on a backlog; older then newer is a feed that arrives in order. // Each function writes a row of its own. A batch write's First is batchSpan // before its Last, so the test catches the two swapped. A single-row write // takes one time. func TestWritesKeepEarliestFirstSeenAndLatestLastSeen(t *testing.T) { t.Parallel() const ( batchASN, singleASN = 64500, 64501 peerASN = 64502 asnQuery = "SELECT first_seen, last_seen FROM asns WHERE asn = ?" peeringQuery = "SELECT first_seen, last_seen FROM peerings " + "WHERE as_a = ? AND as_b = ?" peerQuery = "SELECT first_seen, last_seen FROM bgp_peers " + "WHERE peer_ip = ?" ) for name, olderFirst := range map[string]bool{ "newer then older": false, "older then newer": true, } { t.Run(name, func(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() checkSeenTimes(t, db, olderFirst, func(seen SeenTimes) error { return db.GetOrCreateASNBatch(map[int]SeenTimes{batchASN: seen}) }, batchSpan, asnQuery, batchASN) checkSeenTimes(t, db, olderFirst, func(seen SeenTimes) error { _, err := db.GetOrCreateASN(singleASN, seen.Last) return err }, 0, asnQuery, singleASN) checkSeenTimes(t, db, olderFirst, func(seen SeenTimes) error { return db.RecordPeering(batchASN, singleASN, seen) }, batchSpan, peeringQuery, batchASN, singleASN) checkSeenTimes(t, db, olderFirst, func(seen SeenTimes) error { return db.UpdatePeerBatch(map[string]PeerUpdate{ testV4PeerIP: { PeerIP: testV4PeerIP, PeerASN: peerASN, MessageType: ristypes.MessageTypeUpdate, Seen: seen, }, }) }, batchSpan, peerQuery, testV4PeerIP) checkSeenTimes(t, db, olderFirst, func(seen SeenTimes) error { return db.UpdatePeer(testPeerIP, peerASN, ristypes.MessageTypeUpdate, seen.Last) }, 0, peerQuery, testPeerIP) }) } } // checkSeenTimes calls write twice, each time with First span before Last: at // newer times and at times backlogAge older. It writes the older times first // when olderFirst is true. It checks that query, given args, reads the older // write's First as first_seen and the newer write's Last as last_seen. func checkSeenTimes( t *testing.T, db *Database, olderFirst bool, write func(seen SeenTimes) error, span time.Duration, query string, args ...any, ) { t.Helper() newerLast := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) newer := SeenTimes{First: newerLast.Add(-span), Last: newerLast} older := SeenTimes{ First: newer.First.Add(-backlogAge), Last: newer.Last.Add(-backlogAge), } writes := []SeenTimes{newer, older} if olderFirst { writes = []SeenTimes{older, newer} } for _, seen := range writes { err := write(seen) if err != nil { t.Fatalf("writing first %s, last %s: %v", seen.First, seen.Last, err) } } var firstSeen, lastSeen time.Time err := db.db.QueryRowContext(t.Context(), query, args...). Scan(&firstSeen, &lastSeen) if err != nil { t.Fatalf("reading the row: %v", err) } if !firstSeen.Equal(older.First) || !lastSeen.Equal(newer.Last) { t.Errorf("first seen %s, last seen %s; want %s, %s", firstSeen, lastSeen, older.First, newer.Last) } } // TestGetOrCreateASNReturnsStoredSeenTimes stores an AS at a newer time, then // at an older one. The second call returns the times the row now holds: the // older first_seen and the newer last_seen. func TestGetOrCreateASNReturnsStoredSeenTimes(t *testing.T) { t.Parallel() db, err := New(&config.Config{StateDir: t.TempDir()}, logger.New()) if err != nil { t.Fatalf("failed to create database: %v", err) } defer func() { _ = db.Close() }() const asn = 64500 newer := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC) older := newer.Add(-backlogAge) _, err = db.GetOrCreateASN(asn, newer) if err != nil { t.Fatalf("GetOrCreateASN at %s: %v", newer, err) } got, err := db.GetOrCreateASN(asn, older) if err != nil { t.Fatalf("GetOrCreateASN at %s: %v", older, err) } if !got.FirstSeen.Equal(older) || !got.LastSeen.Equal(newer) { t.Errorf("first seen %s, last seen %s; want %s, %s", got.FirstSeen, got.LastSeen, older, newer) } }