From 946c8a4b418a5f07a98a9f3e35d10e6c72f40dc3 Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Tue, 27 Oct 2026 22:22:01 +0000 Subject: [PATCH] Make the routewatch tests pass on a loaded host (closes #213) Five prefix handler tests gave HandleMessage two seconds to apply a full batch of 25,000 prefixes, which under the race detector on a loaded host takes longer. A test now waits up to stepTimeout, 15 seconds, for each step it expects. The slowest tests filled production limits, such as the peering handler's 500,000 paths. The peering handler now takes its path limit, and the prefix handler its limit on one write of the table's changes, as they take their timer interval. Those tests give small limits, and the tests of the maximum batch size lower it to one batch. This also fixes https://git.eeqj.de/sneak/routewatch/issues/215. The test helpers bound every wait, Stop included, so a test that hangs in one fails with its own message. Model: opus-5-5 --- TODO.md | 6 ++ .../app_integration_internal_test.go | 37 +++----- internal/routewatch/ashandler.go | 23 +++-- .../routewatch/ashandler_internal_test.go | 4 +- .../routewatch/asnfetcher_internal_test.go | 8 +- .../routewatch/batchwrite_internal_test.go | 94 +++++++++++++------ .../routewatch/dbmaintainer_internal_test.go | 4 +- internal/routewatch/peerhandler.go | 23 +++-- .../routewatch/peerhandler_internal_test.go | 2 +- internal/routewatch/peeringhandler.go | 25 +++-- .../peeringhandler_internal_test.go | 49 ++++++---- internal/routewatch/prefixhandler.go | 50 ++++++---- .../routewatch/prefixhandler_internal_test.go | 15 +-- .../prefixhandler_table_internal_test.go | 37 +++++--- 14 files changed, 234 insertions(+), 143 deletions(-) diff --git a/TODO.md b/TODO.md index d581f10..86d7452 100644 --- a/TODO.md +++ b/TODO.md @@ -35,6 +35,12 @@ tested. # Completed Steps +- 2026-10-27: the tests of `internal/routewatch` no longer fail on a loaded + host. Five of them gave `HandleMessage` two seconds to apply a full prefix + batch, which under the race detector can take longer. A test now waits up to + 15 seconds for each step it expects. The tests of the handlers' limits give + the handlers small ones, so the package no longer runs past its 90-second + limit (closes #213, #215) - 2026-10-27: the server works out the home page's cards every minute until it stops. It used to work them out only once, at startup: the end of the context that `Start` is given stopped the refreshes (closes #211) diff --git a/internal/routewatch/app_integration_internal_test.go b/internal/routewatch/app_integration_internal_test.go index 15b3b61..8c1d10e 100644 --- a/internal/routewatch/app_integration_internal_test.go +++ b/internal/routewatch/app_integration_internal_test.go @@ -509,8 +509,6 @@ func announcementFeed(prefixes []string) string { func TestShutdownWritesTheUpdatesQueuedInTheStreamer(t *testing.T) { t.Parallel() - const maxWait = 10 * time.Second - prefixes := []string{"192.0.2.0/24", "198.51.100.0/24", "203.0.113.0/24"} feed := announcementFeed(prefixes) @@ -556,9 +554,9 @@ func TestShutdownWritesTheUpdatesQueuedInTheStreamer(t *testing.T) { for range cap(linesSeen) { select { case <-linesSeen: - case <-time.After(maxWait): + case <-time.After(stepTimeout): t.Fatalf("the streamer did not read %d lines within %s", - cap(linesSeen), maxWait) + cap(linesSeen), stepTimeout) } } @@ -571,8 +569,8 @@ func TestShutdownWritesTheUpdatesQueuedInTheStreamer(t *testing.T) { select { case <-shutDown: - case <-time.After(maxWait): - t.Fatalf("Shutdown did not return within %s", maxWait) + case <-time.After(stepTimeout): + t.Fatalf("Shutdown did not return within %s", stepTimeout) } store.mu.Lock() @@ -609,21 +607,16 @@ func freePort(t *testing.T) int { return addr.Port } -// TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked starts the HTTP server -// and has the AS handler start a write that the store holds until the test -// ends, past Shutdown's deadline. Shutdown must return within its deadline -// plus a small margin, with the HTTP server stopped, and must neither -// checkpoint nor close the database: the real one would wait for the write. +// TestShutdownDoesNotWaitForABlockedWrite starts the HTTP server and has the +// AS handler start a write that the store holds until the test ends, past +// Shutdown's deadline. Shutdown must return without waiting for the write, with +// the HTTP server stopped, and must neither checkpoint nor close the database: +// the real one would wait for the write. // Before the fix Shutdown waited for the write. -func TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked(t *testing.T) { +func TestShutdownDoesNotWaitForABlockedWrite(t *testing.T) { t.Parallel() - const ( - deadline = 100 * time.Millisecond - // margin is how long Shutdown may take after its deadline, to stop - // the HTTP server. - margin = 2 * time.Second - ) + const deadline = 100 * time.Millisecond blocking := newBlockingStore() defer blocking.releaseWrites() @@ -667,9 +660,9 @@ func TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked(t *testing.T) { select { case <-shutDown: - case <-time.After(deadline + margin): + case <-time.After(deadline + stepTimeout): t.Fatalf("Shutdown did not return within %s of its deadline while "+ - "a write was blocked", margin) + "a write was blocked", stepTimeout) } var dialer net.Dialer @@ -744,8 +737,6 @@ func (s *closeOrderStore) record(call string) { func TestShutdownCheckpointsAndClosesTheDatabaseLast(t *testing.T) { t.Parallel() - const deadline = 10 * time.Second - store := &closeOrderStore{Store: newMockStore()} log := logger.New() cfg := &config.Config{} @@ -763,7 +754,7 @@ func TestShutdownCheckpointsAndClosesTheDatabaseLast(t *testing.T) { Path: ristypes.ASPath{Sequence: []int{testASNA}}, }) - ctx, cancel := context.WithTimeout(t.Context(), deadline) + ctx, cancel := context.WithTimeout(t.Context(), stepTimeout) defer cancel() rw.Shutdown(ctx) diff --git a/internal/routewatch/ashandler.go b/internal/routewatch/ashandler.go index 5370bb0..fa8faa6 100644 --- a/internal/routewatch/ashandler.go +++ b/internal/routewatch/ashandler.go @@ -40,9 +40,13 @@ type ASHandler struct { db database.Store logger *logger.Logger + // batchMaxSize is asnBatchMaxSize. Only HandleMessage reads it, so a test + // may lower it before it hands the handler a message. + batchMaxSize int + // Batching. mu guards batch and writing only: the flush goroutine takes // the batch under mu and writes it after releasing mu, so HandleMessage - // waits for a database write only while batch is at asnBatchMaxSize. + // waits for a database write only while batch is at batchMaxSize. mu sync.Mutex batch []asnOp // writing is how many operations the flush goroutine took from batch @@ -79,12 +83,13 @@ func newASHandler( db database.Store, logger *logger.Logger, batchTimeout time.Duration, ) *ASHandler { h := &ASHandler{ - db: db, - logger: logger, - batch: make([]asnOp, 0, asnBatchSize), - batchFullCh: make(chan struct{}, 1), - stopCh: make(chan context.Context, 1), - done: make(chan struct{}), + db: db, + logger: logger, + batchMaxSize: asnBatchMaxSize, + batch: make([]asnOp, 0, asnBatchSize), + batchFullCh: make(chan struct{}, 1), + stopCh: make(chan context.Context, 1), + done: make(chan struct{}), } h.batchTaken.L = &h.mu @@ -127,7 +132,7 @@ func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) { // While the batch is at its maximum size, wait until the flush goroutine // takes it. Meanwhile the handler takes nothing off its queue, which // fills, and the streamer drops messages for it. - for len(h.batch) >= asnBatchMaxSize { + for len(h.batch) >= h.batchMaxSize { h.batchTaken.Wait() } @@ -151,7 +156,7 @@ func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) { // A full batch wakes the flush goroutine. If it is writing, the wake-up // waits in batchFullCh and the batch keeps growing until the write ends - // or the batch reaches asnBatchMaxSize. + // or the batch reaches batchMaxSize. if len(h.batch) >= asnBatchSize { select { case h.batchFullCh <- struct{}{}: diff --git a/internal/routewatch/ashandler_internal_test.go b/internal/routewatch/ashandler_internal_test.go index 3e028d0..dffadc6 100644 --- a/internal/routewatch/ashandler_internal_test.go +++ b/internal/routewatch/ashandler_internal_test.go @@ -19,7 +19,7 @@ func TestASHandlerStoresTheEarliestAndLatestTimesOfANewAS(t *testing.T) { db := newTestDatabase(t) // Built without NewASHandler's flush goroutine, so the test flushes itself. - h := &ASHandler{db: db, logger: logger.New()} + h := &ASHandler{db: db, logger: logger.New(), batchMaxSize: asnBatchMaxSize} first := peerAnnouncement(testPeerIP, testV4Prefix) second := peerAnnouncement(testPeerIP, testV4Prefix) @@ -54,7 +54,7 @@ func TestASHandlerRecordsNothingFromAPathWithASZero(t *testing.T) { store := newMockStore() // Built without NewASHandler's flush goroutine, so the test flushes itself. - h := &ASHandler{db: store, logger: logger.New()} + h := &ASHandler{db: store, logger: logger.New(), batchMaxSize: asnBatchMaxSize} msg := peerAnnouncement(testPeerIP, testV4Prefix) msg.Path = decodePath(t, testASNA, 0, testASNB) diff --git a/internal/routewatch/asnfetcher_internal_test.go b/internal/routewatch/asnfetcher_internal_test.go index 6779d3d..9e2214f 100644 --- a/internal/routewatch/asnfetcher_internal_test.go +++ b/internal/routewatch/asnfetcher_internal_test.go @@ -224,7 +224,7 @@ func TestASNFetcherStopReturnsByItsDeadline(t *testing.T) { select { case <-lookupStarted: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the fetcher did not start the lookup") } @@ -240,22 +240,22 @@ func TestASNFetcherStopReturnsByItsDeadline(t *testing.T) { select { case <-f.done: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the fetcher goroutine did not return after the lookup ended") } } // TestRecordKeepsOnlyTheStatsWindow records a success and a failure every -// second, by a clock the test sets, far longer than statsWindow, and never +// second, by a clock the test sets, for three times statsWindow, and never // asks for the stats. The fetcher must keep only the times within the last // statsWindow. func TestRecordKeepsOnlyTheStatsWindow(t *testing.T) { t.Parallel() const ( - records = 100_000 step = time.Second want = int(statsWindow / step) + records = 3 * want ) clock := time.Now() diff --git a/internal/routewatch/batchwrite_internal_test.go b/internal/routewatch/batchwrite_internal_test.go index e196fb9..0f29c84 100644 --- a/internal/routewatch/batchwrite_internal_test.go +++ b/internal/routewatch/batchwrite_internal_test.go @@ -19,9 +19,15 @@ import ( ) const ( - // handleMessageTimeout is how long a test waits for HandleMessage to - // return, or for a write to start, before it fails. - handleMessageTimeout = 2 * time.Second + // stepTimeout is how long a test waits for a step it expects, such as + // HandleMessage returning, a write starting or Shutdown returning, before + // it fails. Only a step that never comes should reach it. On a loaded + // host, under the race detector, HandleMessage takes seconds to apply a + // full prefix batch. The helpers below bound every wait with it, Stop + // included. A test that hangs in one of them waits out at most two of + // these bounds, its step's and Stop's, and then fails with its own + // message. That leaves time before go test's 90-second timeout. + stepTimeout = 15 * time.Second // stillWaitingAfter is how long a test watches a HandleMessage that must // wait. One that does not wait returns well within it. @@ -198,7 +204,7 @@ func lastLogged(t *testing.T, logs *bytes.Buffer) stopLog { return logged } -// returnsInTime reports whether f returns within handleMessageTimeout. +// returnsInTime reports whether f returns within stepTimeout. func returnsInTime(f func()) bool { done := make(chan struct{}) @@ -210,11 +216,22 @@ func returnsInTime(f func()) bool { select { case <-done: return true - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): return false } } +// stopInTime stops h, with no deadline, and fails the test if Stop does not +// return within stepTimeout. It only marks the test failed, so it can be +// deferred. +func stopInTime(t *testing.T, h interface{ Stop(ctx context.Context) }) { + t.Helper() + + if !returnsInTime(func() { h.Stop(t.Context()) }) { + t.Errorf("Stop did not return within %s", stepTimeout) + } +} + // startBlockedWrite hands h the messages in fill and waits until h starts to // write them to store. The prefix, AS and peer handlers start when fill fills // their batch, and the peering handler on its timer. store holds the write @@ -240,7 +257,7 @@ func startBlockedWrite( select { case <-store.writeStarted: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the handler did not start to write the messages") } } @@ -261,7 +278,7 @@ func handleWhileAWriteIsBlocked( ) { t.Helper() - defer h.Stop(t.Context()) + defer stopInTime(t, h) defer store.releaseWrites() startBlockedWrite(t, store, h, fill) @@ -275,7 +292,9 @@ func handleWhileAWriteIsBlocked( // while store holds the write, hands h the messages in toMax, which bring its // next batch to its maximum size, and the message extra. HandleMessage for // extra must wait until the test lets the write finish, and return after. Then -// it stops h, which writes what it holds. +// it stops h, which writes what it holds. The tests lower h's maximum batch +// size to one batch, so toMax is one batch: the real maximum of ten batches is +// slow to reach under the race detector. func handleAtMaxBatchSize( t *testing.T, store *blockingStore, @@ -288,13 +307,18 @@ func handleAtMaxBatchSize( ) { t.Helper() - defer h.Stop(t.Context()) + defer stopInTime(t, h) defer store.releaseWrites() startBlockedWrite(t, store, h, fill) - for _, msg := range toMax { - h.HandleMessage(msg) + if !returnsInTime(func() { + for _, msg := range toMax { + h.HandleMessage(msg) + } + }) { + t.Fatal("HandleMessage did not return while the batch grew to its " + + "maximum size") } returned := make(chan struct{}) @@ -315,7 +339,7 @@ func handleAtMaxBatchSize( select { case <-returned: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("HandleMessage did not return after the database write finished") } } @@ -345,8 +369,12 @@ func stopWhileAWriteIsBlocked( startBlockedWrite(t, store, h, fill) - for _, msg := range extra { - h.HandleMessage(msg) + if !returnsInTime(func() { + for _, msg := range extra { + h.HandleMessage(msg) + } + }) { + t.Fatal("HandleMessage did not return while a database write was blocked") } ctx, cancel := context.WithTimeout(t.Context(), stopDeadline) @@ -361,7 +389,7 @@ func stopWhileAWriteIsBlocked( select { case <-done: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the flush goroutine did not return after the write finished") } } @@ -380,7 +408,8 @@ func TestPrefixHandlerSkipsItsLastWriteAfterTheStopDeadline(t *testing.T) { store := newBlockingStore() h := newPrefixHandler(store, newErrorLogger(&logs), - routetable.New(routetable.Params{}), longerThanAnyTest) + routetable.New(routetable.Params{}), longerThanAnyTest, + maxTableChangesPerWrite) fill := slices.Repeat([]string{testV4Prefix}, prefixBatchSize) stopWhileAWriteIsBlocked(t, store, h, h.done, []*ristypes.RISMessage{prefixAnnouncement(fill)}, @@ -597,7 +626,7 @@ func TestPeeringHandlerStopCountsTheWriteInProgress(t *testing.T) { select { case <-h.done: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the processing goroutine did not return after the write " + "finished") } @@ -618,7 +647,7 @@ func TestPeeringHandlerStartsNoWriteAfterTheStopDeadline(t *testing.T) { const processInterval = 10 * time.Millisecond store := newBlockingStore() - h := newPeeringHandler(store, logger.New(), processInterval) + h := newPeeringHandler(store, logger.New(), processInterval, maxTrackedPaths) stopWhileAWriteIsBlocked(t, store, h, h.done, []*ristypes.RISMessage{ {Path: ristypes.ASPath{Sequence: []int{testASNA, testASNB}}}, @@ -714,9 +743,11 @@ func TestPrefixHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { const extraPrefix = "198.51.100.0/24" store := newBlockingStore() - h := NewPrefixHandler(store, logger.New(), routetable.New(routetable.Params{})) + h := newPrefixHandler(store, logger.New(), routetable.New(routetable.Params{}), + longerThanAnyTest, maxTableChangesPerWrite) + h.batchMaxSize = prefixBatchSize fill := slices.Repeat([]string{testV4Prefix}, prefixBatchSize) - toMax := slices.Repeat([]string{testV4Prefix}, prefixBatchMaxSize) + toMax := slices.Repeat([]string{testV4Prefix}, prefixBatchSize) handleAtMaxBatchSize(t, store, h, []*ristypes.RISMessage{prefixAnnouncement(fill)}, []*ristypes.RISMessage{prefixAnnouncement(toMax)}, @@ -736,8 +767,9 @@ func TestASHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { store := newBlockingStore() h := newASHandler(store, logger.New(), longerThanAnyTest) + h.batchMaxSize = asnBatchSize fill := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)} - toMax := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchMaxSize)} + toMax := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)} handleAtMaxBatchSize(t, store, h, []*ristypes.RISMessage{{Path: fill}}, []*ristypes.RISMessage{{Path: toMax}}, @@ -755,7 +787,7 @@ func TestASHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { // TestPeerHandlerWaitsAtTheMaximumBatchSize must not have its flush timer fire. // A timer flush during the fill would take only part of it. The batch would // then reach its maximum size before the test's last message, and the test -// would hang. +// would fail. func TestPeerHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { t.Parallel() @@ -763,10 +795,11 @@ func TestPeerHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { store := newBlockingStore() h := newPeerHandler(store, logger.New(), longerThanAnyTest) + h.batchMaxSize = peerBatchSize message := []*ristypes.RISMessage{{Peer: testPeerIP}} handleAtMaxBatchSize(t, store, h, slices.Repeat(message, peerBatchSize), - slices.Repeat(message, peerBatchMaxSize), + slices.Repeat(message, peerBatchSize), &ristypes.RISMessage{Peer: otherPeerIP}) store.mu.Lock() @@ -796,8 +829,9 @@ func TestHandlersWakeTheFlushGoroutineWhenTheBatchIsFull(t *testing.T) { batchSize: prefixBatchSize, handle: func(n int) chan struct{} { h := &PrefixHandler{ - batchFullCh: make(chan struct{}, 1), - table: routetable.New(routetable.Params{}), + batchMaxSize: prefixBatchMaxSize, + batchFullCh: make(chan struct{}, 1), + table: routetable.New(routetable.Params{}), } h.HandleMessage(prefixAnnouncement( slices.Repeat([]string{testV4Prefix}, n))) @@ -809,7 +843,10 @@ func TestHandlersWakeTheFlushGoroutineWhenTheBatchIsFull(t *testing.T) { name: "AS", batchSize: asnBatchSize, handle: func(n int) chan struct{} { - h := &ASHandler{batchFullCh: make(chan struct{}, 1)} + h := &ASHandler{ + batchMaxSize: asnBatchMaxSize, + batchFullCh: make(chan struct{}, 1), + } // The origin AS and each AS in the path are one update each. h.HandleMessage(&ristypes.RISMessage{ Path: ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, n-1)}, @@ -822,7 +859,10 @@ func TestHandlersWakeTheFlushGoroutineWhenTheBatchIsFull(t *testing.T) { name: "peer", batchSize: peerBatchSize, handle: func(n int) chan struct{} { - h := &PeerHandler{batchFullCh: make(chan struct{}, 1)} + h := &PeerHandler{ + batchMaxSize: peerBatchMaxSize, + batchFullCh: make(chan struct{}, 1), + } for range n { h.HandleMessage(&ristypes.RISMessage{Peer: testPeerIP}) } diff --git a/internal/routewatch/dbmaintainer_internal_test.go b/internal/routewatch/dbmaintainer_internal_test.go index 6889580..5b0dd21 100644 --- a/internal/routewatch/dbmaintainer_internal_test.go +++ b/internal/routewatch/dbmaintainer_internal_test.go @@ -97,7 +97,7 @@ func TestDBMaintainerStopReturnsByItsDeadline(t *testing.T) { select { case <-store.started: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the maintainer did not start the checkpoint") } @@ -113,7 +113,7 @@ func TestDBMaintainerStopReturnsByItsDeadline(t *testing.T) { select { case <-m.done: - case <-time.After(handleMessageTimeout): + case <-time.After(stepTimeout): t.Fatal("the maintenance goroutine did not return after the " + "checkpoint ended") } diff --git a/internal/routewatch/peerhandler.go b/internal/routewatch/peerhandler.go index b15a58e..641be9c 100644 --- a/internal/routewatch/peerhandler.go +++ b/internal/routewatch/peerhandler.go @@ -43,10 +43,14 @@ type PeerHandler struct { db database.Store logger *logger.Logger + // batchMaxSize is peerBatchMaxSize. Only HandleMessage reads it, so a test + // may lower it before it hands the handler a message. + batchMaxSize int + // Batching. mu guards peerBatch and writing only: the flush goroutine // takes the batch under mu and writes it after releasing mu, so // HandleMessage waits for a database write only while peerBatch is at - // peerBatchMaxSize. + // batchMaxSize. mu sync.Mutex peerBatch []peerUpdate // writing is how many updates the flush goroutine took from peerBatch @@ -84,12 +88,13 @@ func newPeerHandler( db database.Store, logger *logger.Logger, batchTimeout time.Duration, ) *PeerHandler { h := &PeerHandler{ - db: db, - logger: logger, - peerBatch: make([]peerUpdate, 0, peerBatchSize), - batchFullCh: make(chan struct{}, 1), - stopCh: make(chan context.Context, 1), - done: make(chan struct{}), + db: db, + logger: logger, + batchMaxSize: peerBatchMaxSize, + peerBatch: make([]peerUpdate, 0, peerBatchSize), + batchFullCh: make(chan struct{}, 1), + stopCh: make(chan context.Context, 1), + done: make(chan struct{}), } h.batchTaken.L = &h.mu @@ -135,7 +140,7 @@ func (h *PeerHandler) HandleMessage(msg *ristypes.RISMessage) { // While the batch is at its maximum size, wait until the flush goroutine // takes it. Meanwhile the handler takes nothing off its queue, which // fills, and the streamer drops messages for it. - for len(h.peerBatch) >= peerBatchMaxSize { + for len(h.peerBatch) >= h.batchMaxSize { h.batchTaken.Wait() } @@ -149,7 +154,7 @@ func (h *PeerHandler) HandleMessage(msg *ristypes.RISMessage) { // A full batch wakes the flush goroutine. If it is writing, the wake-up // waits in batchFullCh and the batch keeps growing until the write ends - // or the batch reaches peerBatchMaxSize. + // or the batch reaches batchMaxSize. if len(h.peerBatch) >= peerBatchSize { select { case h.batchFullCh <- struct{}{}: diff --git a/internal/routewatch/peerhandler_internal_test.go b/internal/routewatch/peerhandler_internal_test.go index 23e351f..776427b 100644 --- a/internal/routewatch/peerhandler_internal_test.go +++ b/internal/routewatch/peerhandler_internal_test.go @@ -35,7 +35,7 @@ func TestPeerHandlerWritesTheEarliestAndLatestTimesOfANewPeer(t *testing.T) { // Built without NewPeerHandler's flush goroutine, so the test flushes // itself. - h := &PeerHandler{db: store, logger: logger.New()} + h := &PeerHandler{db: store, logger: logger.New(), batchMaxSize: peerBatchMaxSize} first := peerAnnouncement(testPeerIP, testV4Prefix) second := peerAnnouncement(testPeerIP, testV4Prefix) diff --git a/internal/routewatch/peeringhandler.go b/internal/routewatch/peeringhandler.go index 046a210..e8dfb35 100644 --- a/internal/routewatch/peeringhandler.go +++ b/internal/routewatch/peeringhandler.go @@ -42,6 +42,10 @@ type PeeringHandler struct { db database.Store logger *logger.Logger + // maxPaths is the most paths asPaths holds: maxTrackedPaths, except in + // tests that give a smaller one. + maxPaths int + // In-memory AS path tracking: each path, JSON-encoded, with the earliest // and the latest time an update carried it. mu sync.Mutex @@ -62,21 +66,24 @@ type PeeringHandler struct { // periodically processes accumulated AS paths into peering records. The // handler begins processing immediately upon creation. func NewPeeringHandler(db database.Store, logger *logger.Logger) *PeeringHandler { - return newPeeringHandler(db, logger, peeringProcessInterval) + return newPeeringHandler(db, logger, peeringProcessInterval, maxTrackedPaths) } // newPeeringHandler is NewPeeringHandler with the processing timer's interval, -// processInterval, in place of peeringProcessInterval. A test gives a short -// one to have the timer start a write. +// processInterval, in place of peeringProcessInterval, and the most paths it +// holds, maxPaths, in place of maxTrackedPaths. A test gives a short interval to +// have the timer start a write, and a small maxPaths to fill the map quickly. func newPeeringHandler( db database.Store, logger *logger.Logger, processInterval time.Duration, + maxPaths int, ) *PeeringHandler { h := &PeeringHandler{ - db: db, - logger: logger, - asPaths: make(map[string]database.SeenTimes), - stopCh: make(chan context.Context, 1), - done: make(chan struct{}), + db: db, + logger: logger, + asPaths: make(map[string]database.SeenTimes), + maxPaths: maxPaths, + stopCh: make(chan context.Context, 1), + done: make(chan struct{}), } // Start the periodic processing goroutine @@ -131,7 +138,7 @@ func (h *PeeringHandler) HandleMessage(msg *ristypes.RISMessage) { defer h.mu.Unlock() seen, exists := h.asPaths[key] - if !exists && len(h.asPaths) >= maxTrackedPaths { + if !exists && len(h.asPaths) >= h.maxPaths { // Map is full; drop this new path and count it. h.droppedPaths++ diff --git a/internal/routewatch/peeringhandler_internal_test.go b/internal/routewatch/peeringhandler_internal_test.go index afcb9d9..d39e3cd 100644 --- a/internal/routewatch/peeringhandler_internal_test.go +++ b/internal/routewatch/peeringhandler_internal_test.go @@ -5,7 +5,6 @@ import ( "fmt" "maps" "slices" - "strconv" "sync" "testing" "time" @@ -20,6 +19,10 @@ const ( testASNB = 64501 testASNC = 64502 testASND = 64503 + + // testMaxTrackedPaths is a limit of the path map that a test fills + // quickly, in place of maxTrackedPaths. + testMaxTrackedPaths = 10 ) // recordingStore wraps mockStore to count every RecordPeering call, so a @@ -52,9 +55,10 @@ func (r *recordingStore) callCount() int { // processing goroutine, so tests drive processing explicitly. func newTestHandler(db database.Store) *PeeringHandler { return &PeeringHandler{ - db: db, - logger: logger.New(), - asPaths: make(map[string]database.SeenTimes), + db: db, + logger: logger.New(), + asPaths: make(map[string]database.SeenTimes), + maxPaths: maxTrackedPaths, } } @@ -244,25 +248,28 @@ func TestPeeringHandlerStopWritesTheRemainingPaths(t *testing.T) { // TestPeeringHandlerCapDropsAndCounts verifies that a full map drops new paths // and counts them, while a path already tracked is refreshed rather than -// dropped. +// dropped. The handler's limit is small, and its timer does not fire. func TestPeeringHandlerCapDropsAndCounts(t *testing.T) { t.Parallel() store := &recordingStore{mockStore: newMockStore()} - h := newTestHandler(store) + h := newPeeringHandler(store, logger.New(), longerThanAnyTest, + testMaxTrackedPaths) + + defer stopInTime(t, h) now := time.Now().UTC() - // Fill the map to exactly maxTrackedPaths, including one real path key so - // the "already tracked" branch can be exercised. The filler keys are never - // processed in this test, so their contents do not matter. + // Fill the map to exactly its limit, including one real path key so the + // "already tracked" branch can be exercised. The other paths are of one + // AS, so they carry no peering. existing := pathKey(t, testASNA, testASNB) h.mu.Lock() h.asPaths[existing] = database.SeenTimes{First: now, Last: now} - for i := 0; len(h.asPaths) < maxTrackedPaths; i++ { - h.asPaths[strconv.Itoa(i)] = database.SeenTimes{First: now, Last: now} + for asn := 1; len(h.asPaths) < testMaxTrackedPaths; asn++ { + h.asPaths[pathKey(t, asn)] = database.SeenTimes{First: now, Last: now} } h.mu.Unlock() @@ -270,8 +277,9 @@ func TestPeeringHandlerCapDropsAndCounts(t *testing.T) { handle(h, now.Add(time.Second), testASNA, testASNC) tracked, dropped := snapshot(h) - if tracked != maxTrackedPaths { - t.Fatalf("want map size %d after drop, got %d", maxTrackedPaths, tracked) + if tracked != testMaxTrackedPaths { + t.Fatalf("want map size %d after drop, got %d", testMaxTrackedPaths, + tracked) } if dropped != 1 { @@ -283,8 +291,9 @@ func TestPeeringHandlerCapDropsAndCounts(t *testing.T) { handle(h, refreshed, testASNA, testASNB) tracked, dropped = snapshot(h) - if tracked != maxTrackedPaths { - t.Fatalf("want map size %d after refresh, got %d", maxTrackedPaths, tracked) + if tracked != testMaxTrackedPaths { + t.Fatalf("want map size %d after refresh, got %d", testMaxTrackedPaths, + tracked) } if dropped != 1 { @@ -303,17 +312,21 @@ func TestPeeringHandlerCapDropsAndCounts(t *testing.T) { // TestPeeringHandlerRunResetsTheDroppedCount fills the map, has the handler // drop one path, and runs the processing. The count of dropped paths is the -// run's own, so it is 0 again after the run. +// run's own, so it is 0 again after the run. The handler's limit is small, and +// its timer does not fire. func TestPeeringHandlerRunResetsTheDroppedCount(t *testing.T) { t.Parallel() - h := newTestHandler(newMockStore()) + h := newPeeringHandler(newMockStore(), logger.New(), longerThanAnyTest, + testMaxTrackedPaths) + + defer stopInTime(t, h) now := time.Now().UTC() // Paths of one AS carry no peering, so the run records nothing. h.mu.Lock() - for asn := 1; len(h.asPaths) < maxTrackedPaths; asn++ { + for asn := 1; len(h.asPaths) < testMaxTrackedPaths; asn++ { h.asPaths[pathKey(t, asn)] = database.SeenTimes{First: now, Last: now} } h.mu.Unlock() diff --git a/internal/routewatch/prefixhandler.go b/internal/routewatch/prefixhandler.go index 6472a39..1de36c2 100644 --- a/internal/routewatch/prefixhandler.go +++ b/internal/routewatch/prefixhandler.go @@ -60,10 +60,17 @@ type PrefixHandler struct { metrics *metrics.Tracker table *routetable.Table + // batchMaxSize is prefixBatchMaxSize. Only HandleMessage reads it, so a + // test may lower it before it hands the handler a message. + batchMaxSize int + // tableChangesPerWrite is maxTableChangesPerWrite, except in tests that + // give a smaller one. + tableChangesPerWrite int + // Batching. mu guards batch, writing and writingTableChanges only: the // flush goroutine takes them under mu and writes them after releasing // mu, so HandleMessage waits for a database write only while batch is at - // prefixBatchMaxSize. + // batchMaxSize. mu sync.Mutex batch []seenPrefix // writing is how many updates the flush goroutine took and has not @@ -119,24 +126,30 @@ func (u prefixUpdate) announcesRoute() bool { func NewPrefixHandler( db database.Store, logger *logger.Logger, table *routetable.Table, ) *PrefixHandler { - return newPrefixHandler(db, logger, table, prefixBatchTimeout) + return newPrefixHandler(db, logger, table, prefixBatchTimeout, + maxTableChangesPerWrite) } // newPrefixHandler is NewPrefixHandler with the flush timer's interval, -// batchTimeout, in place of prefixBatchTimeout. A test that the timer must not -// disturb gives an interval longer than the test runs. +// batchTimeout, in place of prefixBatchTimeout, and tableChangesPerWrite in +// place of maxTableChangesPerWrite. A test that the timer must not disturb +// gives an interval longer than the test runs. A test of writes split over +// several flushes gives a small tableChangesPerWrite, so that it exceeds it +// with few changes. func newPrefixHandler( db database.Store, logger *logger.Logger, table *routetable.Table, - batchTimeout time.Duration, + batchTimeout time.Duration, tableChangesPerWrite int, ) *PrefixHandler { h := &PrefixHandler{ - db: db, - logger: logger, - table: table, - batch: make([]seenPrefix, 0, prefixBatchSize), - batchFullCh: make(chan struct{}, 1), - stopCh: make(chan context.Context, 1), - done: make(chan struct{}), + db: db, + logger: logger, + table: table, + batch: make([]seenPrefix, 0, prefixBatchSize), + batchMaxSize: prefixBatchMaxSize, + tableChangesPerWrite: tableChangesPerWrite, + batchFullCh: make(chan struct{}, 1), + stopCh: make(chan context.Context, 1), + done: make(chan struct{}), } h.batchTaken.L = &h.mu @@ -191,7 +204,7 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) { // While the batch is at its maximum size, wait until the flush goroutine // takes it. Meanwhile the handler takes nothing off its queue, which // fills, and the streamer drops messages for it. - for len(h.batch) >= prefixBatchMaxSize { + for len(h.batch) >= h.batchMaxSize { h.batchTaken.Wait() } @@ -239,7 +252,7 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) { // A full batch wakes the flush goroutine. If it is writing, the wake-up // waits in batchFullCh and the batch keeps growing until the write ends - // or the batch reaches prefixBatchMaxSize. + // or the batch reaches batchMaxSize. if len(h.batch) >= prefixBatchSize { select { case h.batchFullCh <- struct{}{}: @@ -250,7 +263,7 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) { // Stop stops the flush goroutine, which makes one last flush before it returns, // and waits for it until ctx ends. That flush writes at most -// maxTableChangesPerWrite of the routing table's changes, and the prefixes of +// tableChangesPerWrite of the routing table's changes, and the prefixes of // the updates the handler holds. Once ctx has ended the flush goroutine skips // that last flush, and a write still running is lost when the process exits. A // failed write of the table's changes is not retried either. Stop logs how many @@ -378,14 +391,13 @@ func (h *PrefixHandler) applyToTable(update prefixUpdate) { }) } -// writeTableChanges writes at most maxTableChangesPerWrite changes of the -// routing table in memory, and every peer the table numbered since the last -// write. +// writeTableChanges writes at most tableChangesPerWrite changes of the routing +// table in memory, and every peer the table numbered since the last write. // When the write fails, they go back to the table, so that a later write writes // them again, each pair with its content then. func (h *PrefixHandler) writeTableChanges() { h.mu.Lock() - changes, newPeers := h.table.TakeChanges(maxTableChangesPerWrite) + changes, newPeers := h.table.TakeChanges(h.tableChangesPerWrite) h.writingTableChanges = len(changes) h.mu.Unlock() diff --git a/internal/routewatch/prefixhandler_internal_test.go b/internal/routewatch/prefixhandler_internal_test.go index c7401d6..a81d346 100644 --- a/internal/routewatch/prefixhandler_internal_test.go +++ b/internal/routewatch/prefixhandler_internal_test.go @@ -237,9 +237,10 @@ func TestPrefixHandlerStopLogsNothingWhenItWroteEverything(t *testing.T) { } } -// longerThanAnyTest is a flush timer interval that no test lasts. A test whose -// prefix, AS or peer handler must flush only when its batch is full and on Stop -// gives it to newPrefixHandler, newASHandler or newPeerHandler. +// longerThanAnyTest is a timer interval that no test lasts. A test gives it to +// newPrefixHandler, newASHandler, newPeerHandler or newPeeringHandler when the +// handler must write only when its batch is full, when the test says, or on +// Stop. const longerThanAnyTest = time.Hour // prefixHandlerWithoutTimer returns a prefix handler that writes to store and @@ -247,9 +248,11 @@ const longerThanAnyTest = time.Hour // NewPrefixHandler's flush goroutine, so the test flushes itself. func prefixHandlerWithoutTimer(store database.Store) *PrefixHandler { return &PrefixHandler{ - db: store, - logger: logger.New(), - table: routetable.New(routetable.Params{}), + db: store, + logger: logger.New(), + table: routetable.New(routetable.Params{}), + batchMaxSize: prefixBatchMaxSize, + tableChangesPerWrite: maxTableChangesPerWrite, } } diff --git a/internal/routewatch/prefixhandler_table_internal_test.go b/internal/routewatch/prefixhandler_table_internal_test.go index b4b894f..e144842 100644 --- a/internal/routewatch/prefixhandler_table_internal_test.go +++ b/internal/routewatch/prefixhandler_table_internal_test.go @@ -30,11 +30,12 @@ const ( // firstManyPrefix is the first prefix announceManyPrefixes announces. firstManyPrefix = "10.0.0.0/32" -) -// tableWriteTimeout is how long a test waits for the flush timer to write the -// routing table's changes: a few ticks of it. -const tableWriteTimeout = 5 * prefixBatchTimeout + // testMaxTableChangesPerWrite is a limit of one write of the routing + // table's changes that a test exceeds quickly, in place of + // maxTableChangesPerWrite. + testMaxTableChangesPerWrite = 10 +) // tableCase is one test of the routing table in memory: the messages handed to // the prefix handler, and for each prefix the peers that carry it with each @@ -276,9 +277,9 @@ func TestPrefixHandlerWritesTheTableChangesEachSecond(t *testing.T) { t.Fatalf("wrote %+v, want the pair of %s and AS%d with "+ "removed %t", changes, prefix, testASNB, step.wantRemoved) } - case <-time.After(tableWriteTimeout): + case <-time.After(stepTimeout): t.Fatalf("the routing table's change was not written within %s", - tableWriteTimeout) + stepTimeout) } } } @@ -375,25 +376,32 @@ func (s *tableWriteSizesStore) WriteRouteChanges( // takes, then flushes three times. The first write must hold as many pairs as // one write takes, and the peer. The second must hold the other pairs, and the // third flush must write nothing. The database must then hold the table in -// memory. +// memory. The handler's limit is small, and its timer does not fire. func TestPrefixHandlerWritesManyTableChangesOverSeveralFlushes(t *testing.T) { t.Parallel() const ( - pairs = maxTableChangesPerWrite * 3 / 2 + pairs = testMaxTableChangesPerWrite * 3 / 2 flushes = 3 ) db := newTestDatabase(t) store := &tableWriteSizesStore{Database: db} - h := prefixHandlerWithoutTimer(store) - announceManyPrefixes(h.table, pairs) + table := routetable.New(routetable.Params{}) + announceManyPrefixes(table, pairs) + + h := newPrefixHandler(store, logger.New(), table, longerThanAnyTest, + testMaxTableChangesPerWrite) + + defer stopInTime(t, h) for range flushes { h.flushBatch() } - wantChanges := []int{maxTableChangesPerWrite, pairs - maxTableChangesPerWrite} + wantChanges := []int{ + testMaxTableChangesPerWrite, pairs - testMaxTableChangesPerWrite, + } wantNewPeers := []int{1, 0} if !slices.Equal(store.changes, wantChanges) || @@ -415,11 +423,11 @@ func TestPrefixHandlerWritesManyTableChangesOverSeveralFlushes(t *testing.T) { // takes. Its last flush writes one write's worth, so Stop must log the pairs // that no write took, and must not say that the stop deadline passed. The // flush timer must not fire, or its writes could leave no pairs for Stop to -// log. +// log. The handler's limit of one write is small. func TestPrefixHandlerStopLogsTheTableChangesLeftUnwritten(t *testing.T) { t.Parallel() - const pairs = maxTableChangesPerWrite + 1 + const pairs = testMaxTableChangesPerWrite + 1 var logs bytes.Buffer @@ -427,7 +435,8 @@ func TestPrefixHandlerStopLogsTheTableChangesLeftUnwritten(t *testing.T) { table := routetable.New(routetable.Params{}) announceManyPrefixes(table, pairs) - h := newPrefixHandler(store, newErrorLogger(&logs), table, longerThanAnyTest) + h := newPrefixHandler(store, newErrorLogger(&logs), table, longerThanAnyTest, + testMaxTableChangesPerWrite) h.Stop(t.Context()) written := 0