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