sneak/routewatch
1
0
Fork 0
Code Issues 3 Pull Requests 1 Actions 4 Packages Projects Releases Wiki Activity

Compare commits

base: sneak/routewatch:946c8a4b418a5f07a98a9f3e35d10e6c72f40dc3
Branches Tags
sneak/routewatch:main sneak/routewatch:next sneak/routewatch:prod sneak/routewatch:issue-27-cached-stats
...
compare: sneak/routewatch:next
Branches Tags
sneak/routewatch:next sneak/routewatch:prod sneak/routewatch:main sneak/routewatch:issue-27-cached-stats
9 Commits
946c8a4b41 ... next
Author SHA1 Message Date
clawbot 742e75914c Rewrite the README sentence by sentence (closes #157)
check / check (push) Waiting to run
Details 
The README is rewritten from scratch against the prose rules of
#157: every sentence under
about 30 words, lists as bullets, every technical term defined where it
first appears, and every statement checked against the code on next. It
leads with what RouteWatch is and how to run it, then the pages, the API
and the blocklists, then the settings, memory and upaas, and last the
design and the development workflow. The dated entry goes into TODO.md.

Model: fable-5-1
 2026-11-03 00:10:08 +01:00
clawbot 37cecedc5b Rewrite TODO.md sentence by sentence (part of #157)
check / check (push) Canceled after 0s
Details 
Every sentence of TODO.md is rewritten from scratch against the rules
of #157: about 30 words at
most, one idea each, subject and verb early, identifiers in backticks.
Status and Next Step describe the repo as the tracker shows it now.
Every Completed Steps entry keeps its date, its facts and its issue
reference, checked against the commit it names. The Workflow section
keeps its meaning. The entry for this rewrite is added.

Model: fable-5-1
 2026-11-02 23:44:09 +01:00
clawbot e5afd94a39 Take every down peer out of the table in one walk (closes #225)
check / check (push) Canceled after 0s
Details 
The prefix handler ran one PeerDown per peer, one after another. When
the sessions of several peers went down together, their walks queued up.
A returning full-table peer's messages stayed held back while the walks
ahead of its own ran, and could reach the limit of 20,000.

The table's PeersDown now takes several peers out of every prefix in one
walk. One walk runs at a time. The next one takes every peer whose
session went down since the previous one began. The doc of
maxHeldBackMessages says how long a peer's messages are held back. The
limit is now 150,000 messages, about 150 MiB. The status page shows how
many messages each handler holds back.

Model: opus-5-5
 2026-11-02 23:10:09 +01:00
clawbot 9bd0e91a3b Let the lock go for as long as it was held during Overview's walk (closes #226)
check / check (push) Canceled after 0s
Details 
The home page's cards are worked out once a minute by Overview, which
walks every prefix of the routing table under the table's read lock.
After each batch of 10,000 prefixes, the walk let the lock go and took
it back at once. The prefix handler, waiting for the write lock, then got
in only once per batch. During a walk, its queue could fill, and the
streamer then dropped updates for it.

The walk now lets the lock go for as long as it held the lock for the
batch, as PeerDown does. A test applies another peer's 1,000
announcements while Overview walks a table with more prefixes than five
of the walk's batches.

Model: opus-5-5
 2026-11-02 08:00:00 +01:00
clawbot d66c59ef07 Lengthen the WHOIS fetcher's wait after a skipped lookup (closes #222)
check / check (push) Canceled after 0s
Details 
A lookup whose RIR is paused is skipped. The skip left the fetcher's wait
as it was. Each lookup asks IANA before it finds its RIR paused. So while
most stale ASes belonged to a paused RIR, the fetcher could ask IANA every
second.

Like a failure, a skipped lookup now makes the wait 1.5 times as long, up
to one minute. The skip is still not counted as a failure, so the status
page's failure figures leave it out.

Model: opus-5-5
 2026-11-02 03:59:47 +01:00
clawbot 26d939ad72 Keep taking messages while a peer's session goes down (closes #216)
check / check (push) Canceled after 0s
Details 
The table's PeerDown visits every prefix under the write lock, which
takes over a second on a full table. The prefix handler called it
inline, so its queue filled and the streamer dropped updates.

PeerDown now holds the lock for 10,000 prefixes at a time, then lets
the lock go for as long again. The handler runs PeerDown on a separate
goroutine, one peer at a time. The handler holds back the down peer's
later messages until that PeerDown returns. Then the handler applies
them in order, one at a time, and takes new messages in between. It
holds back at most 20,000 messages. Stop waits for all of this before
its last flush.

Model: opus-5-5
 2026-11-02 03:27:10 +01:00
clawbot df15e2b2cd Pause a registry's WHOIS server after it refuses a query (closes #218)
check / check (push) Canceled after 0s
Details 
The fetcher kept one interval for every registry, so a registry that
refused a query was asked again within seconds. RIPE blocked the test
host's address that way.

The WHOIS client now pauses an RIR's or NIC.br's server for an hour
after the server refuses a query. A refused or reset connection is a
refusal, and so is an %ERROR:201: or %ERROR:202: line. Lookups at the
other servers go on. A lookup whose RIR is paused leaves the AS stale,
and counts as neither a success nor a failure. IANA is never paused,
because a pause of IANA would stop every lookup. NIC.br's hour-long
skip after its over-limit answer is now the same pause.

Model: opus-5-5
 2026-11-02 02:59:57 +01:00
clawbot 6b004dfbc3 Keep one entry per AS in the AS handler's batch (closes #217)
check / check (push) Canceled after 0s
Details 
HandleMessage added one entry to the batch for every AS of every path,
and waited for the write in progress once the batch held 300,000. In a
burst of the feed its queue then filled, and the streamer dropped
messages.

The batch is now a map from AS number to the earliest and the latest
time of its updates. It holds one entry per AS, so it no longer grows
with the feed's rate. HandleMessage never waits for a write.
asnBatchSize now counts ASes. Stop logs the entries of the batch being
written and of the next batch under "batch_entries". An AS in both
counts twice.

Model: opus-5-5
 2026-11-02 02:10:17 +01:00
clawbot 38b43549b9 Make the routewatch tests pass on a loaded host (closes #213)
check / check (push) Canceled after 0s
Details 
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
#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
 2026-10-28 01:44:47 +01:00
31 changed files with 2784 additions and 1208 deletions
Expand all files Collapse all files
README.md
+730 -578
View File
File diff suppressed because it is too large Load Diff
TODO.md
+347 -251
View File
@@ -10,137 +10,223 @@
# Status # Status
pre-1.0. No git tags. `main` last took `next` on 2026-10-06, through RouteWatch is pre-1.0, with no git tags. `main` last took `next` on 2026-10-27,
https://git.eeqj.de/sneak/routewatch/pulls/6. The linter and the tests are through https://git.eeqj.de/sneak/routewatch/pulls/166.
phases of the Docker build, and the Gitea workflow runs `script/cibuild` (the https://git.eeqj.de/sneak/routewatch/pulls/202 carries the commits since then
format check of the Go code and the markdown, both phases, then the image) on into `main`. It is labelled `merge-ready` and waits for sneak.
every push. The image sets memory ceilings for a 5 GiB container (README
"Memory") and the README says how to run it under upaas (README "Running under The linter and the tests are phases of the Docker build. The Gitea workflow runs
upaas"). A 25-hour run of `a9b6860` on the live feed peaked at about 0.6 GiB `script/cibuild` on every push. That script runs the two phases and checks the
(https://git.eeqj.de/sneak/routewatch/issues/3). A run of `825afa2` on the live formatting of the Go code and the markdown. Then it builds the image.
feed found the prefix handler dropping about a quarter of its updates because
its route writes were slower than the feed The image sets memory ceilings for a 5 GiB container (README "Memory"). README
(https://git.eeqj.de/sneak/routewatch/issues/96); the cheaper writes since then "Running under upaas" says how to run it.
are measured by a benchmark, not yet on the live feed.
A five-day run of `1c65656` on the live feed, from 2026-10-27 to 2026-11-01,
found three problems:
- The prefix handler dropped updates while a peer's session went down
(https://git.eeqj.de/sneak/routewatch/issues/216).
- The AS handler dropped updates when the feed burst
(https://git.eeqj.de/sneak/routewatch/issues/217).
- The WHOIS fetcher kept asking a registry that had refused it
(https://git.eeqj.de/sneak/routewatch/issues/218).
All three are fixed on `next`. So is
https://git.eeqj.de/sneak/routewatch/issues/222, which the third fix brought up.
A run of `26d939a` on the live feed showed the prefix handler still dropping
updates while the home page's cards were worked out.
https://git.eeqj.de/sneak/routewatch/issues/226 fixed that on `next`.
https://git.eeqj.de/sneak/routewatch/issues/225, also on `next`, takes the peers
whose sessions go down together out of the table in one walk. A 24-hour run of
`9bd0e91` on the live feed is checking whether any handler still drops updates.
Two questions wait for sneak: which history the prefix page keeps
(https://git.eeqj.de/sneak/routewatch/issues/161), and which fields the IP
lookup answer gains (https://git.eeqj.de/sneak/routewatch/issues/203).
The order of the project's remaining work is kept on
https://git.eeqj.de/sneak/routewatch/issues/86.
# Next Step # Next Step
Run `next` on the live feed, as README "Running under upaas" describes, until Post the outcome of the 24-hour run of `9bd0e91` on
the routing table stops growing. Post its size and memory figures on https://git.eeqj.de/sneak/routewatch/issues/226: whether any handler still drops
https://git.eeqj.de/sneak/routewatch/issues/122. The same run makes the final updates, and the process's peak memory against 5 GiB. File an issue for each
check https://git.eeqj.de/sneak/routewatch/issues/96 names: whether the prefix problem the run finds.
handler still drops updates after the first hour. If it does, a new issue
follows with the numbers. Then an audit of the code at the commit that run
tested.
# Completed Steps # Completed Steps
- 2026-10-27: the server works out the home page's cards every minute until it - 2026-11-02: `README.md` is rewritten from scratch, sentence by sentence,
stops. It used to work them out only once, at startup: the end of the context against the rules of https://git.eeqj.de/sneak/routewatch/issues/157. Every
that `Start` is given stopped the refreshes (closes #211) statement was checked against the code on `next` (closes #157)
- 2026-10-27: README "Rationale" says why RouteWatch exists: to answer our other - 2026-11-02: `TODO.md` is rewritten from scratch, sentence by sentence, against
services' questions about IP addresses, from its own routing table and the the rules of https://git.eeqj.de/sneak/routewatch/issues/157. Every Completed
WHOIS details it keeps. It still says what RIS Live does not give (closes Steps entry keeps its date, its facts and its issue. Status and Next Step
#204) describe the repo as the tracker shows it (part of #157)
- 2026-10-27: every JSON answer carries `@meta`. A panic on a JSON route answers - 2026-11-02: when the sessions of several peers go down, the prefix handler
takes the peers out of the routing table together. The table's `PeersDown`
takes several peers out of every prefix in one walk. One walk runs at a time.
The next one takes every peer whose session went down since the previous one
began. Each peer used to have a walk of its own. A peer's messages stayed held
back while the walks queued ahead of its own ran. The handler holds back at
most 150,000 messages, about 150 MiB. It used to hold back at most 20,000. The
status page shows how many messages the handler holds back (closes #225)
- 2026-11-02: working out the home page's cards no longer stops the prefix
handler. The walk over the routing table holds the table's lock for 10,000
prefixes at a time, then lets the lock go for as long again, as `PeerDown`
does. It used to take the lock back at once. The prefix handler then applied
about one update per 10,000 prefixes walked. During a walk, its queue could
fill, and the streamer then dropped updates for it (closes #226)
- 2026-11-02: A skipped WHOIS lookup now makes the fetcher wait longer before
the next one, as a failed lookup does. A lookup is skipped when its RIR is
paused. An RIR is one of the five regional Internet registries. The longest
wait is one minute. The status page does not count a skip as a failure. A skip
used to leave the wait as it was. Each lookup asks IANA which RIR holds the AS
before it finds that RIR paused. So while most stale ASes belonged to a paused
RIR, the fetcher could ask IANA every second (closes #222)
- 2026-11-02: A peer's session going down no longer stops the prefix handler.
The handler runs the routing table's `PeerDown` on a goroutine of its own, one
peer at a time. Meanwhile it goes on taking messages. `PeerDown` holds the
table's lock for 10,000 prefixes at a time, then lets the lock go for as long
again. The handler holds back the down peer's later messages until that peer's
`PeerDown` returns. Then the handler applies them in order, one at a time, and
takes new messages in between. It holds back at most 20,000 messages. At that
number, `HandleMessage` waits until one of them is applied. When `Stop` runs
past its deadline, it logs how many held-back messages were not applied
(closes #216)
- 2026-11-02: RouteWatch pauses an RIR's or NIC.br's WHOIS server for an hour
after the server refuses a query. NIC.br is Brazil's registry. A refused or
reset connection is a refusal. So is an answer with an `%ERROR:201:` or
`%ERROR:202:` line. Lookups at the other servers go on. An AS whose RIR is
paused is looked up after the pause. While NIC.br is paused, a Brazilian AS
gets the details from LACNIC's answer. IANA is never paused, because a pause
of IANA would stop every lookup. A refusal by IANA is an ordinary failure.
NIC.br is also paused for an hour after it says RouteWatch has passed its
query limit. Before, the fetcher asked a server again within seconds of a
refusal (closes #218)
- 2026-11-02: The AS handler never waits for a database write. Its batch holds
one entry per AS, with the earliest and the latest time of its updates. So the
batch no longer grows with the feed's rate. It used to hold one entry for each
AS of each path. At 300,000 entries it waited for the write in progress. In a
burst of the feed its queue then filled, and the streamer dropped messages for
it (closes #217)
- 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. Under the race detector that can take longer. A test now waits up to 15
seconds for each step it expects. The tests of the handlers' limits now give
the handlers small limits. 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
given to `Start` stopped the refreshes (closes #211)
- 2026-10-27: README "Rationale" says why RouteWatch exists. RouteWatch answers
our other services' questions about IP addresses, from its own routing table
and the WHOIS details it keeps. The section still says what RIS Live does not
give (closes #204)
- 2026-10-27: Every JSON answer carries `@meta`. A panic on a JSON route answers
500 with the JSON error body. `/status.json` and the health check answer 405 500 with the JSON error body. `/status.json` and the health check answer 405
with the JSON error body to any method they do not take. The 500 and the 405 with the JSON error body to any method they do not take. The 500 and the 405
used to have an empty body. The home page's IP lookup shows the whole JSON used to have an empty body. The home page's IP lookup shows the whole JSON
answer, `@meta` included. It used to show only the answer's `data`, or only answer, `@meta` included. It used to show only the answer's `data`, or only
the message of an error answer. A test checks `@meta` on every JSON route, in the message of an error answer. A test checks `@meta` on every JSON route, in
its successes and its errors (closes #201) its successes and its errors (closes #201)
- 2026-10-27: every value in a JSON answer that has a unit is a number, with the - 2026-10-27: Every value with a unit in a JSON answer is a number. The unit is
unit at the end of its field name. `@meta.execution_time` is now at the end of the field name. `@meta.execution_time` is now
`execution_time_ms`. The stats' `uptime`, `connection_duration` and `execution_time_ms`. In the stats, `uptime` is now `uptime_seconds`,
`memory_usage` are now `uptime_seconds`, `connection_duration_seconds` and `connection_duration` is now `connection_duration_seconds`, and `memory_usage`
`memory_usage_bytes`. `whois_stats.current_interval` is now is now `memory_usage_bytes`. `whois_stats.current_interval` is now
`current_interval_seconds`. They used to be strings such as "12 ms", `whois_stats.current_interval_seconds`. They used to be strings such as "12
"1h18m34s" or "1.1 GB". `connection_duration_seconds` is null while the feed ms", "1h18m34s" or "1.1 GB". `connection_duration_seconds` is null while the
is not connected. `API_POLICIES.md` is vendored from `sneak/prompts`, and feed is not connected. `API_POLICIES.md` is vendored from `sneak/prompts`, and
`REPO_POLICIES.md` re-vendored (closes #199) `REPO_POLICIES.md` is re-vendored (closes #199)
- 2026-10-27: every result of the IP lookup has the same fields. A field without - 2026-10-27: Every result of the IP lookup has the same fields. A field without
a value is null. It used to be left out. An address with no live route has a value is null. It used to be left out. An address with no route in the
every route and AS field set to null, and `ptr` is an empty list when there routing table has every route and AS field set to null. `ptr` is an empty list
are no PTR names. New fields give the number of origin ASes of the netblock, when there are no PTR names. The new field `num_origins` gives the number of
in `num_origins`, and which they are, in `origin_asns` (closes #200) origin ASes of the netblock, and `origin_asns` gives which they are (closes
- 2026-10-27: with `TRUSTED_PROXIES` unset, the server trusts reverse proxies at #200)
- 2026-10-27: With `TRUSTED_PROXIES` unset, the server trusts reverse proxies at
the private addresses of RFC 1918. `/ip/`, the home page's `curl` card and the the private addresses of RFC 1918. `/ip/`, the home page's `curl` card and the
request log then give the client's address from `X-Forwarded-For`. They used request log then give the client's address from `X-Forwarded-For`. They used
to give the proxy's address. A list in `TRUSTED_PROXIES` replaces the default, to give the proxy's address. A list in `TRUSTED_PROXIES` replaces the default.
and `TRUSTED_PROXIES` set but empty trusts no proxy (closes #198) `TRUSTED_PROXIES` set but empty trusts no proxy (closes #198)
- 2026-10-27: the home page has cards with figures of the routing table: the - 2026-10-27: The home page has cards with figures of the routing table. One
newest and oldest kept route, the newest and oldest updated AS, the AS with card shows the newest and the oldest kept route. One shows the newest and the
the most prefixes, the ASes with a single prefix, and fifteen well-known oldest updated AS. One shows the AS with the most prefixes. One shows the ASes
networks. Two cards count the bogon announcements and the prefixes with more with a single prefix. One shows fifteen well-known networks. Two cards count
than one origin AS, and link to the new pages `/bogons` and the bogon announcements and the prefixes with more than one origin AS. They
`/multiple-origins` that list them. A new package, `internal/bogon`, tells link to the new pages `/bogons` and `/multiple-origins`, which list them. A
which prefixes and AS numbers are reserved. The server works the figures out new package, `internal/bogon`, tells which prefixes and AS numbers are
once a minute (closes #154) reserved. The server works the figures out once a minute (closes #154)
- 2026-10-27: the per-peer route tables are gone, with the code that wrote, - 2026-10-27: The per-peer route tables are gone, with the code that wrote,
counted and read them. The prefix handler applies each update to the routing counted and read them. The prefix handler applies each update to the routing
table in memory and writes the table's changes every second. It also stores table in memory. It writes the table's changes every second. It also stores
each new prefix with its first-seen time. The image's memory limits are set each new prefix with its first-seen time. The image's memory limits fit a full
for a full routing table of about 1 GB: `GOMEMLIMIT` is 2.5 GiB, the writing routing table of about 1 GB. `GOMEMLIMIT` is 2.5 GiB. The writing connection's
connection's page cache 512 MiB, and SQLite's heap limits 768 MiB and 1 GiB page cache is 512 MiB. SQLite's soft and hard heap limits are 768 MiB and 1
(closes #122) GiB (closes #122)
- 2026-10-27: the pages, the API and the stats read every route from the routing - 2026-10-27: The pages, the API and the stats read every route from the routing
table in memory. For a prefix with several origin ASes, the IP lookup gives table in memory. For a prefix with several origin ASes, the IP lookup gives
the one most peers carry. Its `last_seen` is the newest kept route's time. The the one most peers carry. Its `last_seen` is the newest kept route's time. The
prefix page and API list every peer that carries the prefix, with an AS path, prefix page and API list every peer that carries the prefix. Only the kept
next hop and time only for the kept routes. The stats count the origins whose routes show an AS path, a next hop and a time. The stats count the origins
kept routes were all withdrawn, in `origins_without_kept_route` (part of #122) whose kept routes were all withdrawn, in `origins_without_kept_route` (part of
- 2026-10-27: the prefix, AS and peer handlers make a timed write on every tick
of their timers, every 1, 2 and 2 seconds. They used to skip every other tick.
A full batch's write restarts the timer, so the next timed write comes one
interval after that write began (closes #192)
- 2026-10-27: once the stop deadline has passed, the AS, peer and peering
handlers start no write either. A full batch or a tick of the timer that
waited while a write ran past the deadline could still start one. The flush
goroutines of the prefix, AS and peer handlers now run the same code (closes
#189)
- 2026-10-27: once the stop deadline has passed, the prefix handler starts no
flush. A batch that filled while a write ran past the deadline could still be
written after it (closes #188)
- 2026-10-27: the prefix handler applies each update to the routing table in
memory, and writes the table's changes to the database every second. A write
takes at most 20,000 changed pairs, and the rest follow in the next writes. A
failed write is written again later. Startup reads the table before the
streamer connects. The pages still read the per-peer route tables (part of
#122) #122)
- 2026-10-27: the database keeps a copy of the whole routing table in a new - 2026-10-27: The prefix, AS and peer handlers make a timed write on every tick
of their timers. The prefix handler's timer ticks every second. The other two
tick every two seconds. They used to skip every other tick. A full batch's
write restarts the timer. So the next timed write comes one interval after
that write began (closes #192)
- 2026-10-27: Once the stop deadline has passed, the AS, peer and peering
handlers start no write either. Before, a full batch or a timer tick could
wait while a write ran past the deadline. Either could then start one more
write. The flush goroutines of the prefix, AS and peer handlers now run the
same code (closes #189)
- 2026-10-27: Once the stop deadline has passed, the prefix handler starts no
flush. Before, a batch that filled during a late write could still be written
after the deadline (closes #188)
- 2026-10-27: The prefix handler applies each update to the routing table in
memory. It writes the table's changes to the database every second. A write
takes at most 20,000 changed pairs of prefix and origin AS. The rest follow in
the next writes. A failed write is written again later. Startup reads the
table before the streamer connects. The pages still read the per-peer route
tables (part of #122)
- 2026-10-27: The database keeps a copy of the whole routing table in a new
`routes` table, one row per prefix and origin AS. The peers' numbers are in a `routes` table, one row per prefix and origin AS. The peers' numbers are in a
new `route_peers` table. One function writes the pairs that changed in memory, new `route_peers` table. One function writes the pairs that changed in memory.
and another reads the whole table back into memory at startup. Nothing uses Another reads the whole table back into memory at startup. Nothing uses them
them yet (part of #122) yet (part of #122)
- 2026-10-27: a new package, `internal/routetable`, holds the whole routing - 2026-10-27: A new package, `internal/routetable`, holds the whole routing
table in memory. For each prefix and origin AS it keeps the peers that carry table in memory. For each prefix and origin AS it keeps the peers that carry
it, one bit per peer, and the two newest of their routes. Nothing uses it yet it, one bit per peer. It also keeps the two newest of their routes. Nothing
(part of #122) uses it yet (part of #122)
- 2026-10-27: each result of the IP lookup lists the public blocklists the - 2026-10-27: Each result of the IP lookup lists the public blocklists the
address is on, in `blocklists`. The lists are DShield, Feodo Tracker, two address is on, in `blocklists`. The lists are DShield, Feodo Tracker, two
FireHOL lists, Spamhaus DROP and the Tor exit list. RouteWatch downloads each FireHOL lists, two Spamhaus DROP lists and the Tor exit list. RouteWatch
list on its own schedule and answers from copies in memory. The copies are downloads each list on its own schedule and answers from copies in memory. The
also kept in the state directory's `blocklists` directory. IP lookup answers copies are also kept in the state directory's `blocklists` directory. IP
carry `Cache-Control`. An address with no live route now has a result too, lookup answers carry `Cache-Control`. An address with no route now has a
without route fields, so the IP lookup no longer answers 404 (closes #158) result too, without route fields. So the IP lookup no longer answers 404
- 2026-10-27: the home page has an IP information API card. It shows the `curl` (closes #158)
command that looks up the visitor's own address at `/ip/{addr}`, and that - 2026-10-27: The home page has an IP information API card. It shows the `curl`
command's live answer (closes #156) command that looks up the visitor's own address at `/ip/{addr}`. It also shows
- 2026-10-27: on the AS page, a click on the heading of the IPv4 or the IPv6 that command's live answer (closes #156)
- 2026-10-27: On the AS page, a click on the heading of the IPv4 or the IPv6
prefix list folds or unfolds the list. Both lists start open (closes #155) prefix list folds or unfolds the list. Both lists start open (closes #155)
- 2026-10-27: the AS page lists its IPv4 and its IPv6 prefixes by mask length, - 2026-10-27: The AS page lists its IPv4 and its IPv6 prefixes by mask length,
shortest first, and prefixes of one mask length by address. They used to be shortest first. Prefixes of one mask length are listed by address. They used
listed by address (closes #153) to be sorted by address first, then by mask length (closes #153)
- 2026-10-27: on `/` and `/status`, a spinner beside the status turns one frame - 2026-10-27: The connection status on `/` and `/status` gets a spinner. It
each time the stats show more messages than the time before. A page that has turns one frame each time the stats show more messages than the time before.
not seen more messages for three refreshes shows "stale" and the time since After three refreshes with no new messages, the page shows "stale" in red
then instead, in red (closes #152) instead. Next to it is the time since the last fresh answer (closes #152)
- 2026-10-27: the WHOIS details of a Brazilian AS keep their accented letters. - 2026-10-27: The WHOIS details of a Brazilian AS keep their accented letters.
LACNIC's answer for such an AS comes from NIC.br, Brazil's registry, with each LACNIC's answer for such an AS is NIC.br's answer with each accented letter
accented letter replaced. The details now come from NIC.br's own server, replaced. NIC.br is Brazil's registry. The details now come from NIC.br's own
`whois.registro.br`. When that query fails, the details from LACNIC's answer server, `whois.registro.br`. When that query fails, the details from LACNIC's
are kept and a warning is logged. After NIC.br answers that RouteWatch is over answer are kept and a warning is logged. RouteWatch stops asking NIC.br for an
its query limit, RouteWatch stops asking NIC.br for an hour (closes #174) hour after NIC.br says RouteWatch is over its query limit (closes #174)
- 2026-10-27: `make asupdate` stops with an error when the download of `as.csv` - 2026-10-27: `make asupdate` stops with an error when the download of `as.csv`
breaks off. The generator used to retry the failed read forever. A record that breaks off. The generator used to retry the failed read forever. A record that
does not parse is still logged and skipped (closes #177) does not parse is still logged and skipped (closes #177)
@@ -149,182 +235,192 @@ tested.
one AS. A failed download used to replace the list with an empty file. The one AS. A failed download used to replace the list with an empty file. The
generator reads `as.csv` from `ipverse/as-metadata`, the source's new name generator reads `as.csv` from `ipverse/as-metadata`, the source's new name
(closes #173) (closes #173)
- 2026-10-27: the WHOIS details of an AS at RIPE, APNIC or AFRINIC come only - 2026-10-27: The WHOIS details of an AS at RIPE, APNIC or AFRINIC come only
from its `aut-num` object and the organisation object it names. RIPE and APNIC from its `aut-num` object and the organisation object it names. RIPE and APNIC
start their answer with the `as-block` object of the AS's block. Its dates start their answer with the `as-block` object of the AS's block. Its dates
were stored as the AS's (closes #168) were stored as the AS's (closes #168)
- 2026-10-27: AS names keep their accented letters. The AS list built into - 2026-10-27: AS names keep their accented letters. The AS list built into
RouteWatch is rebuilt from today's `as.csv`, which added a country code RouteWatch is rebuilt from today's `as.csv`, which added a country code
column. That file no longer lists AS 0 or the documentation AS numbers. A column. That file no longer lists AS 0 or the documentation AS numbers. A
WHOIS answer that is not valid UTF-8 is decoded as Latin-1, which RIPE and WHOIS answer that is not valid UTF-8 is decoded as Latin-1 before it is parsed
APNIC send, before it is parsed and stored (closes #165) and stored. RIPE and APNIC send Latin-1 (closes #165)
- 2026-10-27: the Age column on the AS and prefix pages reads in words, such as - 2026-10-27: The Age column on the AS and prefix pages reads in words, such as
"5 minutes ago" or "2 weeks ago", instead of Go durations such as "360h0m0s "5 minutes ago" or "2 weeks ago". It used to print Go durations such as
ago". An age under a minute reads in seconds, and one over a month in months "360h0m0s ago". An age under a minute reads "now" or in seconds. An age over a
or years instead of a date (closes #163) month reads in months or years instead of a date (closes #163)
- 2026-10-26: a write to a stored AS, peering or peer keeps the earlier of the - 2026-10-26: A write to a stored AS, peering or peer keeps the earlier of the
two first-seen times and the later of the two last-seen times. An old update two first-seen times. It keeps the later of the two last-seen times. An old
from a collector catching up on a backlog no longer moves last seen back update from a collector catching up on a backlog no longer moves last seen
(closes #162) back (closes #162)
- 2026-10-26: the status page shows "Route Churn/min", the number of prefix - 2026-10-26: The status page shows "Route Churn/min". That is the number of
announcements and withdrawals, from all peers, in the last full clock minute. prefix announcements and withdrawals from all peers in the last full clock
`/api/v1/stats` reports it as `route_churn_per_min` in `stream`, which minute. `/api/v1/stats` reports it as `route_churn_per_min` in `stream`. It
replaces the moving average `route_churn_per_sec`. The messages and updates replaces the moving average `route_churn_per_sec`. The messages and updates
per second on `/` and `/status` are whole numbers (closes #160) per second on `/` and `/status` are whole numbers (closes #160)
- 2026-10-26: the WHOIS fetcher backs off more slowly. A failure makes its wait - 2026-10-26: The WHOIS fetcher backs off more slowly. A failure makes its wait
1.5 times as long, up to one minute instead of five. Its queries to RIPE, 1.5 times as long, up to one minute instead of five. Its queries to RIPE,
APNIC and AFRINIC leave out person and role objects, which RIPE counts against APNIC and AFRINIC leave out person and role objects. RIPE counts those objects
a daily limit per address. A refused query is logged with the RIR's error line against a daily limit per address. A refused query is logged with the RIR's
(closes #159) error line (closes #159)
- 2026-10-26: the home page's AS name search lists the ASes whose handle or - 2026-10-26: The home page's AS name search works. It lists the ASes whose
description holds the text, as links to their pages, from the new handle or description holds the text, as links to their pages. The new
`/api/v1/search/as`; the search ignores case. When the database has no record `/api/v1/search/as` answers it. The search ignores case. When the database has
of an AS, its page takes the handle and description from the AS list built no record of an AS, its page takes the handle and description from the AS list
into RouteWatch and still lists the AS's prefixes (closes #151) built into RouteWatch. It still lists the AS's prefixes (closes #151)
- 2026-10-19: README "HTTP Endpoints" lists every route with what it answers, - 2026-10-19: README "HTTP Endpoints" lists every route with what it answers.
"Database Schema" matches `schema.sql`, and the rest of the README matches the README "Database Schema" matches `schema.sql`. The rest of the README matches
code; this file brought up to date (closes #72) the code. This file is brought up to date (closes #72)
- 2026-10-19: route writes are cheaper: the live route and prefix tables lose - 2026-10-19: Route writes are cheaper. The live route and prefix tables lose
their random UUID keys and the prefix tables their duplicate index, a route their random UUID keys. The prefix tables lose their duplicate index. A route
update sets only the columns that change, and every write goes through one update sets only the columns that change. Every write goes through one
connection with a page cache of 1 GiB (README "Memory"). A benchmark writes connection with a page cache of 1 GiB (README "Memory"). A benchmark writes
the prefix handler's largest batch faster than the feed sends it (closes #96) the prefix handler's largest batch faster than the feed sends it (closes #96)
- 2026-10-19: the WAL checkpoint, the incremental vacuum and ANALYZE take the - 2026-10-19: The checkpoint of the WAL (SQLite's write-ahead log), the
database lock every batch write holds, so a vacuum no longer fails with incremental vacuum and `ANALYZE` take the database lock that every batch write
"database is locked" and an ANALYZE no longer makes a batch write lose its holds. So a vacuum no longer fails with "database is locked". An `ANALYZE` no
updates; ANALYZE runs as `PRAGMA optimize` with an analysis limit (closes #94) longer makes a batch write lose its updates. `ANALYZE` runs as
- 2026-10-19: shutdown stops the streamer first, and each handler writes `PRAGMA optimize` with an analysis limit (closes #94)
everything left on its queue before it stops, so the updates waiting there are - 2026-10-19: Shutdown stops the streamer first. Each handler then writes
everything left on its queue before it stops. So the updates waiting there are
no longer lost (closes #69) no longer lost (closes #69)
- 2026-10-19: a path that ends in an AS set of several members has origin AS 0, - 2026-10-19: A path that ends in an AS set of several members has origin AS 0,
no known origin, instead of the set's last member, and the set adds no which means no known origin. It used to have the set's last member as its
peerings; the pages show such a route as having no known origin (closes #75) origin. The set adds no peerings. The pages show such a route as having no
known origin (closes #75)
- 2026-10-19: `bgp_peer_count` drops to 0 when the last peer goes down (closes - 2026-10-19: `bgp_peer_count` drops to 0 when the last peer goes down (closes
#92) #92)
- 2026-10-19: `bgp_peer_count` counts every peer the feed has heard from, not - 2026-10-19: `bgp_peer_count` counts every peer the feed has heard from. It
only those whose session opened since startup, and drops a peer whose session used to count only the peers whose session opened since startup. It drops a
goes down (closes #74) peer whose session goes down (closes #74)
- 2026-10-19: the shared files are re-vendored from `sneak/prompts` at - 2026-10-19: The shared files are re-vendored from `sneak/prompts` at
`0653579`: golangci-lint v2.14.0 and its configuration, lint and test as `0653579`. The linter is `golangci-lint` v2.14.0 with its configuration. Lint
`Dockerfile` phases that keep Go's and golangci-lint's caches, markdown and test are `Dockerfile` phases that keep Go's and `golangci-lint`'s caches.
formatted with prettier, agent guidance in `AGENTS.md`; the code is fixed for `make fmt` also formats the markdown with `prettier`. The agent guidance moves
what the new linter configuration finds (closes #52) to `AGENTS.md`. The code is fixed for what the new linter configuration finds
- 2026-10-19: the streamer reads feed lines up to 1 MiB, so a line over 64 KiB (closes #52)
no longer ends the connection (closes #76) - 2026-10-19: The streamer reads feed lines up to 1 MiB. A line over 64 KiB used
- 2026-10-19: a peer's live routes are removed when its BGP session goes down; to end the connection (closes #76)
`STATE` messages are never dropped for backpressure, and one that finds its - 2026-10-19: A peer's live routes are removed when its BGP session goes down.
`STATE` messages are never dropped when a queue is full. One that finds its
queue full waits for room ahead of the handler's other messages (closes #56) queue full waits for room ahead of the handler's other messages (closes #56)
- 2026-10-19: the prefix-length pages pick their sample with a bounded number of - 2026-10-19: The prefix-length pages pick their sample with a bounded number of
index lookups instead of reading every route of that length, and list each index lookups. They used to read every route of that length. They list each
prefix once (closes #66) prefix once (closes #66)
- 2026-10-19: a request past its time limit answers 504 instead of 408, and - 2026-10-19: A request past its time limit answers 504 instead of 408.
`/api/v1/stats` answers 504 instead of 500 when its read runs out of time `/api/v1/stats` answers 504 instead of 500 when its read runs out of time
(closes #70) (closes #70)
- 2026-10-19: the AS, peer and prefix handlers write each batch outside the lock - 2026-10-19: The AS, peer and prefix handlers write each batch outside the lock
their message handling needs, so messages keep coming off their queues during their message handling needs. So messages keep coming off their queues during
a write; meanwhile the next batch grows to at most ten batch sizes (closes a write. Meanwhile the next batch grows to at most ten batch sizes (closes
#65) #65)
- 2026-10-19: a live route is identified by prefix and peer, so an announcement - 2026-10-19: A live route is identified by prefix and peer. So an announcement
with a new origin AS replaces the peer's route and a withdrawal removes it with a new origin AS replaces the peer's route. A withdrawal removes it
whatever its origin AS (closes #55) whatever its origin AS (closes #55)
- 2026-10-14: the streamer reconnects when RIS Live ends the stream or sends - 2026-10-14: The streamer reconnects when RIS Live ends the stream or sends
nothing for 60 seconds, and the health check reports the feed disconnected nothing for 60 seconds. The health check reports the feed disconnected
meanwhile (closes #53) meanwhile (closes #53)
- 2026-10-14: the prefix page takes the names of the origin ASes from the prefix - 2026-10-14: The prefix page takes the names of the origin ASes from the prefix
query instead of reading every route of each origin AS (closes #67) query. It used to read every route of each origin AS (closes #67)
- 2026-10-14: the daemon exits with status 1 when its web server cannot listen - 2026-10-14: The daemon exits with status 1 when its web server cannot listen
on its port, instead of running on without it (closes #73) on its port. It used to run on without a web server (closes #73)
- 2026-10-14: the prefix pages parse the prefix before looking it up: one that - 2026-10-14: The prefix pages parse the prefix before looking it up. One that
does not parse answers 400, and any valid way of writing a prefix finds its does not parse answers 400. Any valid way of writing a prefix finds its routes
routes (closes #71) (closes #71)
- 2026-10-14: the IP lookup ignores routes shorter than /8 for IPv4 and /16 for - 2026-10-14: The IP lookup ignores routes shorter than /8 for IPv4 and /16 for
IPv6, so a default route is no longer named as an address's owner (closes #57) IPv6. So a default route is no longer named as an address's owner (closes #57)
- 2026-10-14: a prefix batch keeps each peer's last update for a prefix, instead - 2026-10-14: A prefix batch keeps each peer's last update for a prefix. It used
of one update per prefix across all peers (closes #54) to keep one update per prefix across all peers (closes #54)
- 2026-10-14: `reconnect_count` in `/api/v1/stats` counts every reconnect - 2026-10-14: `reconnect_count` in `/api/v1/stats` counts every reconnect
(closes #68) (closes #68)
- 2026-10-03: `/api/v1/stats` serves the prefix distribution from memory, seeded - 2026-10-03: `/api/v1/stats` serves the prefix distribution from memory. The
at startup and adjusted on every live-route write, so a request no longer distribution is seeded at startup and adjusted on every live-route write. So a
reads every live route (closes #30) request no longer reads every live route (closes #30)
- 2026-10-03: a new database is created with `auto_vacuum` set to incremental, - 2026-10-03: A new database is created with `auto_vacuum` set to incremental.
through the connection string so it is set before the file is first written, The setting goes in the connection string, so it is set before the file is
and each periodic incremental vacuum now returns up to 1000 free pages; the first written. Each periodic incremental vacuum now returns up to 1000 free
late `PRAGMA auto_vacuum` in `Initialize`, which SQLite ignored, is gone pages. The late `PRAGMA auto_vacuum` in `Initialize`, which SQLite ignored, is
(closes #43) gone (closes #43)
- 2026-10-03: looking up an IP address no longer reads every IPv6 route: both - 2026-10-03: Looking up an IP address no longer reads every IPv6 route. Both
families find the most specific live route with at most 33 or 129 lookups on families find the most specific live route with at most 33 or 129 lookups on
the prefix index, and the IPv4 range columns are gone. Prefixes from the feed the prefix index. The IPv4 range columns are gone. Prefixes from the feed are
are stored in one text form, so an IPv6 withdrawal, which the feed sends stored in one text form. So an IPv6 withdrawal, which the feed sends
uncompressed, now removes its route (closes #48) uncompressed, now removes its route (closes #48)
- 2026-10-02: a plain `docker build .` stamps the commit's tag or short commit - 2026-10-02: A plain `docker build .` stamps the commit's tag or short commit
(`git describe --tags --always`) into the page footer instead of `unknown`: into the page footer. It used to stamp `unknown`. The value comes from
`.dockerignore` sends `.git` without `.git/config`, a `VERSION` build argument `git describe --tags --always`. `.dockerignore` sends `.git` without
takes precedence, and `make build` stamps the same value (closes #46) `.git/config`. A `VERSION` build argument takes precedence. `make build`
- 2026-09-29: the entrypoint creates the data directory if it is missing and stamps the same value (closes #46)
stops the start if a step fails; README "Running under upaas" no longer asks - 2026-09-29: The entrypoint creates the data directory if it is missing. It
stops the start if a step fails. README "Running under upaas" no longer asks
for the host directory to be created first (closes #42) for the host directory to be created first (closes #42)
- 2026-09-29: `.dockerignore` keeps `.git`, local build output, local databases - 2026-09-29: `.dockerignore` keeps `.git`, local build output, local databases
and `.env` out of the Docker build context, and so out of the source archive and `.env` out of the Docker build context. So they stay out of the source
in the image (closes #39) archive in the image (closes #39)
- 2026-09-29: README first line names the MIT license and the author; the - 2026-09-29: The README's first line names the MIT licence and the author. The
License section now says MIT and links `LICENSE`, and an Author section was License section says MIT and links `LICENSE`. An Author section is added. This
added; this file brought up to date (closes #38) file is brought up to date (closes #38)
- 2026-09-29: MIT `LICENSE` (closes #1) - 2026-09-29: `LICENSE` is added, with the MIT licence (closes #1)
- 2026-09-28: stopping the daemon while the feed is flowing no longer panics - 2026-09-28: Stopping the daemon while the feed is flowing no longer panics
with "send on closed channel": the read loop checks for a stop just before with "send on closed channel". The read loop checks for a stop just before
handing a message to the handler queues, and a second `Stop` no longer closes handing a message to the handler queues. A second `Stop` no longer closes the
the queues again (closes #34) queues again (closes #34)
- 2026-09-28: `docker stop` no longer kills the daemon 2 seconds after the stop - 2026-09-28: `docker stop` no longer kills the daemon 2 seconds after the stop
signal: the entrypoint switches to the `routewatch` user with `setpriv` signal. The entrypoint switches to the `routewatch` user with `setpriv`
instead of `runuser`, so the daemon receives the signal itself and gets the instead of `runuser`. So the daemon receives the signal itself. It gets the
whole wait `docker stop` allows, up to its own 60-second limit (closes #33) whole wait `docker stop` allows, up to its own 60-second limit (closes #33)
- 2026-09-28: ready to run under upaas: a set but invalid `PORT`, - 2026-09-28: RouteWatch is ready to run under upaas. A set but invalid `PORT`,
`XDG_DATA_HOME` or `MALLOC_ARENA_MAX` stops the start, the health check `XDG_DATA_HOME` or `MALLOC_ARENA_MAX` stops the start. The health check
follows `PORT`, README "Running under upaas" section (closes #31) follows `PORT`. README gains a "Running under upaas" section (closes #31)
- 2026-09-22: realtime in-memory database statistics: counts seeded at startup - 2026-09-22: The database statistics are kept in memory. The counts are seeded
and adjusted on every write, oldest/newest route timestamps via index-end at startup and adjusted on every write. The oldest and newest route times come
lookups; `/api/v1/stats` no longer scans the tables (closes #27) from a lookup at each end of an index. `/api/v1/stats` no longer scans the
- 2026-09-21: batch writes take the write lock when their transaction begins tables (closes #27)
(`_txlock=immediate`), so they wait out a WAL checkpoint instead of failing - 2026-09-21: Batch writes take the write lock when their transaction begins
(`_txlock=immediate`). So they wait out a WAL checkpoint instead of failing
with "database is locked" (closes #25) with "database is locked" (closes #25)
- 2026-09-21: `MALLOC_ARENA_MAX=2` in the image caps glibc malloc arenas, so - 2026-09-21: `MALLOC_ARENA_MAX=2` in the image caps the number of glibc malloc
memory outside the Go runtime no longer grows with the core count (closes #23) arenas. So memory outside the Go runtime no longer grows with the core count
- 2026-09-21: `GOMEMLIMIT=1536MiB` in the image; README Memory section with the (closes #23)
- 2026-09-21: The image sets `GOMEMLIMIT=1536MiB`. README "Memory" gives the
memory budget and the 5 GiB container limit (closes #13) memory budget and the 5 GiB container limit (closes #13)
- 2026-09-21: the four handler queues hold at most 20,000 messages each, down - 2026-09-21: The four handler queues hold at most 20,000 messages each, down
from 100,000 (closes #11) from 100,000 (closes #11)
- 2026-09-21: two goroutine leaks fixed: the stats handlers after a timeout and - 2026-09-21: Two goroutine leaks are fixed. The stats handlers leaked after a
the streamer's tickers on every reconnect (closes #12) timeout. The streamer's tickers leaked on every reconnect (closes #12)
- 2026-09-21: parsed RIS messages no longer keep the unused `Community` and - 2026-09-21: Parsed RIS messages no longer keep the unused `Community` and
`Raw` fields (closes #9) `Raw` fields (closes #9)
- 2026-09-21: `.editorconfig`, and a Gitea workflow that runs `script/cibuild` - 2026-09-21: `.editorconfig` is added. A Gitea workflow runs `script/cibuild`
on every push (closes #14) on every push (closes #14)
- 2026-09-21: the peering handler's AS-path map holds at most 500,000 paths and - 2026-09-21: The peering handler's AS-path map holds at most 500,000 paths.
is swapped for an empty one every 30 seconds instead of copied (closes #10) Every 30 seconds it is swapped for an empty one instead of copied (closes #10)
- 2026-09-21: SQLite memory bounded across the whole connection pool: a 64 MiB - 2026-09-21: SQLite's memory is bounded across the whole connection pool. Each
page cache on each connection, 1 GiB soft and 1.5 GiB hard heap limits (closes connection has a 64 MiB page cache. The heap limits are 1 GiB soft and 1.5 GiB
#8) hard (closes #8)
- 2026-09-21: the Docker build runs the format check, the linter and the tests, - 2026-09-21: The Docker build runs the format check, the linter and the tests.
linting in a separate stage on a golangci-lint image pinned by digest (closes Linting runs in a separate stage on a `golangci-lint` image pinned by digest
#5) (closes #5)
- 2026-09-21: `make test` skips the live-network feed test (`-short`), so - 2026-09-21: `make test` skips the live feed test, with `-short`. So
`make check` no longer depends on the network (closes #2) `make check` no longer depends on the network (closes #2)
- 2026-07-07 Adopted scripts-to-rule-them-all: `script/` entrypoints, Makefile - 2026-07-07: The scripts-to-rule-them-all layout is adopted. `script/` holds
shims, README Entrypoints section the entrypoints. The `Makefile` targets `check`, `test`, `lint`, `fmt` and
- 2026-02-22: repo policy compliance: required policy files, .gitignore update, `fmt-check` call them. So do `bootstrap`, `setup`, `docker` and `hooks`.
Makefile fmt-check/check/docker/hooks targets, gofmt pass README gains an "Entrypoints" section
(repo-policies-compliance, unmerged) - 2026-02-22: The repo is brought in line with the repo policies. The required
- 2026-01-01: WAL checkpointing: periodic (5s), on startup with logging, policy files are added. `.gitignore` is updated. The `Makefile` gains
TRUNCATE mode; fixed slow queries `fmt-check`, `check`, `docker` and `hooks` targets. The Go code is formatted
- 2025-12-31: status page: navbar, home page with search, oldest/newest route with `gofmt`. The work was on the branch `repo-policies-compliance`, unmerged
timestamps, NULL handling in WHOIS stats; container runs as routewatch user when this entry was written
with proper state dir - 2026-01-01: The WAL is checkpointed every 5 seconds, and at startup with a log
- 2025-12-30: structured HTTP request logging, increased timeouts, CIDR prefix line. Checkpoints run in `TRUNCATE` mode. This fixed slow queries
URL routing fixes, status page metrics and footer - 2025-12-31: The pages get a navigation bar and a home page with a search. The
- 2025-12-29: Dockerfile multi-stage build with source archive; SQLite status page shows the oldest and newest route times. The WHOIS stats query
incremental vacuum for non-blocking space reclamation handles `NULL`. The container runs as the `routewatch` user with the right
- 2025-07-27: initial RouteWatch BGP stream monitor state directory
- 2025-12-30: HTTP requests are logged as structured log lines. The HTTP
timeouts are longer. Prefix URLs with a slash in them route correctly. The
status page gets more metrics and a footer
- 2025-12-29: The `Dockerfile` builds in stages and puts a source archive in the
image. SQLite reclaims space with incremental vacuum, which does not block
- 2025-07-27: The first commit: RouteWatch, a BGP stream monitor
# Future Steps # Future Steps
None.
internal/database/database_internal_test.go
+1 -1
View File
@@ -273,7 +273,7 @@ func TestVacuumReturnsFreePages(t *testing.T) {
writeTableChanges(t, db, table) writeTableChanges(t, db, table)
// The peer going down removes every prefix, and so every row. // The peer going down removes every prefix, and so every row.
table.PeerDown(peerA) table.PeersDown([]string{peerA})
writeTableChanges(t, db, table) writeTableChanges(t, db, table)
var before int var before int
internal/database/routes_internal_test.go
+2 -2
View File
@@ -107,7 +107,7 @@ func TestReadRouteTableGivesBackWhatWasWritten(t *testing.T) {
// A peer moves to another origin, one goes down and a new one comes. // A peer moves to another origin, one goes down and a new one comes.
announceTo(source, tablePrefixV4, asB, peerA, 60) announceTo(source, tablePrefixV4, asB, peerA, 60)
source.PeerDown(peerC) source.PeersDown([]string{peerC})
announceTo(source, tablePrefixV6, asB, peerE, 70) announceTo(source, tablePrefixV6, asB, peerE, 70)
writeTableChanges(t, db, source) writeTableChanges(t, db, source)
@@ -133,7 +133,7 @@ func TestReadRouteTableGivesATableThatTakesLaterUpdates(t *testing.T) {
// another one goes down, and a new peer comes. // another one goes down, and a new peer comes.
for _, table := range []*routetable.Table{source, read} { for _, table := range []*routetable.Table{source, read} {
table.Withdraw(netip.MustParsePrefix(tablePrefixV4), peerA) table.Withdraw(netip.MustParsePrefix(tablePrefixV4), peerA)
table.PeerDown(peerB) table.PeersDown([]string{peerB})
announceTo(table, tablePrefixShortV4, asB, peerD, 50) announceTo(table, tablePrefixShortV4, asB, peerD, 50)
} }
internal/routetable/overview.go
+15 -10
View File
@@ -10,10 +10,6 @@ import (
"git.eeqj.de/sneak/routewatch/internal/ristypes" "git.eeqj.de/sneak/routewatch/internal/ristypes"
) )
// walkBatch is how many prefixes the walk over the whole table reads in one
// hold of the read lock. The updates waiting for the lock get it in between.
const walkBatch = 10000
// Overview holds figures about the whole table. Working them out takes a walk // Overview holds figures about the whole table. Working them out takes a walk
// over every prefix, so a caller asks for them now and then and keeps them. // over every prefix, so a caller asks for them now and then and keeps them.
type Overview struct { type Overview struct {
@@ -83,8 +79,9 @@ type OriginPeers struct {
// Overview works out the table's overview. It lists at most maxListed bogon // Overview works out the table's overview. It lists at most maxListed bogon
// announcements and at most maxListed prefixes with more than one origin AS: // announcements and at most maxListed prefixes with more than one origin AS:
// the first in prefix order. It walks over every prefix, but holds the read // the first in prefix order. It visits every prefix in the table, in batches
// lock for walkBatch prefixes at a time. // of walkBatch. After each batch, it lets the table's lock go for as long as
// it held the lock for the batch.
func (t *Table) Overview(maxListed int) Overview { func (t *Table) Overview(maxListed int) Overview {
var overview Overview var overview Overview
@@ -114,15 +111,18 @@ func (t *Table) Overview(maxListed int) Overview {
} }
// walkPrefixes calls visit with every prefix of the table and its origins. It // walkPrefixes calls visit with every prefix of the table and its origins. It
// holds the read lock, but lets it go after every walkBatch prefixes, so the // holds the read lock for walkBatch prefixes at a time. After each batch, it
// updates waiting for it get in. A prefix that is added or removed in such a // lets the table's lock go for as long as it held the lock for the batch.
// gap may or may not be visited, as Go allows for a map that changes during a // During a walk over many batches, updates can then take the lock about half
// range over it. visit must not keep origins once it returns. // of the time. The walk may or may not visit a prefix that is added or removed
// while the lock is let go. Go allows this in a range over a map that changes.
// visit must not keep origins once it returns.
func (t *Table) walkPrefixes(visit func(prefix netip.Prefix, origins []*origin)) { func (t *Table) walkPrefixes(visit func(prefix netip.Prefix, origins []*origin)) {
t.mu.RLock() t.mu.RLock()
defer t.mu.RUnlock() defer t.mu.RUnlock()
visited := 0 visited := 0
batchStart := time.Now()
for _, f := range []*family{&t.ipv4, &t.ipv6} { for _, f := range []*family{&t.ipv4, &t.ipv6} {
for _, prefixes := range f.byLength { for _, prefixes := range f.byLength {
@@ -131,8 +131,13 @@ func (t *Table) walkPrefixes(visit func(prefix netip.Prefix, origins []*origin))
visited++ visited++
if visited%walkBatch == 0 { if visited%walkBatch == 0 {
held := time.Since(batchStart)
t.mu.RUnlock() t.mu.RUnlock()
time.Sleep(held)
t.mu.RLock() t.mu.RLock()
batchStart = time.Now()
} }
} }
} }
internal/routetable/overview_internal_test.go
+58
View File
@@ -131,3 +131,61 @@ func TestWalkPrefixesLetsUpdatesIn(t *testing.T) {
"before its second batch") "before its second batch")
} }
} }
// TestOverviewLetsUpdatesIn applies another peer's 1,000 announcements while
// Overview walks a table with more prefixes than five of the walk's batches.
// After each batch, the walk lets the lock go for as long as it held the lock.
// So all 1,000 announcements must be applied before Overview returns. A walk
// that takes the lock back at once lets in about one update per batch.
func TestOverviewLetsUpdatesIn(t *testing.T) {
t.Parallel()
const (
asn = 1000
peer = "192.0.2.1"
otherPeer = "192.0.2.2"
// prefixCount is more prefixes than five of the walk's batches.
prefixCount = 5*walkBatch + 1
announcements = 1000
)
routeTime := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC)
table := New(Params{})
prefixes := make([]netip.Prefix, 0, prefixCount)
addr := netip.MustParseAddr("1.0.0.0")
for range prefixCount {
prefix := netip.PrefixFrom(addr, addr.BitLen())
table.Announce(prefix, asn, Route{Peer: peer, Time: routeTime})
prefixes = append(prefixes, prefix)
addr = addr.Next()
}
overviewDone := make(chan struct{})
go func() {
defer close(overviewDone)
table.Overview(0)
}()
// Wait until Overview holds the read lock. TryLock fails while a reader
// holds it.
for table.mu.TryLock() {
table.mu.Unlock()
runtime.Gosched()
}
for _, prefix := range prefixes[:announcements] {
table.Announce(prefix, asn, Route{Peer: otherPeer, Time: routeTime})
}
select {
case <-overviewDone:
t.Fatal("Overview returned before another peer's 1,000 announcements " +
"were applied")
default:
}
<-overviewDone
}
internal/routetable/reads_test.go
+1 -1
View File
@@ -227,7 +227,7 @@ func TestCounts(t *testing.T) {
}) })
// peerC was the last peer of the IPv6 prefix. It keeps its number. // peerC was the last peer of the IPv6 prefix. It keeps its number.
table.PeerDown(peerC) table.PeersDown([]string{peerC})
checkCounts(t, table, routetable.Counts{ checkCounts(t, table, routetable.Counts{
Pairs: 2, Pairs: 2,
Peers: 3, Peers: 3,
internal/routetable/routetable.go
+50 -9
View File
@@ -27,6 +27,11 @@ const (
// kept routes in order: each of its nodes holds up to 63 times. // kept routes in order: each of its nodes holds up to 63 times.
keptTimesDegree = 32 keptTimesDegree = 32
// walkBatch is how many prefixes a walk over the whole table visits in
// one hold of the lock. Overview and PeersDown each walk the whole table.
// Callers waiting for the lock get it between batches.
walkBatch = 10000
ipv4Bits = 32 ipv4Bits = 32
ipv6Bits = 128 ipv6Bits = 128
@@ -200,24 +205,60 @@ func (t *Table) Withdraw(prefix netip.Prefix, peer string) {
} }
} }
// PeerDown applies a peer's session going down: the peer leaves every peer // PeersDown applies the sessions of peers going down: each of the peers leaves
// set, and every route of it is dropped. When the peer carries any prefix, it // every peer set, and every route of each is dropped. When any of them carries
// visits every prefix in the table. // a prefix, PeersDown visits every prefix in the table once, in batches of
func (t *Table) PeerDown(peer string) { // walkBatch. After each batch, it lets the table's lock go for as long as it
// held the lock for the batch. During a walk over many batches, reads and
// updates can then take the lock about half of the time. An announcement by
// one of the peers applied during the walk may be dropped too. So the caller
// applies those peers' later updates only once PeersDown has returned.
func (t *Table) PeersDown(peers []string) {
t.mu.Lock() t.mu.Lock()
defer t.mu.Unlock() defer t.mu.Unlock()
number, known := t.peerNumbers[peer] // numbers holds the number of each of the peers that carries a prefix.
if !known || t.peerPrefixes[number] == 0 { numbers := make([]uint, 0, len(peers))
for _, peer := range peers {
number, known := t.peerNumbers[peer]
if known && t.peerPrefixes[number] > 0 {
numbers = append(numbers, number)
}
}
if len(numbers) == 0 {
return return
} }
visited := 0
batchStart := time.Now()
for _, f := range []*family{&t.ipv4, &t.ipv6} { for _, f := range []*family{&t.ipv4, &t.ipv6} {
for _, prefixes := range f.byLength { for _, prefixes := range f.byLength {
for prefix, origins := range prefixes { for prefix, origins := range prefixes {
o := originWithPeer(origins, number) for _, number := range numbers {
if o != nil { o := originWithPeer(origins, number)
t.leave(prefix, o, number) if o != nil {
t.leave(prefix, o, number)
// leave may have removed an origin of the
// prefix, or the prefix itself.
origins = prefixes[prefix]
}
}
// Go allows the map to change before the next step of
// the range over it.
visited++
if visited%walkBatch == 0 {
held := time.Since(batchStart)
t.mu.Unlock()
time.Sleep(held)
t.mu.Lock()
batchStart = time.Now()
} }
} }
} }
internal/routetable/routetable_internal_test.go
+69
View File
@@ -0,0 +1,69 @@
package routetable
import (
"net/netip"
"runtime"
"testing"
"time"
)
// TestPeersDownLetsReadsIn reads the table's counts again and again while a
// peer that carries more than two batches of prefixes goes down. PeersDown lets
// the lock go after every walkBatch prefixes, so a read must get in while the
// peer still carries some of its prefixes but no longer all.
func TestPeersDownLetsReadsIn(t *testing.T) {
t.Parallel()
const (
asn = 1000
peer = "192.0.2.1"
// prefixCount is more prefixes than two of walkBatch.
prefixCount = 2*walkBatch + 1
)
routeTime := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC)
table := New(Params{})
addr := netip.MustParseAddr("1.0.0.0")
for range prefixCount {
prefix := netip.PrefixFrom(addr, addr.BitLen())
table.Announce(prefix, asn, Route{Peer: peer, Time: routeTime})
addr = addr.Next()
}
// Hold a read lock until PeersDown waits for the lock, so that the first
// read below starts once PeersDown holds it. TryRLock fails once a writer
// waits.
table.mu.RLock()
peerDownDone := make(chan struct{})
go func() {
defer close(peerDownDone)
table.PeersDown([]string{peer})
}()
for table.mu.TryRLock() {
table.mu.RUnlock()
runtime.Gosched()
}
table.mu.RUnlock()
for {
routes := table.Counts().IPv4Routes
if routes > 0 && routes < prefixCount {
break
}
select {
case <-peerDownDone:
t.Fatal("no read got in while PeersDown ran")
default:
}
}
<-peerDownDone
}
internal/routetable/routetable_test.go
+44 -11
View File
@@ -69,10 +69,10 @@ func withdraw(peer string) step {
} }
} }
// peerDown is the step of peer's session going down. // peersDown is the step of the sessions of peers going down.
func peerDown(peer string) step { func peersDown(peers ...string) step {
return func(table *routetable.Table, _ netip.Prefix) { return func(table *routetable.Table, _ netip.Prefix) {
table.PeerDown(peer) table.PeersDown(peers)
} }
} }
@@ -272,21 +272,28 @@ func TestWithdrawalsAndPeerDowns(t *testing.T) {
{ {
name: "a peer going down leaves the prefix", name: "a peer going down leaves the prefix",
steps: []step{announce(peerA, asA, 10), announce(peerB, asA, 20), steps: []step{announce(peerA, asA, 10), announce(peerB, asA, 20),
peerDown(peerB)}, peersDown(peerB)},
want: []routetable.Origin{{ASN: asA, Peers: []string{peerA}, want: []routetable.Origin{{ASN: asA, Peers: []string{peerA},
Routes: []routetable.Route{routeOf(peerA, asA, 10)}}}, Routes: []routetable.Route{routeOf(peerA, asA, 10)}}},
}, },
{ {
name: "a peer going down after it withdrew changes nothing", name: "a peer going down after it withdrew changes nothing",
steps: []step{announce(peerA, asA, 10), announce(peerB, asA, 20), steps: []step{announce(peerA, asA, 10), announce(peerB, asA, 20),
withdraw(peerB), peerDown(peerB)}, withdraw(peerB), peersDown(peerB)},
want: []routetable.Origin{{ASN: asA, Peers: []string{peerA}, want: []routetable.Origin{{ASN: asA, Peers: []string{peerA},
Routes: []routetable.Route{routeOf(peerA, asA, 10)}}}, Routes: []routetable.Route{routeOf(peerA, asA, 10)}}},
}, },
{
name: "peers going down together each leave the prefix",
steps: []step{announce(peerA, asA, 10), announce(peerB, asB, 20),
announce(peerC, asB, 30), peersDown(peerA, peerB)},
want: []routetable.Origin{{ASN: asB, Peers: []string{peerC},
Routes: []routetable.Route{routeOf(peerC, asB, 30)}}},
},
}) })
} }
func TestPeerDownLeavesEveryPrefix(t *testing.T) { func TestPeersDownLeavesEveryPrefix(t *testing.T) {
t.Parallel() t.Parallel()
table := routetable.New(routetable.Params{}) table := routetable.New(routetable.Params{})
@@ -303,7 +310,7 @@ func TestPeerDownLeavesEveryPrefix(t *testing.T) {
} }
table.Announce(prefixes[0], asB, routeOf(peerB, asB, 20)) table.Announce(prefixes[0], asB, routeOf(peerB, asB, 20))
table.PeerDown(peerA) table.PeersDown([]string{peerA})
want := []routetable.Origin{{ASN: asB, Peers: []string{peerB}, want := []routetable.Origin{{ASN: asB, Peers: []string{peerB},
Routes: []routetable.Route{routeOf(peerB, asB, 20)}}} Routes: []routetable.Route{routeOf(peerB, asB, 20)}}}
@@ -333,6 +340,32 @@ func TestPeerDownLeavesEveryPrefix(t *testing.T) {
} }
} }
// TestPeersDownTakesOutPeersOfDifferentPrefixes takes peerA and peerB out in
// one PeersDown. peerA carries only prefixV4, and peerB only prefixV6. So
// peerA's leaving removes prefixV4 before PeersDown looks for peerB there. Both
// prefixes must then be gone.
func TestPeersDownTakesOutPeersOfDifferentPrefixes(t *testing.T) {
t.Parallel()
table := routetable.New(routetable.Params{})
prefixes := []netip.Prefix{
netip.MustParsePrefix(prefixV4),
netip.MustParsePrefix(prefixV6),
}
table.Announce(prefixes[0], asA, routeOf(peerA, asA, 10))
table.Announce(prefixes[1], asB, routeOf(peerB, asB, 20))
table.PeersDown([]string{peerA, peerB})
for _, prefix := range prefixes {
got := table.Origins(prefix)
if got != nil {
t.Errorf("Origins(%s) = %+v after its only peer went down, want nil",
prefix, got)
}
}
}
func TestCountsOriginsWithoutKeptRoute(t *testing.T) { func TestCountsOriginsWithoutKeptRoute(t *testing.T) {
t.Parallel() t.Parallel()
@@ -358,7 +391,7 @@ func TestCountsOriginsWithoutKeptRoute(t *testing.T) {
{announce(peerC, asA, 30), 0}, {announce(peerC, asA, 30), 0},
{withdraw(peerB), 0}, {withdraw(peerB), 0},
{withdraw(peerC), 1}, {withdraw(peerC), 1},
{peerDown(peerA), 0}, {peersDown(peerA), 0},
} }
for i, s := range steps { for i, s := range steps {
@@ -464,7 +497,7 @@ func TestTakeChangesHoldsOnlyPairsThatChanged(t *testing.T) {
checkChanges(t, table, []change{}, map[string]uint{}) checkChanges(t, table, []change{}, map[string]uint{})
// peerA going down changes v4, the one prefix it carries. // peerA going down changes v4, the one prefix it carries.
table.PeerDown(peerA) table.PeersDown([]string{peerA})
checkChanges(t, table, []change{ checkChanges(t, table, []change{
{Prefix: prefixV4, OriginASN: asA, Peers: []uint{1, 2}, {Prefix: prefixV4, OriginASN: asA, Peers: []uint{1, 2},
Routes: []routetable.Route{ Routes: []routetable.Route{
@@ -473,7 +506,7 @@ func TestTakeChangesHoldsOnlyPairsThatChanged(t *testing.T) {
}, map[string]uint{}) }, map[string]uint{})
// peerA, which carries nothing now, goes down again. // peerA, which carries nothing now, goes down again.
table.PeerDown(peerA) table.PeersDown([]string{peerA})
checkChanges(t, table, []change{}, map[string]uint{}) checkChanges(t, table, []change{}, map[string]uint{})
} }
@@ -617,7 +650,7 @@ func TestConcurrentUse(t *testing.T) {
func(round int) { table.Announce(prefix, asA, routeOf(peerA, asA, round)) }, func(round int) { table.Announce(prefix, asA, routeOf(peerA, asA, round)) },
func(round int) { table.Announce(prefix, asB, routeOf(peerB, asB, round)) }, func(round int) { table.Announce(prefix, asB, routeOf(peerB, asB, round)) },
func(int) { table.Withdraw(prefix, peerA) }, func(int) { table.Withdraw(prefix, peerA) },
func(int) { table.PeerDown(peerB) }, func(int) { table.PeersDown([]string{peerB}) },
func(int) { table.PutBackChanges(table.TakeChanges(math.MaxInt)) }, func(int) { table.PutBackChanges(table.TakeChanges(math.MaxInt)) },
func(int) { table.ChangeCount() }, func(int) { table.ChangeCount() },
func(int) { table.Lookup(prefix.Addr()) }, func(int) { table.Lookup(prefix.Addr()) },
internal/routewatch/app_integration_internal_test.go
+15 -25
View File
@@ -509,8 +509,6 @@ func announcementFeed(prefixes []string) string {
func TestShutdownWritesTheUpdatesQueuedInTheStreamer(t *testing.T) { func TestShutdownWritesTheUpdatesQueuedInTheStreamer(t *testing.T) {
t.Parallel() t.Parallel()
const maxWait = 10 * time.Second
prefixes := []string{"192.0.2.0/24", "198.51.100.0/24", "203.0.113.0/24"} prefixes := []string{"192.0.2.0/24", "198.51.100.0/24", "203.0.113.0/24"}
feed := announcementFeed(prefixes) feed := announcementFeed(prefixes)
@@ -556,9 +554,9 @@ func TestShutdownWritesTheUpdatesQueuedInTheStreamer(t *testing.T) {
for range cap(linesSeen) { for range cap(linesSeen) {
select { select {
case <-linesSeen: case <-linesSeen:
case <-time.After(maxWait): case <-time.After(stepTimeout):
t.Fatalf("the streamer did not read %d lines within %s", 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 { select {
case <-shutDown: case <-shutDown:
case <-time.After(maxWait): case <-time.After(stepTimeout):
t.Fatalf("Shutdown did not return within %s", maxWait) t.Fatalf("Shutdown did not return within %s", stepTimeout)
} }
store.mu.Lock() store.mu.Lock()
@@ -609,21 +607,16 @@ func freePort(t *testing.T) int {
return addr.Port return addr.Port
} }
// TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked starts the HTTP server // TestShutdownDoesNotWaitForABlockedWrite starts the HTTP server and has the
// and has the AS handler start a write that the store holds until the test // AS handler start a write that the store holds until the test ends, past
// ends, past Shutdown's deadline. Shutdown must return within its deadline // Shutdown's deadline. Shutdown must return without waiting for the write, with
// plus a small margin, with the HTTP server stopped, and must neither // the HTTP server stopped, and must neither checkpoint nor close the database:
// checkpoint nor close the database: the real one would wait for the write. // the real one would wait for the write.
// Before the fix Shutdown waited for the write. // Before the fix Shutdown waited for the write.
func TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked(t *testing.T) { func TestShutdownDoesNotWaitForABlockedWrite(t *testing.T) {
t.Parallel() t.Parallel()
const ( const deadline = 100 * time.Millisecond
deadline = 100 * time.Millisecond
// margin is how long Shutdown may take after its deadline, to stop
// the HTTP server.
margin = 2 * time.Second
)
blocking := newBlockingStore() blocking := newBlockingStore()
defer blocking.releaseWrites() defer blocking.releaseWrites()
@@ -651,9 +644,8 @@ func TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked(t *testing.T) {
} }
rw.dbHandler = NewASHandler(store, log) rw.dbHandler = NewASHandler(store, log)
fill := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)}
startBlockedWrite(t, blocking, rw.dbHandler, startBlockedWrite(t, blocking, rw.dbHandler,
[]*ristypes.RISMessage{{Path: fill}}) []*ristypes.RISMessage{{Path: pathOfASes(asnBatchSize)}})
ctx, cancel := context.WithTimeout(t.Context(), deadline) ctx, cancel := context.WithTimeout(t.Context(), deadline)
defer cancel() defer cancel()
@@ -667,9 +659,9 @@ func TestShutdownReturnsByItsDeadlineWhileAWriteIsBlocked(t *testing.T) {
select { select {
case <-shutDown: case <-shutDown:
case <-time.After(deadline + margin): case <-time.After(deadline + stepTimeout):
t.Fatalf("Shutdown did not return within %s of its deadline while "+ 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 var dialer net.Dialer
@@ -744,8 +736,6 @@ func (s *closeOrderStore) record(call string) {
func TestShutdownCheckpointsAndClosesTheDatabaseLast(t *testing.T) { func TestShutdownCheckpointsAndClosesTheDatabaseLast(t *testing.T) {
t.Parallel() t.Parallel()
const deadline = 10 * time.Second
store := &closeOrderStore{Store: newMockStore()} store := &closeOrderStore{Store: newMockStore()}
log := logger.New() log := logger.New()
cfg := &config.Config{} cfg := &config.Config{}
@@ -763,7 +753,7 @@ func TestShutdownCheckpointsAndClosesTheDatabaseLast(t *testing.T) {
Path: ristypes.ASPath{Sequence: []int{testASNA}}, Path: ristypes.ASPath{Sequence: []int{testASNA}},
}) })
ctx, cancel := context.WithTimeout(t.Context(), deadline) ctx, cancel := context.WithTimeout(t.Context(), stepTimeout)
defer cancel() defer cancel()
rw.Shutdown(ctx) rw.Shutdown(ctx)
internal/routewatch/ashandler.go
+42 -87
View File
@@ -18,39 +18,34 @@ const (
// (asnBatchTimeout), so a queue smaller than asnBatchSize is fine. // (asnBatchTimeout), so a queue smaller than asnBatchSize is fine.
asHandlerQueueSize = 20000 asHandlerQueueSize = 20000
// asnBatchSize is the number of ASN operations to batch together // asnBatchSize is the number of ASes in a full batch, which wakes the
// flush goroutine to write it.
asnBatchSize = 30000 asnBatchSize = 30000
// asnBatchMaxSize is the most ASN operations the batch holds while the
// flush goroutine writes the previous one: ten batches, about 10 MiB
// (README "Memory"). At this size HandleMessage waits until the flush
// goroutine takes the batch.
asnBatchMaxSize = 300000
// asnBatchTimeout is the maximum time to wait before flushing a batch // asnBatchTimeout is the maximum time to wait before flushing a batch
// DO NOT reduce this timeout - larger batches are more efficient // DO NOT reduce this timeout - larger batches are more efficient
asnBatchTimeout = 2 * time.Second asnBatchTimeout = 2 * time.Second
) )
// ASHandler processes Autonomous System Number (ASN) information extracted from // ASHandler records every AS in the AS paths of BGP UPDATE messages. Its batch
// BGP UPDATE messages. It uses batched database operations to efficiently store // holds the earliest and the latest time of each AS's updates. The flush
// ASN data, collecting operations into batches that are flushed either when the // goroutine writes the batch to the database when it holds asnBatchSize ASes,
// batch reaches a size threshold or after a timeout period. // and every asnBatchTimeout.
type ASHandler struct { type ASHandler struct {
db database.Store db database.Store
logger *logger.Logger logger *logger.Logger
// Batching. mu guards batch and writing only: the flush goroutine takes // Batching. mu guards batch and writing only. The flush goroutine takes
// the batch under mu and writes it after releasing mu, so HandleMessage // the batch under mu and writes it after releasing mu. So HandleMessage
// waits for a database write only while batch is at asnBatchMaxSize. // never waits for a database write.
mu sync.Mutex mu sync.Mutex
batch []asnOp // batch holds the earliest and the latest time of the updates for each AS
// writing is how many operations the flush goroutine took from batch // since the flush goroutine last took it. It holds one entry per AS,
// and has not finished writing. // however many updates arrive.
writing int batch map[int]database.SeenTimes
// batchTaken is signalled when the flush goroutine takes batch; its L is // writing is how many ASes the flush goroutine took from batch and has
// &mu. // not finished writing.
batchTaken sync.Cond writing int
batchFullCh chan struct{} // wakes the flush goroutine when batch is full batchFullCh chan struct{} // wakes the flush goroutine when batch is full
// stopCh hands Stop's context to the flush goroutine. It holds one, so // stopCh hands Stop's context to the flush goroutine. It holds one, so
// Stop does not wait for a write in progress to hand it over. // Stop does not wait for a write in progress to hand it over.
@@ -58,16 +53,10 @@ type ASHandler struct {
done chan struct{} // closed when the flush goroutine returns done chan struct{} // closed when the flush goroutine returns
} }
type asnOp struct {
number int
timestamp time.Time
}
// NewASHandler creates and returns a new ASHandler instance. It initializes // NewASHandler creates and returns a new ASHandler instance. It initializes
// the batching system and starts a background goroutine that periodically // the batching system and starts a background goroutine that periodically
// flushes accumulated ASN operations to the database. The caller must call // writes the collected ASes to the database. The caller must call Stop when
// Stop when finished to ensure all pending operations are flushed and the // finished, to write the pending ASes and end the background goroutine.
// background goroutine is terminated.
func NewASHandler(db database.Store, logger *logger.Logger) *ASHandler { func NewASHandler(db database.Store, logger *logger.Logger) *ASHandler {
return newASHandler(db, logger, asnBatchTimeout) return newASHandler(db, logger, asnBatchTimeout)
} }
@@ -81,12 +70,11 @@ func newASHandler(
h := &ASHandler{ h := &ASHandler{
db: db, db: db,
logger: logger, logger: logger,
batch: make([]asnOp, 0, asnBatchSize), batch: make(map[int]database.SeenTimes),
batchFullCh: make(chan struct{}, 1), batchFullCh: make(chan struct{}, 1),
stopCh: make(chan context.Context, 1), stopCh: make(chan context.Context, 1),
done: make(chan struct{}), done: make(chan struct{}),
} }
h.batchTaken.L = &h.mu
// Start the flush timer goroutine // Start the flush timer goroutine
go flushLoop(batchTimeout, h.batchFullCh, h.stopCh, h.done, h.flushBatch) go flushLoop(batchTimeout, h.batchFullCh, h.stopCh, h.done, h.flushBatch)
@@ -110,48 +98,25 @@ func (h *ASHandler) QueueCapacity() int {
return asHandlerQueueSize return asHandlerQueueSize
} }
// HandleMessage processes a RIS Live BGP message by extracting all ASNs from // HandleMessage adds the time of msg to the batch entry of each AS in its AS
// the AS path and queuing them for batch insertion into the database. The // path, the origin AS and the members of an AS set included. When the batch
// origin ASN and all transit ASNs are recorded with their associated // holds asnBatchSize ASes, HandleMessage wakes the flush goroutine to write it.
// timestamps. When the batch reaches the configured size threshold, the flush
// goroutine is woken to write it.
func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) { func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) {
// Use the pre-parsed timestamp
timestamp := msg.ParsedTimestamp
originASN := msg.Path.Origin()
h.mu.Lock() h.mu.Lock()
defer h.mu.Unlock() defer h.mu.Unlock()
// While the batch is at its maximum size, wait until the flush goroutine // The origin AS is the last AS of the sequence, so the loop adds it too.
// takes it. Meanwhile the handler takes nothing off its queue, which
// fills, and the streamer drops messages for it.
for len(h.batch) >= asnBatchMaxSize {
h.batchTaken.Wait()
}
// Queue origin ASN operation
if originASN > 0 {
h.batch = append(h.batch, asnOp{
number: originASN,
timestamp: timestamp,
})
}
// Also track all ASNs in the path, the members of an AS set included
for _, asn := range slices.Concat(msg.Path.Sequence, msg.Path.Set) { for _, asn := range slices.Concat(msg.Path.Sequence, msg.Path.Set) {
if asn > 0 { if asn > 0 {
h.batch = append(h.batch, asnOp{ seen := h.batch[asn]
number: asn, seen.Add(msg.ParsedTimestamp)
timestamp: timestamp, h.batch[asn] = seen
})
} }
} }
// A full batch wakes the flush goroutine. If it is writing, the wake-up // 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 // waits in batchFullCh and the batch keeps taking updates until the write
// or the batch reaches asnBatchMaxSize. // ends.
if len(h.batch) >= asnBatchSize { if len(h.batch) >= asnBatchSize {
select { select {
case h.batchFullCh <- struct{}{}: case h.batchFullCh <- struct{}{}:
@@ -160,10 +125,11 @@ func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) {
} }
} }
// Stop stops the flush goroutine, which writes the operations the handler holds // Stop stops the flush goroutine and waits for it until ctx ends. The flush
// before it returns, and waits for it until ctx ends. Once ctx has ended the // goroutine writes the batch before it returns, unless ctx has ended. A write
// flush goroutine skips that last write, and a write still running is lost // still running when the process exits is lost. Stop logs how many entries are
// when the process exits, so Stop logs how many operations are not written. // not written, in the batch being written and in the next batch. An AS in both
// batches counts twice.
func (h *ASHandler) Stop(ctx context.Context) { func (h *ASHandler) Stop(ctx context.Context) {
h.stopCh <- ctx h.stopCh <- ctx
@@ -178,14 +144,14 @@ func (h *ASHandler) Stop(ctx context.Context) {
if unwritten > 0 { if unwritten > 0 {
h.logger.Error("Stop deadline passed before the AS handler wrote "+ h.logger.Error("Stop deadline passed before the AS handler wrote "+
"its updates", "updates", unwritten) "its batches", "batch_entries", unwritten)
} }
} }
// takeBatch returns the pending operations and leaves an empty batch in their // takeBatch returns the pending ASes and leaves an empty batch in their place
// place for HandleMessage to fill. They count in writing until flushBatch has // for HandleMessage to fill. They count in writing until flushBatch has written
// written them. // them.
func (h *ASHandler) takeBatch() []asnOp { func (h *ASHandler) takeBatch() map[int]database.SeenTimes {
h.mu.Lock() h.mu.Lock()
defer h.mu.Unlock() defer h.mu.Unlock()
@@ -195,8 +161,7 @@ func (h *ASHandler) takeBatch() []asnOp {
batch := h.batch batch := h.batch
h.writing = len(batch) h.writing = len(batch)
h.batch = make([]asnOp, 0, asnBatchSize) h.batch = make(map[int]database.SeenTimes)
h.batchTaken.Broadcast()
return batch return batch
} }
@@ -209,21 +174,11 @@ func (h *ASHandler) flushBatch() {
return return
} }
// The earliest and the latest time the batch saw each AS. The batch holds
// several updates for an AS, from many peers, so a new AS is stored first
// seen at the earliest of them and last seen at the latest.
asns := make(map[int]database.SeenTimes)
for _, op := range batch {
seen := asns[op.number]
seen.Add(op.timestamp)
asns[op.number] = seen
}
// Process all ASNs in a single batch transaction // Process all ASNs in a single batch transaction
err := h.db.GetOrCreateASNBatch(asns) err := h.db.GetOrCreateASNBatch(batch)
if err != nil { if err != nil {
h.logger.Error("Failed to process ASN batch", h.logger.Error("Failed to process ASN batch",
"error", err, "count", len(asns)) "error", err, "count", len(batch))
} }
h.mu.Lock() h.mu.Lock()
internal/routewatch/ashandler_internal_test.go
+24 -7
View File
@@ -5,28 +5,43 @@ import (
"slices" "slices"
"testing" "testing"
"git.eeqj.de/sneak/routewatch/internal/database"
"git.eeqj.de/sneak/routewatch/internal/logger" "git.eeqj.de/sneak/routewatch/internal/logger"
"git.eeqj.de/sneak/routewatch/internal/ristypes"
) )
// pathOfASes returns an AS path of n different ASes: AS 1 to AS n. With n up to
// asnBatchSize, none of them is testASNA to testASND.
func pathOfASes(n int) ristypes.ASPath {
sequence := make([]int, n)
for i := range sequence {
sequence[i] = i + 1
}
return ristypes.ASPath{Sequence: sequence}
}
// TestASHandlerStoresTheEarliestAndLatestTimesOfANewAS handles two updates // TestASHandlerStoresTheEarliestAndLatestTimesOfANewAS handles two updates
// whose path carries an AS the database does not hold yet, the second 5 // whose path carries an AS the database does not hold yet, in one batch into a
// seconds after the first, in one batch into a real database. The AS is stored // real database. The second is 5 seconds after the first, and the handler gets
// first seen at the time of the first update and last seen at the time of the // it first. The AS is stored first seen at the time of the first update and
// second. // last seen at the time of the second.
func TestASHandlerStoresTheEarliestAndLatestTimesOfANewAS(t *testing.T) { func TestASHandlerStoresTheEarliestAndLatestTimesOfANewAS(t *testing.T) {
t.Parallel() t.Parallel()
db := newTestDatabase(t) db := newTestDatabase(t)
// Built without NewASHandler's flush goroutine, so the test flushes itself. // 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(), batch: make(map[int]database.SeenTimes),
}
first := peerAnnouncement(testPeerIP, testV4Prefix) first := peerAnnouncement(testPeerIP, testV4Prefix)
second := peerAnnouncement(testPeerIP, testV4Prefix) second := peerAnnouncement(testPeerIP, testV4Prefix)
second.ParsedTimestamp = first.ParsedTimestamp.Add(secondUpdateAfter) second.ParsedTimestamp = first.ParsedTimestamp.Add(secondUpdateAfter)
h.HandleMessage(first)
h.HandleMessage(second) h.HandleMessage(second)
h.HandleMessage(first)
h.flushBatch() h.flushBatch()
asn, _, err := db.GetAS(t.Context(), testASNA) asn, _, err := db.GetAS(t.Context(), testASNA)
@@ -54,7 +69,9 @@ func TestASHandlerRecordsNothingFromAPathWithASZero(t *testing.T) {
store := newMockStore() store := newMockStore()
// Built without NewASHandler's flush goroutine, so the test flushes itself. // 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(), batch: make(map[int]database.SeenTimes),
}
msg := peerAnnouncement(testPeerIP, testV4Prefix) msg := peerAnnouncement(testPeerIP, testV4Prefix)
msg.Path = decodePath(t, testASNA, 0, testASNB) msg.Path = decodePath(t, testASNA, 0, testASNB)
internal/routewatch/asnfetcher.go
+31 -5
View File
@@ -187,25 +187,33 @@ func (f *ASNFetcher) recordSuccess() {
f.statsMu.Unlock() f.statsMu.Unlock()
} }
// recordFailure increases the interval on failed fetch using exponential backoff. // lengthenInterval makes the interval 1.5 times as long, up to maxInterval.
func (f *ASNFetcher) recordFailure() { // A failed lookup and a skipped one both lengthen it.
func (f *ASNFetcher) lengthenInterval() {
f.intervalMu.Lock() f.intervalMu.Lock()
f.consecutiveFails++ defer f.intervalMu.Unlock()
// Exponential backoff: multiply by 1.5, capped at max
newInterval := min( newInterval := min(
f.currentInterval*backoffNumerator/backoffDenominator, maxInterval) f.currentInterval*backoffNumerator/backoffDenominator, maxInterval)
if newInterval != f.currentInterval { if newInterval != f.currentInterval {
f.logger.Debug("Increased fetch interval due to failure", f.logger.Debug("Increased fetch interval",
"old_interval", f.currentInterval, "old_interval", f.currentInterval,
"new_interval", newInterval, "new_interval", newInterval,
"consecutive_failures", f.consecutiveFails, "consecutive_failures", f.consecutiveFails,
) )
f.currentInterval = newInterval f.currentInterval = newInterval
} }
}
// recordFailure counts a failed fetch and lengthens the interval.
func (f *ASNFetcher) recordFailure() {
f.intervalMu.Lock()
f.consecutiveFails++
f.intervalMu.Unlock() f.intervalMu.Unlock()
f.lengthenInterval()
// Record error time for stats, dropping those older than statsWindow // Record error time for stats, dropping those older than statsWindow
f.statsMu.Lock() f.statsMu.Lock()
now := f.now() now := f.now()
@@ -287,6 +295,16 @@ func (f *ASNFetcher) fetchNextStale(ctx context.Context) {
// so the AS stays stale. An AS IANA refers to no RIR is stored with no // so the AS stays stale. An AS IANA refers to no RIR is stored with no
// WHOIS data, so it is not looked up again until it is stale; that counts // WHOIS data, so it is not looked up again until it is stale; that counts
// as neither a success nor a failure. // as neither a success nor a failure.
//
// The WHOIS client pauses an RIR's or NIC.br's server for whois.PauseTime
// after the server refuses a query. Lookups at the other servers go on. IANA
// is never paused, so a refusal by IANA is an ordinary failure. A lookup
// whose RIR is paused fails with whois.ErrPaused and is skipped. A skipped
// lookup leaves the AS stale and is not counted as a failure. Like a
// failure, a skipped lookup lengthens the interval. Each lookup asks IANA
// before it finds its RIR paused, so with a one-second interval the fetcher
// would ask IANA every second. The lookups that QueueImmediate asks for also
// run through fetchAndUpdate.
func (f *ASNFetcher) fetchAndUpdate(ctx context.Context, asn int) bool { func (f *ASNFetcher) fetchAndUpdate(ctx context.Context, asn int) bool {
ctx, cancel := context.WithTimeout(ctx, time.Minute) ctx, cancel := context.WithTimeout(ctx, time.Minute)
defer cancel() defer cancel()
@@ -307,6 +325,14 @@ func (f *ASNFetcher) fetchAndUpdate(ctx context.Context, asn int) bool {
return false return false
} }
if errors.Is(err, whois.ErrPaused) {
f.logger.Info("Skipped WHOIS lookup, the RIR's server is paused",
"asn", asn, "error", err)
f.lengthenInterval()
return false
}
if err != nil { if err != nil {
f.logger.Error("WHOIS lookup failed", "asn", asn, "error", err) f.logger.Error("WHOIS lookup failed", "asn", asn, "error", err)
f.recordFailure() f.recordFailure()
internal/routewatch/asnfetcher_internal_test.go
+150 -4
View File
@@ -13,6 +13,7 @@ import (
"git.eeqj.de/sneak/routewatch/internal/database" "git.eeqj.de/sneak/routewatch/internal/database"
"git.eeqj.de/sneak/routewatch/internal/logger" "git.eeqj.de/sneak/routewatch/internal/logger"
"git.eeqj.de/sneak/routewatch/internal/whois"
) )
// The WHOIS servers a lookup asks: IANA first, then the RIR IANA refers it // The WHOIS servers a lookup asks: IANA first, then the RIR IANA refers it
@@ -131,6 +132,151 @@ func TestFetchAndUpdateKeepsTheRowWhenTheLookupFails(t *testing.T) {
} }
} }
// TestFetchAndUpdateWaitsOutAPause looks up an AS at RIPE while RIPE refuses
// the query. The test sets the WHOIS client's clock. The next lookup comes a
// second before whois.PauseTime has passed. It sends RIPE nothing and leaves
// the AS never looked up. It counts as neither a success nor a failure. A
// lookup at whois.PauseTime asks RIPE again.
func TestFetchAndUpdateWaitsOutAPause(t *testing.T) {
t.Parallel()
f, db := newFetcherWithWHOISAnswers(t, map[string]string{
ianaWHOISServer: ianaRefersToRIPE,
ripeWHOISServer: ripeAccessDenied,
})
ripeAsks := 0
dial := f.whoisClient.DialContext
f.whoisClient.DialContext = func(
ctx context.Context, network, address string,
) (net.Conn, error) {
if address == ripeWHOISServer {
ripeAsks++
}
return dial(ctx, network, address)
}
start := time.Date(2026, 11, 2, 0, 0, 0, 0, time.UTC)
now := start
f.whoisClient.Now = func() time.Time { return now }
f.fetchAndUpdate(t.Context(), testASNA)
now = start.Add(whois.PauseTime - time.Second)
f.fetchAndUpdate(t.Context(), testASNA)
if ripeAsks != 1 {
t.Errorf("RIPE was asked %d times during its pause, want 1", ripeAsks)
}
stats, err := db.GetWHOISStats(t.Context(), whoisStaleThreshold)
if err != nil {
t.Fatalf("GetWHOISStats: %v", err)
}
if stats.NeverFetched != 1 {
t.Errorf("never looked up = %d, want 1", stats.NeverFetched)
}
got := f.GetStats()
if got.ConsecutiveFails != 1 || got.ErrorsLastHour != 1 ||
got.SuccessesLastHour != 0 {
t.Errorf("%d failures in a row, %d errors, %d successes; want 1, 1, 0",
got.ConsecutiveFails, got.ErrorsLastHour, got.SuccessesLastHour)
}
now = start.Add(whois.PauseTime)
f.fetchAndUpdate(t.Context(), testASNA)
if ripeAsks != 2 {
t.Errorf("RIPE was asked %d times after its pause, want 2", ripeAsks)
}
}
// TestFetchAndUpdateBacksOffDuringAPause looks up an AS at RIPE while RIPE
// refuses the query. The refusal pauses RIPE for an hour, so every later
// lookup in the test is skipped. The test sets the WHOIS client's clock and
// looks the AS up again each time the interval has passed. Like a failure,
// each skip must make the interval 1.5 times as long, up to one minute. The
// skips must not count as failures.
func TestFetchAndUpdateBacksOffDuringAPause(t *testing.T) {
t.Parallel()
f, _ := newFetcherWithWHOISAnswers(t, map[string]string{
ianaWHOISServer: ianaRefersToRIPE,
ripeWHOISServer: ripeAccessDenied,
})
now := time.Date(2026, 11, 2, 0, 0, 0, 0, time.UTC)
f.whoisClient.Now = func() time.Time { return now }
f.fetchAndUpdate(t.Context(), testASNA)
for i, want := range []time.Duration{
33750 * time.Millisecond,
50625 * time.Millisecond,
time.Minute,
time.Minute,
} {
now = now.Add(f.getInterval())
f.fetchAndUpdate(t.Context(), testASNA)
if got := f.getInterval(); got != want {
t.Errorf("interval after %d skipped lookups = %v, want %v",
i+1, got, want)
}
}
got := f.GetStats()
if got.ConsecutiveFails != 1 || got.ErrorsLastHour != 1 {
t.Errorf("%d failures in a row and %d errors, want 1 and 1",
got.ConsecutiveFails, got.ErrorsLastHour)
}
}
// TestFetchAndUpdateKeepsAskingIANA looks up an AS while IANA's server
// refuses the connection. The test sets the WHOIS client's clock. The next
// lookup comes a second before whois.PauseTime has passed. IANA is never
// paused, so that lookup asks IANA again. Each refusal counts as a failure.
func TestFetchAndUpdateKeepsAskingIANA(t *testing.T) {
t.Parallel()
// With no answers, every server refuses the connection.
f, _ := newFetcherWithWHOISAnswers(t, map[string]string{})
ianaAsks := 0
dial := f.whoisClient.DialContext
f.whoisClient.DialContext = func(
ctx context.Context, network, address string,
) (net.Conn, error) {
if address == ianaWHOISServer {
ianaAsks++
}
return dial(ctx, network, address)
}
start := time.Date(2026, 11, 2, 0, 0, 0, 0, time.UTC)
now := start
f.whoisClient.Now = func() time.Time { return now }
f.fetchAndUpdate(t.Context(), testASNA)
now = start.Add(whois.PauseTime - time.Second)
f.fetchAndUpdate(t.Context(), testASNA)
got := f.GetStats()
if ianaAsks != 2 || got.ConsecutiveFails != 2 {
t.Errorf("IANA was asked %d times, with %d failures in a row; "+
"want 2 and 2", ianaAsks, got.ConsecutiveFails)
}
}
// TestRecordStepsTheInterval has the fetcher fail from its base interval of // TestRecordStepsTheInterval has the fetcher fail from its base interval of
// 15 seconds, then succeed. Each failure makes the interval 1.5 times as // 15 seconds, then succeed. Each failure makes the interval 1.5 times as
// long, up to one minute, and each success halves it, down to one second. // long, up to one minute, and each success halves it, down to one second.
@@ -224,7 +370,7 @@ func TestASNFetcherStopReturnsByItsDeadline(t *testing.T) {
select { select {
case <-lookupStarted: case <-lookupStarted:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the fetcher did not start the lookup") t.Fatal("the fetcher did not start the lookup")
} }
@@ -240,22 +386,22 @@ func TestASNFetcherStopReturnsByItsDeadline(t *testing.T) {
select { select {
case <-f.done: case <-f.done:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the fetcher goroutine did not return after the lookup ended") t.Fatal("the fetcher goroutine did not return after the lookup ended")
} }
} }
// TestRecordKeepsOnlyTheStatsWindow records a success and a failure every // 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 // asks for the stats. The fetcher must keep only the times within the last
// statsWindow. // statsWindow.
func TestRecordKeepsOnlyTheStatsWindow(t *testing.T) { func TestRecordKeepsOnlyTheStatsWindow(t *testing.T) {
t.Parallel() t.Parallel()
const ( const (
records = 100_000
step = time.Second step = time.Second
want = int(statsWindow / step) want = int(statsWindow / step)
records = 3 * want
) )
clock := time.Now() clock := time.Now()
internal/routewatch/batchwrite_internal_test.go
+116 -59
View File
@@ -5,6 +5,7 @@ import (
"context" "context"
"encoding/json" "encoding/json"
"fmt" "fmt"
"io"
"log/slog" "log/slog"
"slices" "slices"
"sync" "sync"
@@ -19,9 +20,15 @@ import (
) )
const ( const (
// handleMessageTimeout is how long a test waits for HandleMessage to // stepTimeout is how long a test waits for a step it expects, such as
// return, or for a write to start, before it fails. // HandleMessage returning, a write starting or Shutdown returning, before
handleMessageTimeout = 2 * time.Second // 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 // stillWaitingAfter is how long a test watches a HandleMessage that must
// wait. One that does not wait returns well within it. // wait. One that does not wait returns well within it.
@@ -171,12 +178,14 @@ type stopLog struct {
Msg string `json:"msg"` Msg string `json:"msg"`
Updates int `json:"updates"` Updates int `json:"updates"`
TableChanges int `json:"table_changes"` TableChanges int `json:"table_changes"`
HeldMessages int `json:"held_messages"`
Paths int `json:"paths"` Paths int `json:"paths"`
BatchEntries int `json:"batch_entries"`
} }
// newErrorLogger returns a logger that writes only errors, as JSON lines, to // newErrorLogger returns a logger that writes only errors, as JSON lines, to
// logs. // logs.
func newErrorLogger(logs *bytes.Buffer) *logger.Logger { func newErrorLogger(logs io.Writer) *logger.Logger {
return &logger.Logger{Logger: slog.New(slog.NewJSONHandler(logs, return &logger.Logger{Logger: slog.New(slog.NewJSONHandler(logs,
&slog.HandlerOptions{Level: slog.LevelError}))} &slog.HandlerOptions{Level: slog.LevelError}))}
} }
@@ -198,7 +207,7 @@ func lastLogged(t *testing.T, logs *bytes.Buffer) stopLog {
return logged return logged
} }
// returnsInTime reports whether f returns within handleMessageTimeout. // returnsInTime reports whether f returns within stepTimeout.
func returnsInTime(f func()) bool { func returnsInTime(f func()) bool {
done := make(chan struct{}) done := make(chan struct{})
@@ -210,11 +219,22 @@ func returnsInTime(f func()) bool {
select { select {
case <-done: case <-done:
return true return true
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
return false 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 // 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 // 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 // their batch, and the peering handler on its timer. store holds the write
@@ -240,7 +260,7 @@ func startBlockedWrite(
select { select {
case <-store.writeStarted: case <-store.writeStarted:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the handler did not start to write the messages") t.Fatal("the handler did not start to write the messages")
} }
} }
@@ -261,7 +281,7 @@ func handleWhileAWriteIsBlocked(
) { ) {
t.Helper() t.Helper()
defer h.Stop(t.Context()) defer stopInTime(t, h)
defer store.releaseWrites() defer store.releaseWrites()
startBlockedWrite(t, store, h, fill) startBlockedWrite(t, store, h, fill)
@@ -275,7 +295,9 @@ func handleWhileAWriteIsBlocked(
// while store holds the write, hands h the messages in toMax, which bring its // 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 // 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 // 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( func handleAtMaxBatchSize(
t *testing.T, t *testing.T,
store *blockingStore, store *blockingStore,
@@ -288,13 +310,18 @@ func handleAtMaxBatchSize(
) { ) {
t.Helper() t.Helper()
defer h.Stop(t.Context()) defer stopInTime(t, h)
defer store.releaseWrites() defer store.releaseWrites()
startBlockedWrite(t, store, h, fill) startBlockedWrite(t, store, h, fill)
for _, msg := range toMax { if !returnsInTime(func() {
h.HandleMessage(msg) 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{}) returned := make(chan struct{})
@@ -315,7 +342,7 @@ func handleAtMaxBatchSize(
select { select {
case <-returned: case <-returned:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("HandleMessage did not return after the database write finished") t.Fatal("HandleMessage did not return after the database write finished")
} }
} }
@@ -345,8 +372,12 @@ func stopWhileAWriteIsBlocked(
startBlockedWrite(t, store, h, fill) startBlockedWrite(t, store, h, fill)
for _, msg := range extra { if !returnsInTime(func() {
h.HandleMessage(msg) 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) ctx, cancel := context.WithTimeout(t.Context(), stopDeadline)
@@ -361,7 +392,7 @@ func stopWhileAWriteIsBlocked(
select { select {
case <-done: case <-done:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the flush goroutine did not return after the write finished") t.Fatal("the flush goroutine did not return after the write finished")
} }
} }
@@ -380,7 +411,8 @@ func TestPrefixHandlerSkipsItsLastWriteAfterTheStopDeadline(t *testing.T) {
store := newBlockingStore() store := newBlockingStore()
h := newPrefixHandler(store, newErrorLogger(&logs), h := newPrefixHandler(store, newErrorLogger(&logs),
routetable.New(routetable.Params{}), longerThanAnyTest) routetable.New(routetable.Params{}), longerThanAnyTest,
maxTableChangesPerWrite)
fill := slices.Repeat([]string{testV4Prefix}, prefixBatchSize) fill := slices.Repeat([]string{testV4Prefix}, prefixBatchSize)
stopWhileAWriteIsBlocked(t, store, h, h.done, stopWhileAWriteIsBlocked(t, store, h, h.done,
[]*ristypes.RISMessage{prefixAnnouncement(fill)}, []*ristypes.RISMessage{prefixAnnouncement(fill)},
@@ -466,20 +498,20 @@ func TestPrefixHandlerStopCountsTheTableChangesOfAWriteInProgress(t *testing.T)
} }
} }
// TestASHandlerSkipsItsLastWriteAfterTheStopDeadline also checks what Stop
// logs: the asnBatchSize entries of the held write and the entry for testASNB,
// handled since, are not written.
func TestASHandlerSkipsItsLastWriteAfterTheStopDeadline(t *testing.T) { func TestASHandlerSkipsItsLastWriteAfterTheStopDeadline(t *testing.T) {
t.Parallel() t.Parallel()
// Each message gives an update for its origin AS and one for each AS const wantEntries = asnBatchSize + 1
// in its path: fill asnBatchSize+1, extra 2.
const wantUpdates = asnBatchSize + 1 + 2
var logs bytes.Buffer var logs bytes.Buffer
store := newBlockingStore() store := newBlockingStore()
h := newASHandler(store, newErrorLogger(&logs), longerThanAnyTest) h := newASHandler(store, newErrorLogger(&logs), longerThanAnyTest)
fill := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)}
stopWhileAWriteIsBlocked(t, store, h, h.done, stopWhileAWriteIsBlocked(t, store, h, h.done,
[]*ristypes.RISMessage{{Path: fill}}, []*ristypes.RISMessage{{Path: pathOfASes(asnBatchSize)}},
&ristypes.RISMessage{Path: ristypes.ASPath{Sequence: []int{testASNB}}}) &ristypes.RISMessage{Path: ristypes.ASPath{Sequence: []int{testASNB}}})
store.mu.Lock() store.mu.Lock()
@@ -489,26 +521,27 @@ func TestASHandlerSkipsItsLastWriteAfterTheStopDeadline(t *testing.T) {
t.Errorf("AS%d was written after the stop deadline", testASNB) t.Errorf("AS%d was written after the stop deadline", testASNB)
} }
if logged := lastLogged(t, &logs); logged.Updates != wantUpdates { if logged := lastLogged(t, &logs); logged.BatchEntries != wantEntries {
t.Errorf("Stop logged %d updates not written, want %d", t.Errorf("Stop logged %d batch entries not written, want %d",
logged.Updates, wantUpdates) logged.BatchEntries, wantEntries)
} }
} }
// TestASHandlerSkipsAFullBatchAfterTheStopDeadline hands the AS handler a full // TestASHandlerSkipsAFullBatchAfterTheStopDeadline hands the AS handler a full
// batch while a write is held, so the batch's wake-up of the flush goroutine // batch while a write is held, so the batch's wake-up of the flush goroutine
// waits. The stop deadline passes meanwhile. When the write ends, the flush // waits. The full batch holds the fill's ASes again, and testASNB. The stop
// goroutine must stop instead of writing the batch. // deadline passes meanwhile. When the write ends, the flush goroutine must stop
// instead of writing the batch.
func TestASHandlerSkipsAFullBatchAfterTheStopDeadline(t *testing.T) { func TestASHandlerSkipsAFullBatchAfterTheStopDeadline(t *testing.T) {
t.Parallel() t.Parallel()
store := newBlockingStore() store := newBlockingStore()
h := newASHandler(store, logger.New(), longerThanAnyTest) h := newASHandler(store, logger.New(), longerThanAnyTest)
fill := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)} fill := &ristypes.RISMessage{Path: pathOfASes(asnBatchSize)}
full := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNB}, asnBatchSize)}
stopWhileAWriteIsBlocked(t, store, h, h.done, stopWhileAWriteIsBlocked(t, store, h, h.done,
[]*ristypes.RISMessage{{Path: fill}}, []*ristypes.RISMessage{fill},
&ristypes.RISMessage{Path: full}) fill,
&ristypes.RISMessage{Path: ristypes.ASPath{Sequence: []int{testASNB}}})
store.mu.Lock() store.mu.Lock()
defer store.mu.Unlock() defer store.mu.Unlock()
@@ -597,7 +630,7 @@ func TestPeeringHandlerStopCountsTheWriteInProgress(t *testing.T) {
select { select {
case <-h.done: case <-h.done:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the processing goroutine did not return after the write " + t.Fatal("the processing goroutine did not return after the write " +
"finished") "finished")
} }
@@ -618,7 +651,7 @@ func TestPeeringHandlerStartsNoWriteAfterTheStopDeadline(t *testing.T) {
const processInterval = 10 * time.Millisecond const processInterval = 10 * time.Millisecond
store := newBlockingStore() store := newBlockingStore()
h := newPeeringHandler(store, logger.New(), processInterval) h := newPeeringHandler(store, logger.New(), processInterval, maxTrackedPaths)
stopWhileAWriteIsBlocked(t, store, h, h.done, stopWhileAWriteIsBlocked(t, store, h, h.done,
[]*ristypes.RISMessage{ []*ristypes.RISMessage{
{Path: ristypes.ASPath{Sequence: []int{testASNA, testASNB}}}, {Path: ristypes.ASPath{Sequence: []int{testASNA, testASNB}}},
@@ -674,9 +707,8 @@ func TestASHandlerHandlesMessagesWhileAWriteIsBlocked(t *testing.T) {
store := newBlockingStore() store := newBlockingStore()
h := newASHandler(store, logger.New(), longerThanAnyTest) h := newASHandler(store, logger.New(), longerThanAnyTest)
fill := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)}
handleWhileAWriteIsBlocked(t, store, h, handleWhileAWriteIsBlocked(t, store, h,
[]*ristypes.RISMessage{{Path: fill}}, []*ristypes.RISMessage{{Path: pathOfASes(asnBatchSize)}},
&ristypes.RISMessage{Path: ristypes.ASPath{Sequence: []int{testASNB}}}) &ristypes.RISMessage{Path: ristypes.ASPath{Sequence: []int{testASNB}}})
store.mu.Lock() store.mu.Lock()
@@ -714,9 +746,11 @@ func TestPrefixHandlerWaitsAtTheMaximumBatchSize(t *testing.T) {
const extraPrefix = "198.51.100.0/24" const extraPrefix = "198.51.100.0/24"
store := newBlockingStore() 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) fill := slices.Repeat([]string{testV4Prefix}, prefixBatchSize)
toMax := slices.Repeat([]string{testV4Prefix}, prefixBatchMaxSize) toMax := slices.Repeat([]string{testV4Prefix}, prefixBatchSize)
handleAtMaxBatchSize(t, store, h, handleAtMaxBatchSize(t, store, h,
[]*ristypes.RISMessage{prefixAnnouncement(fill)}, []*ristypes.RISMessage{prefixAnnouncement(fill)},
[]*ristypes.RISMessage{prefixAnnouncement(toMax)}, []*ristypes.RISMessage{prefixAnnouncement(toMax)},
@@ -731,31 +765,48 @@ func TestPrefixHandlerWaitsAtTheMaximumBatchSize(t *testing.T) {
} }
} }
func TestASHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { // TestASHandlerNeverWaitsForAWrite starts a write that the store holds. Then it
// hands the AS handler twenty messages whose paths each hold one AS
// asnBatchSize times. HandleMessage must return each time, and the batch must
// hold one entry, for that AS.
func TestASHandlerNeverWaitsForAWrite(t *testing.T) {
t.Parallel() t.Parallel()
const messages = 20
store := newBlockingStore() store := newBlockingStore()
h := newASHandler(store, logger.New(), longerThanAnyTest) h := newASHandler(store, logger.New(), longerThanAnyTest)
fill := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchSize)}
toMax := ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, asnBatchMaxSize)}
handleAtMaxBatchSize(t, store, h,
[]*ristypes.RISMessage{{Path: fill}},
[]*ristypes.RISMessage{{Path: toMax}},
&ristypes.RISMessage{Path: ristypes.ASPath{Sequence: []int{testASNB}}})
store.mu.Lock() defer stopInTime(t, h)
defer store.mu.Unlock() defer store.releaseWrites()
if !store.asns[testASNB] { startBlockedWrite(t, store, h,
t.Errorf("Stop did not write AS%d, handled after the batch reached its "+ []*ristypes.RISMessage{{Path: pathOfASes(asnBatchSize)}})
"maximum size", testASNB)
oneAS := &ristypes.RISMessage{
Path: ristypes.ASPath{Sequence: slices.Repeat([]int{testASNB}, asnBatchSize)},
}
if !returnsInTime(func() {
for range messages {
h.HandleMessage(oneAS)
}
}) {
t.Fatal("HandleMessage did not return while a database write was blocked")
}
h.mu.Lock()
defer h.mu.Unlock()
if len(h.batch) != 1 {
t.Errorf("the batch holds %d entries for one AS, want 1", len(h.batch))
} }
} }
// TestPeerHandlerWaitsAtTheMaximumBatchSize must not have its flush timer fire. // TestPeerHandlerWaitsAtTheMaximumBatchSize must not have its flush timer fire.
// A timer flush during the fill would take only part of it. The batch would // 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 // then reach its maximum size before the test's last message, and the test
// would hang. // would fail.
func TestPeerHandlerWaitsAtTheMaximumBatchSize(t *testing.T) { func TestPeerHandlerWaitsAtTheMaximumBatchSize(t *testing.T) {
t.Parallel() t.Parallel()
@@ -763,10 +814,11 @@ func TestPeerHandlerWaitsAtTheMaximumBatchSize(t *testing.T) {
store := newBlockingStore() store := newBlockingStore()
h := newPeerHandler(store, logger.New(), longerThanAnyTest) h := newPeerHandler(store, logger.New(), longerThanAnyTest)
h.batchMaxSize = peerBatchSize
message := []*ristypes.RISMessage{{Peer: testPeerIP}} message := []*ristypes.RISMessage{{Peer: testPeerIP}}
handleAtMaxBatchSize(t, store, h, handleAtMaxBatchSize(t, store, h,
slices.Repeat(message, peerBatchSize), slices.Repeat(message, peerBatchSize),
slices.Repeat(message, peerBatchMaxSize), slices.Repeat(message, peerBatchSize),
&ristypes.RISMessage{Peer: otherPeerIP}) &ristypes.RISMessage{Peer: otherPeerIP})
store.mu.Lock() store.mu.Lock()
@@ -796,8 +848,9 @@ func TestHandlersWakeTheFlushGoroutineWhenTheBatchIsFull(t *testing.T) {
batchSize: prefixBatchSize, batchSize: prefixBatchSize,
handle: func(n int) chan struct{} { handle: func(n int) chan struct{} {
h := &PrefixHandler{ h := &PrefixHandler{
batchFullCh: make(chan struct{}, 1), batchMaxSize: prefixBatchMaxSize,
table: routetable.New(routetable.Params{}), batchFullCh: make(chan struct{}, 1),
table: routetable.New(routetable.Params{}),
} }
h.HandleMessage(prefixAnnouncement( h.HandleMessage(prefixAnnouncement(
slices.Repeat([]string{testV4Prefix}, n))) slices.Repeat([]string{testV4Prefix}, n)))
@@ -809,11 +862,12 @@ func TestHandlersWakeTheFlushGoroutineWhenTheBatchIsFull(t *testing.T) {
name: "AS", name: "AS",
batchSize: asnBatchSize, batchSize: asnBatchSize,
handle: func(n int) chan struct{} { handle: func(n int) chan struct{} {
h := &ASHandler{batchFullCh: make(chan struct{}, 1)} h := &ASHandler{
// The origin AS and each AS in the path are one update each. batch: make(map[int]database.SeenTimes),
h.HandleMessage(&ristypes.RISMessage{ batchFullCh: make(chan struct{}, 1),
Path: ristypes.ASPath{Sequence: slices.Repeat([]int{testASNA}, n-1)}, }
}) // Each of the path's n ASes is one entry of the batch.
h.HandleMessage(&ristypes.RISMessage{Path: pathOfASes(n)})
return h.batchFullCh return h.batchFullCh
}, },
@@ -822,7 +876,10 @@ func TestHandlersWakeTheFlushGoroutineWhenTheBatchIsFull(t *testing.T) {
name: "peer", name: "peer",
batchSize: peerBatchSize, batchSize: peerBatchSize,
handle: func(n int) chan struct{} { 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 { for range n {
h.HandleMessage(&ristypes.RISMessage{Peer: testPeerIP}) h.HandleMessage(&ristypes.RISMessage{Peer: testPeerIP})
} }
internal/routewatch/dbmaintainer_internal_test.go
+2 -2
View File
@@ -97,7 +97,7 @@ func TestDBMaintainerStopReturnsByItsDeadline(t *testing.T) {
select { select {
case <-store.started: case <-store.started:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the maintainer did not start the checkpoint") t.Fatal("the maintainer did not start the checkpoint")
} }
@@ -113,7 +113,7 @@ func TestDBMaintainerStopReturnsByItsDeadline(t *testing.T) {
select { select {
case <-m.done: case <-m.done:
case <-time.After(handleMessageTimeout): case <-time.After(stepTimeout):
t.Fatal("the maintenance goroutine did not return after the " + t.Fatal("the maintenance goroutine did not return after the " +
"checkpoint ended") "checkpoint ended")
} }
internal/routewatch/peerhandler.go
+14 -9
View File
@@ -43,10 +43,14 @@ type PeerHandler struct {
db database.Store db database.Store
logger *logger.Logger 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 // Batching. mu guards peerBatch and writing only: the flush goroutine
// takes the batch under mu and writes it after releasing mu, so // takes the batch under mu and writes it after releasing mu, so
// HandleMessage waits for a database write only while peerBatch is at // HandleMessage waits for a database write only while peerBatch is at
// peerBatchMaxSize. // batchMaxSize.
mu sync.Mutex mu sync.Mutex
peerBatch []peerUpdate peerBatch []peerUpdate
// writing is how many updates the flush goroutine took from peerBatch // 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, db database.Store, logger *logger.Logger, batchTimeout time.Duration,
) *PeerHandler { ) *PeerHandler {
h := &PeerHandler{ h := &PeerHandler{
db: db, db: db,
logger: logger, logger: logger,
peerBatch: make([]peerUpdate, 0, peerBatchSize), batchMaxSize: peerBatchMaxSize,
batchFullCh: make(chan struct{}, 1), peerBatch: make([]peerUpdate, 0, peerBatchSize),
stopCh: make(chan context.Context, 1), batchFullCh: make(chan struct{}, 1),
done: make(chan struct{}), stopCh: make(chan context.Context, 1),
done: make(chan struct{}),
} }
h.batchTaken.L = &h.mu 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 // While the batch is at its maximum size, wait until the flush goroutine
// takes it. Meanwhile the handler takes nothing off its queue, which // takes it. Meanwhile the handler takes nothing off its queue, which
// fills, and the streamer drops messages for it. // fills, and the streamer drops messages for it.
for len(h.peerBatch) >= peerBatchMaxSize { for len(h.peerBatch) >= h.batchMaxSize {
h.batchTaken.Wait() 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 // 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 // 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 { if len(h.peerBatch) >= peerBatchSize {
select { select {
case h.batchFullCh <- struct{}{}: case h.batchFullCh <- struct{}{}:
internal/routewatch/peerhandler_internal_test.go
+1 -1
View File
@@ -35,7 +35,7 @@ func TestPeerHandlerWritesTheEarliestAndLatestTimesOfANewPeer(t *testing.T) {
// Built without NewPeerHandler's flush goroutine, so the test flushes // Built without NewPeerHandler's flush goroutine, so the test flushes
// itself. // itself.
h := &PeerHandler{db: store, logger: logger.New()} h := &PeerHandler{db: store, logger: logger.New(), batchMaxSize: peerBatchMaxSize}
first := peerAnnouncement(testPeerIP, testV4Prefix) first := peerAnnouncement(testPeerIP, testV4Prefix)
second := peerAnnouncement(testPeerIP, testV4Prefix) second := peerAnnouncement(testPeerIP, testV4Prefix)
internal/routewatch/peeringhandler.go
+16 -9
View File
@@ -42,6 +42,10 @@ type PeeringHandler struct {
db database.Store db database.Store
logger *logger.Logger 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 // In-memory AS path tracking: each path, JSON-encoded, with the earliest
// and the latest time an update carried it. // and the latest time an update carried it.
mu sync.Mutex mu sync.Mutex
@@ -62,21 +66,24 @@ type PeeringHandler struct {
// periodically processes accumulated AS paths into peering records. The // periodically processes accumulated AS paths into peering records. The
// handler begins processing immediately upon creation. // handler begins processing immediately upon creation.
func NewPeeringHandler(db database.Store, logger *logger.Logger) *PeeringHandler { 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, // newPeeringHandler is NewPeeringHandler with the processing timer's interval,
// processInterval, in place of peeringProcessInterval. A test gives a short // processInterval, in place of peeringProcessInterval, and the most paths it
// one to have the timer start a write. // 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( func newPeeringHandler(
db database.Store, logger *logger.Logger, processInterval time.Duration, db database.Store, logger *logger.Logger, processInterval time.Duration,
maxPaths int,
) *PeeringHandler { ) *PeeringHandler {
h := &PeeringHandler{ h := &PeeringHandler{
db: db, db: db,
logger: logger, logger: logger,
asPaths: make(map[string]database.SeenTimes), asPaths: make(map[string]database.SeenTimes),
stopCh: make(chan context.Context, 1), maxPaths: maxPaths,
done: make(chan struct{}), stopCh: make(chan context.Context, 1),
done: make(chan struct{}),
} }
// Start the periodic processing goroutine // Start the periodic processing goroutine
@@ -131,7 +138,7 @@ func (h *PeeringHandler) HandleMessage(msg *ristypes.RISMessage) {
defer h.mu.Unlock() defer h.mu.Unlock()
seen, exists := h.asPaths[key] 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. // Map is full; drop this new path and count it.
h.droppedPaths++ h.droppedPaths++
internal/routewatch/peeringhandler_internal_test.go
+31 -18
View File
@@ -5,7 +5,6 @@ import (
"fmt" "fmt"
"maps" "maps"
"slices" "slices"
"strconv"
"sync" "sync"
"testing" "testing"
"time" "time"
@@ -20,6 +19,10 @@ const (
testASNB = 64501 testASNB = 64501
testASNC = 64502 testASNC = 64502
testASND = 64503 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 // 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. // processing goroutine, so tests drive processing explicitly.
func newTestHandler(db database.Store) *PeeringHandler { func newTestHandler(db database.Store) *PeeringHandler {
return &PeeringHandler{ return &PeeringHandler{
db: db, db: db,
logger: logger.New(), logger: logger.New(),
asPaths: make(map[string]database.SeenTimes), 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 // TestPeeringHandlerCapDropsAndCounts verifies that a full map drops new paths
// and counts them, while a path already tracked is refreshed rather than // 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) { func TestPeeringHandlerCapDropsAndCounts(t *testing.T) {
t.Parallel() t.Parallel()
store := &recordingStore{mockStore: newMockStore()} store := &recordingStore{mockStore: newMockStore()}
h := newTestHandler(store) h := newPeeringHandler(store, logger.New(), longerThanAnyTest,
testMaxTrackedPaths)
defer stopInTime(t, h)
now := time.Now().UTC() now := time.Now().UTC()
// Fill the map to exactly maxTrackedPaths, including one real path key so // Fill the map to exactly its limit, including one real path key so the
// the "already tracked" branch can be exercised. The filler keys are never // "already tracked" branch can be exercised. The other paths are of one
// processed in this test, so their contents do not matter. // AS, so they carry no peering.
existing := pathKey(t, testASNA, testASNB) existing := pathKey(t, testASNA, testASNB)
h.mu.Lock() h.mu.Lock()
h.asPaths[existing] = database.SeenTimes{First: now, Last: now} h.asPaths[existing] = database.SeenTimes{First: now, Last: now}
for i := 0; len(h.asPaths) < maxTrackedPaths; i++ { for asn := 1; len(h.asPaths) < testMaxTrackedPaths; asn++ {
h.asPaths[strconv.Itoa(i)] = database.SeenTimes{First: now, Last: now} h.asPaths[pathKey(t, asn)] = database.SeenTimes{First: now, Last: now}
} }
h.mu.Unlock() h.mu.Unlock()
@@ -270,8 +277,9 @@ func TestPeeringHandlerCapDropsAndCounts(t *testing.T) {
handle(h, now.Add(time.Second), testASNA, testASNC) handle(h, now.Add(time.Second), testASNA, testASNC)
tracked, dropped := snapshot(h) tracked, dropped := snapshot(h)
if tracked != maxTrackedPaths { if tracked != testMaxTrackedPaths {
t.Fatalf("want map size %d after drop, got %d", maxTrackedPaths, tracked) t.Fatalf("want map size %d after drop, got %d", testMaxTrackedPaths,
tracked)
} }
if dropped != 1 { if dropped != 1 {
@@ -283,8 +291,9 @@ func TestPeeringHandlerCapDropsAndCounts(t *testing.T) {
handle(h, refreshed, testASNA, testASNB) handle(h, refreshed, testASNA, testASNB)
tracked, dropped = snapshot(h) tracked, dropped = snapshot(h)
if tracked != maxTrackedPaths { if tracked != testMaxTrackedPaths {
t.Fatalf("want map size %d after refresh, got %d", maxTrackedPaths, tracked) t.Fatalf("want map size %d after refresh, got %d", testMaxTrackedPaths,
tracked)
} }
if dropped != 1 { if dropped != 1 {
@@ -303,17 +312,21 @@ func TestPeeringHandlerCapDropsAndCounts(t *testing.T) {
// TestPeeringHandlerRunResetsTheDroppedCount fills the map, has the handler // TestPeeringHandlerRunResetsTheDroppedCount fills the map, has the handler
// drop one path, and runs the processing. The count of dropped paths is the // 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) { func TestPeeringHandlerRunResetsTheDroppedCount(t *testing.T) {
t.Parallel() t.Parallel()
h := newTestHandler(newMockStore()) h := newPeeringHandler(newMockStore(), logger.New(), longerThanAnyTest,
testMaxTrackedPaths)
defer stopInTime(t, h)
now := time.Now().UTC() now := time.Now().UTC()
// Paths of one AS carry no peering, so the run records nothing. // Paths of one AS carry no peering, so the run records nothing.
h.mu.Lock() 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.asPaths[pathKey(t, asn)] = database.SeenTimes{First: now, Last: now}
} }
h.mu.Unlock() h.mu.Unlock()
internal/routewatch/prefixhandler.go
+244 -48
View File
@@ -44,6 +44,21 @@ const (
// most one pair. So the million pairs that a full-table peer's session // most one pair. So the million pairs that a full-table peer's session
// going down changes are written in about a minute. // going down changes are written in about a minute.
maxTableChangesPerWrite = 20000 maxTableChangesPerWrite = 20000
// maxHeldBackMessages is the most messages the handler holds back from
// peers whose session went down. A peer's messages are held back from
// the moment its session goes down until peerDown has applied them. If
// peerDown is running at that moment, the peer waits for the rest of
// peerDown's current PeersDown call. The peer also waits while peerDown
// applies the messages held back from that call's peers, those that
// arrive meanwhile included. The next PeersDown call takes the peer out.
// Once that call returns, peerDown applies the messages held back from
// that call's peers, one peer after another, in the order the call lists
// them. A held-back message that says the peer's session went down again
// makes the peer's later messages wait for the next call. A message takes
// about 1 KiB, so 150,000 take about 150 MiB (README "Memory"). At this
// number HandleMessage waits until one of them is applied.
maxHeldBackMessages = 150000
) )
// PrefixHandler keeps the routing table in memory current from the feed. It // PrefixHandler keeps the routing table in memory current from the feed. It
@@ -52,6 +67,17 @@ const (
// does an announcement whose AS path is empty or holds AS 0 anywhere. A peer // does an announcement whose AS path is empty or holds AS 0 anywhere. A peer
// whose BGP session goes down leaves every prefix. // whose BGP session goes down leaves every prefix.
// //
// The table's PeersDown applies sessions going down. It visits every prefix,
// which takes seconds on a full table. So the handler runs PeersDown on a
// separate goroutine and goes on taking messages meanwhile. One PeersDown runs
// at a time. The next one takes every peer whose session went down since the
// previous one began. PeersDown lets the table's lock go about half of the
// time, so the handler applies other peers' messages while PeersDown runs. The
// handler holds back a down peer's later messages until peerDown applies them,
// as the doc of maxHeldBackMessages describes. It applies them in order, one at
// a time, and takes new messages in between. It holds back at most
// maxHeldBackMessages messages.
//
// Each flush writes the table's changes to the database. It also stores each // Each flush writes the table's changes to the database. It also stores each
// prefix the updates name with the time it was first seen. // prefix the updates name with the time it was first seen.
type PrefixHandler struct { type PrefixHandler struct {
@@ -60,10 +86,17 @@ type PrefixHandler struct {
metrics *metrics.Tracker metrics *metrics.Tracker
table *routetable.Table table *routetable.Table
// Batching. mu guards batch, writing and writingTableChanges only: the // 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: the
// flush goroutine takes them under mu and writes them after releasing // flush goroutine takes them under mu and writes them after releasing
// mu, so HandleMessage waits for a database write only while batch is at // mu, so HandleMessage waits for a database write only while batch is at
// prefixBatchMaxSize. // batchMaxSize.
mu sync.Mutex mu sync.Mutex
batch []seenPrefix batch []seenPrefix
// writing is how many updates the flush goroutine took and has not // writing is how many updates the flush goroutine took and has not
@@ -80,6 +113,26 @@ type PrefixHandler struct {
// Stop does not wait for a write in progress to hand it over. // Stop does not wait for a write in progress to hand it over.
stopCh chan context.Context stopCh chan context.Context
done chan struct{} // closed when the flush goroutine returns done chan struct{} // closed when the flush goroutine returns
// Peers whose session went down. heldBack, under mu, holds each such
// peer's later messages, in order, until the peer has left every prefix
// and they are applied. A peer with no such messages yet has an empty
// entry. heldCount, under mu, is how many messages heldBack holds.
// heldTaken is signalled each time a held-back message is taken out to
// be applied; its L is &mu.
heldBack map[string][]*ristypes.RISMessage
heldCount int
heldTaken sync.Cond
// downPeers, under mu, lists the peers whose session went down and that
// the next PeersDown takes. peerDownRunning, under mu, says whether
// peerDown is running. peerDowns counts the peerDown goroutines that have
// not returned.
downPeers []string
peerDownRunning bool
peerDowns sync.WaitGroup
// tablePeersDown is the table's PeersDown. Only peerDown calls it, so a
// test may replace it before it hands the handler a message.
tablePeersDown func(peers []string)
} }
// seenPrefix is what the batch keeps of an update: the prefix it names and its // seenPrefix is what the batch keeps of an update: the prefix it names and its
@@ -119,26 +172,35 @@ func (u prefixUpdate) announcesRoute() bool {
func NewPrefixHandler( func NewPrefixHandler(
db database.Store, logger *logger.Logger, table *routetable.Table, db database.Store, logger *logger.Logger, table *routetable.Table,
) *PrefixHandler { ) *PrefixHandler {
return newPrefixHandler(db, logger, table, prefixBatchTimeout) return newPrefixHandler(db, logger, table, prefixBatchTimeout,
maxTableChangesPerWrite)
} }
// newPrefixHandler is NewPrefixHandler with the flush timer's interval, // newPrefixHandler is NewPrefixHandler with the flush timer's interval,
// batchTimeout, in place of prefixBatchTimeout. A test that the timer must not // batchTimeout, in place of prefixBatchTimeout, and tableChangesPerWrite in
// disturb gives an interval longer than the test runs. // 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( func newPrefixHandler(
db database.Store, logger *logger.Logger, table *routetable.Table, db database.Store, logger *logger.Logger, table *routetable.Table,
batchTimeout time.Duration, batchTimeout time.Duration, tableChangesPerWrite int,
) *PrefixHandler { ) *PrefixHandler {
h := &PrefixHandler{ h := &PrefixHandler{
db: db, db: db,
logger: logger, logger: logger,
table: table, table: table,
batch: make([]seenPrefix, 0, prefixBatchSize), batch: make([]seenPrefix, 0, prefixBatchSize),
batchFullCh: make(chan struct{}, 1), batchMaxSize: prefixBatchMaxSize,
stopCh: make(chan context.Context, 1), tableChangesPerWrite: tableChangesPerWrite,
done: make(chan struct{}), batchFullCh: make(chan struct{}, 1),
stopCh: make(chan context.Context, 1),
done: make(chan struct{}),
heldBack: make(map[string][]*ristypes.RISMessage),
tablePeersDown: table.PeersDown,
} }
h.batchTaken.L = &h.mu h.batchTaken.L = &h.mu
h.heldTaken.L = &h.mu
// Start the flush timer goroutine // Start the flush timer goroutine
go flushLoop(batchTimeout, h.batchFullCh, h.stopCh, h.done, h.flushBatch) go flushLoop(batchTimeout, h.batchFullCh, h.stopCh, h.done, h.flushBatch)
@@ -166,11 +228,100 @@ func (h *PrefixHandler) QueueCapacity() int {
return prefixHandlerQueueSize return prefixHandlerQueueSize
} }
// HandleMessage processes a message to track prefix information // HandleMessage processes a message to track prefix information. A message
// from a peer whose session went down is held back until peerDown applies it.
func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) { func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) {
h.mu.Lock()
defer h.mu.Unlock()
// While maxHeldBackMessages messages are held back, wait until one of them
// is taken out to be applied. Meanwhile the handler takes nothing off its
// queue, as at batchMaxSize.
for h.heldCount >= maxHeldBackMessages {
h.heldTaken.Wait()
}
held, goingDown := h.heldBack[msg.Peer]
if goingDown {
h.heldBack[msg.Peer] = append(held, msg)
h.heldCount++
return
}
h.applyMessage(msg)
}
// HeldBackCount returns how many messages the handler holds back from peers
// whose session went down. The status page shows it.
func (h *PrefixHandler) HeldBackCount() int {
h.mu.Lock()
defer h.mu.Unlock()
return h.heldCount
}
// Stop waits for every PeersDown the handler started and for the messages held
// back meanwhile to be applied. It gives up this wait once ctx ends. Then Stop
// stops the flush goroutine and waits for it until ctx ends. The flush
// goroutine makes one last flush before it returns. That flush writes at most
// 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 updates and table changes are not written. It also logs how many
// held-back messages are not applied. The caller calls Stop once its last
// HandleMessage has returned.
func (h *PrefixHandler) Stop(ctx context.Context) {
peerDownsDone := make(chan struct{})
go func() {
h.peerDowns.Wait()
close(peerDownsDone)
}()
select {
case <-peerDownsDone:
case <-ctx.Done():
}
h.stopCh <- ctx
select {
case <-h.done:
case <-ctx.Done():
}
h.mu.Lock()
unwritten := h.writing + len(h.batch)
tableChanges := h.writingTableChanges + h.table.ChangeCount()
heldMessages := h.heldCount
h.mu.Unlock()
if unwritten == 0 && tableChanges == 0 && heldMessages == 0 {
return
}
if ctx.Err() != nil {
h.logger.Error("Stop deadline passed before the prefix handler wrote "+
"its updates", "updates", unwritten, "table_changes", tableChanges,
"held_messages", heldMessages)
return
}
h.logger.Error("The prefix handler stopped before it wrote everything",
"updates", unwritten, "table_changes", tableChanges,
"held_messages", heldMessages)
}
// applyMessage applies msg. The caller holds mu. A peer's session going down
// has the peer leave every prefix. An update is applied to the routing table,
// and its prefixes join the batch.
func (h *PrefixHandler) applyMessage(msg *ristypes.RISMessage) {
if msg.Type == ristypes.MessageTypeState { if msg.Type == ristypes.MessageTypeState {
if msg.State == ristypes.StateDown { if msg.State == ristypes.StateDown {
h.table.PeerDown(msg.Peer) h.startPeerDown(msg.Peer)
} }
return return
@@ -185,13 +336,10 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) {
// the path after the rest of it. // the path after the rest of it.
path := slices.Concat(msg.Path.Sequence, msg.Path.Set) path := slices.Concat(msg.Path.Sequence, msg.Path.Set)
h.mu.Lock()
defer h.mu.Unlock()
// While the batch is at its maximum size, wait until the flush goroutine // While the batch is at its maximum size, wait until the flush goroutine
// takes it. Meanwhile the handler takes nothing off its queue, which // takes it. Meanwhile the handler takes nothing off its queue, which
// fills, and the streamer drops messages for it. // fills, and the streamer drops messages for it.
for len(h.batch) >= prefixBatchMaxSize { for len(h.batch) >= h.batchMaxSize {
h.batchTaken.Wait() h.batchTaken.Wait()
} }
@@ -239,7 +387,7 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) {
// A full batch wakes the flush goroutine. If it is writing, the wake-up // 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 // 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 { if len(h.batch) >= prefixBatchSize {
select { select {
case h.batchFullCh <- struct{}{}: case h.batchFullCh <- struct{}{}:
@@ -248,39 +396,88 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) {
} }
} }
// Stop stops the flush goroutine, which makes one last flush before it returns, // startPeerDown adds peer to downPeers. It starts peerDown on a new goroutine
// and waits for it until ctx ends. That flush writes at most // unless peerDown is running. The caller holds mu. The peer's messages are
// maxTableChangesPerWrite of the routing table's changes, and the prefixes of // held back until peerDown has applied them. Messages held back for an earlier
// the updates the handler holds. Once ctx has ended the flush goroutine skips // session of the peer going down, and not yet applied, stay held back.
// that last flush, and a write still running is lost when the process exits. A func (h *PrefixHandler) startPeerDown(peer string) {
// failed write of the table's changes is not retried either. Stop logs how many _, goingDown := h.heldBack[peer]
// updates and how many of the table's changes are not written. if !goingDown {
func (h *PrefixHandler) Stop(ctx context.Context) { h.heldBack[peer] = []*ristypes.RISMessage{}
h.stopCh <- ctx
select {
case <-h.done:
case <-ctx.Done():
} }
h.mu.Lock() h.downPeers = append(h.downPeers, peer)
unwritten := h.writing + len(h.batch)
tableChanges := h.writingTableChanges + h.table.ChangeCount()
h.mu.Unlock()
if unwritten == 0 && tableChanges == 0 { if h.peerDownRunning {
return return
} }
if ctx.Err() != nil { h.peerDownRunning = true
h.logger.Error("Stop deadline passed before the prefix handler wrote "+ h.peerDowns.Add(1)
"its updates", "updates", unwritten, "table_changes", tableChanges)
return go h.peerDown()
}
// peerDown takes every peer in downPeers and runs the table's PeersDown for
// them. Then it applies the messages held back from each of those peers. It
// repeats this until downPeers is empty.
func (h *PrefixHandler) peerDown() {
defer h.peerDowns.Done()
for {
h.mu.Lock()
peers := h.downPeers
h.downPeers = nil
if len(peers) == 0 {
h.peerDownRunning = false
h.mu.Unlock()
return
}
h.mu.Unlock()
h.tablePeersDown(peers)
for _, peer := range peers {
h.applyHeldBack(peer)
}
} }
}
h.logger.Error("The prefix handler stopped before it wrote everything", // applyHeldBack applies the messages held back from peer, in order. It takes
"updates", unwritten, "table_changes", tableChanges) // mu for one message at a time, so HandleMessage takes new messages in
// between. The peer's new messages join the end of the held-back ones. A
// held-back message that says the peer's session went down again adds the
// peer to downPeers. The rest stay held back until the next PeersDown has
// returned.
func (h *PrefixHandler) applyHeldBack(peer string) {
for {
h.mu.Lock()
held := h.heldBack[peer]
if len(held) == 0 {
delete(h.heldBack, peer)
h.mu.Unlock()
return
}
msg := held[0]
held[0] = nil // so that the message is freed once applied
h.heldBack[peer] = held[1:]
h.heldCount--
h.heldTaken.Broadcast()
h.applyMessage(msg)
h.mu.Unlock()
if msg.Type == ristypes.MessageTypeState &&
msg.State == ristypes.StateDown {
return
}
}
} }
// takeBatch returns the pending updates and leaves an empty batch in their // takeBatch returns the pending updates and leaves an empty batch in their
@@ -378,14 +575,13 @@ func (h *PrefixHandler) applyToTable(update prefixUpdate) {
}) })
} }
// writeTableChanges writes at most maxTableChangesPerWrite changes of the // writeTableChanges writes at most tableChangesPerWrite changes of the routing
// routing table in memory, and every peer the table numbered since the last // table in memory, and every peer the table numbered since the last write.
// write.
// When the write fails, they go back to the table, so that a later write writes // When the write fails, they go back to the table, so that a later write writes
// them again, each pair with its content then. // them again, each pair with its content then.
func (h *PrefixHandler) writeTableChanges() { func (h *PrefixHandler) writeTableChanges() {
h.mu.Lock() h.mu.Lock()
changes, newPeers := h.table.TakeChanges(maxTableChangesPerWrite) changes, newPeers := h.table.TakeChanges(h.tableChangesPerWrite)
h.writingTableChanges = len(changes) h.writingTableChanges = len(changes)
h.mu.Unlock() h.mu.Unlock()
internal/routewatch/prefixhandler_internal_test.go
+103 -6
View File
@@ -237,22 +237,119 @@ func TestPrefixHandlerStopLogsNothingWhenItWroteEverything(t *testing.T) {
} }
} }
// longerThanAnyTest is a flush timer interval that no test lasts. A test whose // TestPrefixHandlerStopLogsTheMessagesHeldBack stops a prefix handler with a
// prefix, AS or peer handler must flush only when its batch is full and on Stop // deadline that has passed, while a peer's PeersDown is held up and one message
// gives it to newPrefixHandler, newASHandler or newPeerHandler. // of the peer is held back. Stop must log that message as not applied.
func TestPrefixHandlerStopLogsTheMessagesHeldBack(t *testing.T) {
t.Parallel()
var logs bytes.Buffer
h := newPrefixHandler(newMockStore(), newErrorLogger(&logs),
routetable.New(routetable.Params{}), longerThanAnyTest,
maxTableChangesPerWrite)
release := holdUpPeersDown(h)
defer close(release)
h.HandleMessage(peerAnnouncement(testPeerIP, testV4Prefix))
h.HandleMessage(sessionDown())
h.HandleMessage(peerAnnouncement(testPeerIP, testV6Prefix))
ctx, cancel := context.WithCancel(t.Context())
cancel()
h.Stop(ctx)
logged := lastLogged(t, &logs)
if logged.HeldMessages != 1 {
t.Errorf("Stop logged %d held messages not applied, want 1",
logged.HeldMessages)
}
}
// TestPrefixHandlerStopWaitsForTheMessagesHeldBack stops a prefix handler
// while a peer's PeersDown is held up and an announcement of the peer is held
// back. Stop must wait. Once the PeersDown is let go and Stop returns, the
// announcement must be in the database.
func TestPrefixHandlerStopWaitsForTheMessagesHeldBack(t *testing.T) {
t.Parallel()
db := newTestDatabase(t)
h := newPrefixHandler(db, logger.New(), routetable.New(routetable.Params{}),
longerThanAnyTest, maxTableChangesPerWrite)
release := holdUpPeersDown(h)
h.HandleMessage(sessionDown())
h.HandleMessage(peerAnnouncement(testPeerIP, testV4Prefix))
stopped := make(chan struct{})
go func() {
h.Stop(t.Context())
close(stopped)
}()
select {
case <-stopped:
t.Error("Stop returned while a PeersDown was held up")
case <-time.After(stillWaitingAfter):
}
close(release)
select {
case <-stopped:
case <-time.After(stepTimeout):
t.Fatalf("Stop did not return within %s of the PeersDown's release",
stepTimeout)
}
read, err := db.ReadRouteTable(t.Context())
if err != nil {
t.Fatalf("ReadRouteTable: %v", err)
}
checkTableOrigins(t, read, map[string]map[int][]string{
testV4Prefix: {testASNB: {testPeerIP}},
})
}
// 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 const longerThanAnyTest = time.Hour
// prefixHandlerWithoutTimer returns a prefix handler that writes to store and // prefixHandlerWithoutTimer returns a prefix handler that writes to store and
// applies the updates to an empty routing table. It is built without // applies the updates to an empty routing table. It is built without
// NewPrefixHandler's flush goroutine, so the test flushes itself. // NewPrefixHandler's flush goroutine, so the test flushes itself.
func prefixHandlerWithoutTimer(store database.Store) *PrefixHandler { func prefixHandlerWithoutTimer(store database.Store) *PrefixHandler {
table := routetable.New(routetable.Params{})
return &PrefixHandler{ return &PrefixHandler{
db: store, db: store,
logger: logger.New(), logger: logger.New(),
table: routetable.New(routetable.Params{}), table: table,
batchMaxSize: prefixBatchMaxSize,
tableChangesPerWrite: maxTableChangesPerWrite,
heldBack: make(map[string][]*ristypes.RISMessage),
tablePeersDown: table.PeersDown,
} }
} }
// holdUpPeersDown makes each PeersDown of h wait until the returned channel is
// closed, as another peer's long PeersDown would hold it up. The test calls it
// before it hands h a message.
func holdUpPeersDown(h *PrefixHandler) chan struct{} {
release := make(chan struct{})
h.tablePeersDown = func(peers []string) {
<-release
h.table.PeersDown(peers)
}
return release
}
// newTestDatabase opens a database in a new temporary directory. It is closed // newTestDatabase opens a database in a new temporary directory. It is closed
// when the test ends. // when the test ends.
func newTestDatabase(t *testing.T) *database.Database { func newTestDatabase(t *testing.T) *database.Database {
internal/routewatch/prefixhandler_table_internal_test.go
+401 -23
View File
@@ -7,8 +7,10 @@ import (
"log/slog" "log/slog"
"net/netip" "net/netip"
"reflect" "reflect"
"runtime"
"slices" "slices"
"strings" "strings"
"sync"
"testing" "testing"
"time" "time"
@@ -30,11 +32,12 @@ const (
// firstManyPrefix is the first prefix announceManyPrefixes announces. // firstManyPrefix is the first prefix announceManyPrefixes announces.
firstManyPrefix = "10.0.0.0/32" firstManyPrefix = "10.0.0.0/32"
)
// tableWriteTimeout is how long a test waits for the flush timer to write the // testMaxTableChangesPerWrite is a limit of one write of the routing
// routing table's changes: a few ticks of it. // table's changes that a test exceeds quickly, in place of
const tableWriteTimeout = 5 * prefixBatchTimeout // maxTableChangesPerWrite.
testMaxTableChangesPerWrite = 10
)
// tableCase is one test of the routing table in memory: the messages handed to // 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 // the prefix handler, and for each prefix the peers that carry it with each
@@ -100,6 +103,359 @@ func TestPrefixHandlerAppliesUpdatesToTheRoutingTable(t *testing.T) {
}) })
} }
// TestPrefixHandlerTakesMessagesWhileAPeerGoesDown holds up the PeersDown of a
// peer whose session went down, as another peer's long PeersDown would. The
// handler must go on taking messages. It applies another peer's announcement
// at once. It holds back these messages of the down peer, in this order:
// - an announcement;
// - its session going down again;
// - a second announcement.
//
// HeldBackCount must count them. Once the PeersDown calls have returned, the
// down peer must carry only the prefix of the second announcement.
func TestPrefixHandlerTakesMessagesWhileAPeerGoesDown(t *testing.T) {
t.Parallel()
const heldMessages = 3
h := prefixHandlerWithoutTimer(newMockStore())
release := holdUpPeersDown(h)
h.HandleMessage(peerAnnouncement(testPeerIP, testV4Prefix))
handled := returnsInTime(func() {
for _, msg := range []*ristypes.RISMessage{
sessionDown(),
peerAnnouncement(secondPeerIP, otherV4Prefix),
peerAnnouncement(testPeerIP, testV6Prefix),
sessionDown(),
peerAnnouncement(testPeerIP, setV4Prefix),
} {
h.HandleMessage(msg)
}
})
if !handled {
t.Fatalf("the handler did not take the messages after the session "+
"went down within %s", stepTimeout)
}
checkTableOrigins(t, h.table, map[string]map[int][]string{
testV4Prefix: {testASNB: {testPeerIP}},
otherV4Prefix: {testASNB: {secondPeerIP}},
testV6Prefix: {},
setV4Prefix: {},
})
if h.HeldBackCount() != heldMessages {
t.Errorf("HeldBackCount() = %d, want %d", h.HeldBackCount(),
heldMessages)
}
close(release)
if !returnsInTime(h.peerDowns.Wait) {
t.Fatalf("the PeersDown calls did not return within %s", stepTimeout)
}
checkTableOrigins(t, h.table, map[string]map[int][]string{
testV4Prefix: {},
otherV4Prefix: {testASNB: {secondPeerIP}},
testV6Prefix: {},
setV4Prefix: {testASNB: {testPeerIP}},
})
}
// TestPrefixHandlerTakesPeersDownTogether has four peers announce testV4Prefix.
// It holds up the PeersDown of the first peer, whose session goes down.
// Meanwhile the sessions of the three others go down, and each of them
// announces otherV4Prefix. Once the first PeersDown is let go, the next one
// must take the three others together. No peer may then carry testV4Prefix,
// and the three others must carry otherV4Prefix.
func TestPrefixHandlerTakesPeersDownTogether(t *testing.T) {
t.Parallel()
others := []string{secondPeerIP, thirdPeerIP, fourthPeerIP}
h := prefixHandlerWithoutTimer(newMockStore())
// calls receives the peers of each PeersDown, with room for one call
// for each peer.
calls := make(chan []string, len(others)+1)
release := make(chan struct{})
h.tablePeersDown = func(peers []string) {
calls <- slices.Clone(peers)
<-release
h.table.PeersDown(peers)
}
for _, peer := range append([]string{testPeerIP}, others...) {
h.HandleMessage(peerAnnouncement(peer, testV4Prefix))
}
h.HandleMessage(sessionDown())
select {
case <-calls:
case <-time.After(stepTimeout):
t.Fatalf("PeersDown did not begin within %s", stepTimeout)
}
for _, peer := range others {
h.HandleMessage(sessionDownOf(peer))
h.HandleMessage(peerAnnouncement(peer, otherV4Prefix))
}
close(release)
if !returnsInTime(h.peerDowns.Wait) {
t.Fatalf("the PeersDown calls did not return within %s", stepTimeout)
}
close(calls)
later := make([][]string, 0, len(calls))
for peers := range calls {
later = append(later, peers)
}
if !reflect.DeepEqual(later, [][]string{others}) {
t.Errorf("the PeersDown calls after the first took %v, want %v "+
"together", later, others)
}
checkTableOrigins(t, h.table, map[string]map[int][]string{
testV4Prefix: {},
otherV4Prefix: {testASNB: others},
})
}
// TestPrefixHandlerAppliesMessagesWhilePeersDownRuns gives a peer 50,000
// prefixes and hands the prefix handler that peer's session going down. The
// table's PeersDown then visits the prefixes in five batches. Once PeersDown
// has begun, the handler is handed 1,000 announcements of another peer. The
// handler must apply them all before PeersDown ends, while the down peer still
// carries some of its prefixes.
func TestPrefixHandlerAppliesMessagesWhilePeersDownRuns(t *testing.T) {
t.Parallel()
const (
// downPeerPrefixes is five times the 10,000 prefixes PeersDown visits
// in one hold of the table's lock.
downPeerPrefixes = 50000
// otherPeerMessages is far more messages than the handler applies
// while PeersDown runs, if PeersDown takes the lock back at once after
// each batch. The handler then applies only a few for each batch.
otherPeerMessages = 1000
// firstOtherAddr is the address of the other peer's first prefix.
firstOtherAddr = "2001:db8:2::"
)
h := prefixHandlerWithoutTimer(newMockStore())
announceManyPrefixes(h.table, downPeerPrefixes)
h.HandleMessage(sessionDown())
// Wait until PeersDown has begun: the down peer has left some of its
// prefixes. The down peer's prefixes are IPv4 and the other peer's are
// IPv6, so the counts tell them apart.
for h.table.Counts().IPv4Routes == downPeerPrefixes {
runtime.Gosched()
}
// Each announcement names the /128 of the next address.
addr := netip.MustParseAddr(firstOtherAddr)
for range otherPeerMessages {
h.HandleMessage(peerAnnouncement(secondPeerIP,
netip.PrefixFrom(addr, addr.BitLen()).String()))
addr = addr.Next()
}
counts := h.table.Counts()
if counts.IPv6Routes != otherPeerMessages {
t.Errorf("the other peer carries %d prefixes, want %d",
counts.IPv6Routes, otherPeerMessages)
}
if counts.IPv4Routes == 0 {
t.Errorf("PeersDown ended before the handler applied the other peer's "+
"%d announcements", otherPeerMessages)
}
if !returnsInTime(h.peerDowns.Wait) {
t.Fatalf("the PeersDown did not return within %s", stepTimeout)
}
}
// TestPrefixHandlerTakesMessagesWhileAReturningPeerSendsItsTable gives a peer
// 50,000 prefixes and hands the prefix handler that peer's session going down.
// Once PeersDown has begun, the peer comes back and sends more announcements
// than the handler's queue holds, as a peer that sends its whole table again
// does. The handler must hold them back and go on taking messages. Another
// peer's announcement, handed next, must be applied before PeersDown ends.
func TestPrefixHandlerTakesMessagesWhileAReturningPeerSendsItsTable(t *testing.T) {
t.Parallel()
const (
// downPeerPrefixes is five times the 10,000 prefixes PeersDown visits
// in one hold of the table's lock.
downPeerPrefixes = 50000
returningMessages = prefixHandlerQueueSize + 1
)
table := routetable.New(routetable.Params{})
announceManyPrefixes(table, downPeerPrefixes)
h := newPrefixHandler(newMockStore(), logger.New(), table,
longerThanAnyTest, maxTableChangesPerWrite)
defer stopInTime(t, h)
h.HandleMessage(sessionDown())
// Wait until PeersDown has begun: the down peer has left some of its
// prefixes, which are all IPv4.
for h.table.Counts().IPv4Routes == downPeerPrefixes {
runtime.Gosched()
}
returning := peerAnnouncement(testPeerIP, testV6Prefix)
if !returnsInTime(func() {
for range returningMessages {
h.HandleMessage(returning)
}
h.HandleMessage(peerAnnouncement(secondPeerIP, testV6Prefix))
}) {
t.Fatalf("the handler did not take the messages within %s", stepTimeout)
}
if h.table.Counts().IPv4Routes == 0 {
t.Error("PeersDown ended before the handler took the other peer's " +
"announcement")
}
checkTableOrigins(t, h.table, map[string]map[int][]string{
testV6Prefix: {testASNB: {secondPeerIP}},
})
if !returnsInTime(h.peerDowns.Wait) {
t.Fatalf("the PeersDown did not return within %s", stepTimeout)
}
checkTableOrigins(t, h.table, map[string]map[int][]string{
testV6Prefix: {testASNB: {testPeerIP, secondPeerIP}},
})
}
// TestPrefixHandlerTakesMessagesWhileItAppliesHeldBackOnes holds back many
// messages of a peer whose session went down. Each names a prefix that does
// not parse, so applying it logs an error. Each log write takes a
// millisecond. While the handler applies the held-back messages, it must take
// another peer's announcement.
func TestPrefixHandlerTakesMessagesWhileItAppliesHeldBackOnes(t *testing.T) {
t.Parallel()
const (
// heldMessages take the handler at least a second to apply.
heldMessages = 1000
badPrefix = "not a prefix"
)
logs := &slowWriter{firstWrite: make(chan struct{})}
h := newPrefixHandler(newMockStore(), newErrorLogger(logs),
routetable.New(routetable.Params{}), longerThanAnyTest,
maxTableChangesPerWrite)
defer stopInTime(t, h)
release := holdUpPeersDown(h)
h.HandleMessage(sessionDown())
for range heldMessages {
h.HandleMessage(peerAnnouncement(testPeerIP, badPrefix))
}
close(release)
select {
case <-logs.firstWrite:
case <-time.After(stepTimeout):
t.Fatal("the handler did not start to apply the held-back messages")
}
if !returnsInTime(func() {
h.HandleMessage(peerAnnouncement(secondPeerIP, otherV4Prefix))
}) {
t.Fatalf("HandleMessage did not return within %s", stepTimeout)
}
h.mu.Lock()
left := len(h.heldBack[testPeerIP])
h.mu.Unlock()
if left == 0 {
t.Error("the handler took another peer's announcement only once it " +
"had applied every held-back message")
}
}
// TestPrefixHandlerWaitsAtTheMaximumHeldBack holds up the PeersDown of a peer
// whose session went down. It hands the handler maxHeldBackMessages messages
// of that peer. HandleMessage must then wait, even for another peer's
// message, until the PeersDown returns and a held-back message is applied.
func TestPrefixHandlerWaitsAtTheMaximumHeldBack(t *testing.T) {
t.Parallel()
h := newPrefixHandler(newMockStore(), logger.New(),
routetable.New(routetable.Params{}), longerThanAnyTest,
maxTableChangesPerWrite)
defer stopInTime(t, h)
release := holdUpPeersDown(h)
h.HandleMessage(sessionDown())
held := peerAnnouncement(testPeerIP, testV6Prefix)
for range maxHeldBackMessages {
h.HandleMessage(held)
}
returned := make(chan struct{})
go func() {
h.HandleMessage(peerAnnouncement(secondPeerIP, otherV4Prefix))
close(returned)
}()
select {
case <-returned:
t.Error("HandleMessage returned while maxHeldBackMessages messages " +
"were held back")
case <-time.After(stillWaitingAfter):
}
close(release)
select {
case <-returned:
case <-time.After(stepTimeout):
t.Fatal("HandleMessage did not return after the PeersDown returned")
}
}
// slowWriter takes a millisecond over each write and drops what it is given.
// It closes firstWrite at the first write.
type slowWriter struct {
firstWrite chan struct{}
once sync.Once
}
func (w *slowWriter) Write(p []byte) (int, error) {
w.once.Do(func() { close(w.firstWrite) })
time.Sleep(time.Millisecond)
return len(p), nil
}
// TestPrefixHandlerAppliesAPathWithoutAnOriginToTheRoutingTable hands the // TestPrefixHandlerAppliesAPathWithoutAnOriginToTheRoutingTable hands the
// prefix handler announcements whose AS path gives no origin. One whose path // prefix handler announcements whose AS path gives no origin. One whose path
// is empty or holds AS 0 removes the peer's route, as a withdrawal does; one // is empty or holds AS 0 removes the peer's route, as a withdrawal does; one
@@ -198,8 +554,9 @@ func TestPrefixHandlerKeepsThePathOfAPathEndingInASet(t *testing.T) {
} }
} }
// checkTableCases hands the messages of each case to a new prefix handler and // checkTableCases hands the messages of each case to a new prefix handler. It
// checks its routing table right after, with no flush. // checks the handler's routing table once the handler's PeersDown calls have
// returned, with no flush.
func checkTableCases(t *testing.T, tests []tableCase) { func checkTableCases(t *testing.T, tests []tableCase) {
t.Helper() t.Helper()
@@ -212,17 +569,28 @@ func checkTableCases(t *testing.T, tests []tableCase) {
h.HandleMessage(msg) h.HandleMessage(msg)
} }
for prefix, want := range tt.want { h.peerDowns.Wait()
got := tableOrigins(h.table, prefix) checkTableOrigins(t, h.table, tt.want)
if !reflect.DeepEqual(got, want) {
t.Errorf("peers of %s by origin AS = %v, want %v",
prefix, got, want)
}
}
}) })
} }
} }
// checkTableOrigins checks, for each prefix in want, the peers that carry it
// in table with each origin AS.
func checkTableOrigins(
t *testing.T, table *routetable.Table, want map[string]map[int][]string,
) {
t.Helper()
for prefix, wantOrigins := range want {
got := tableOrigins(table, prefix)
if !reflect.DeepEqual(got, wantOrigins) {
t.Errorf("peers of %s by origin AS = %v, want %v",
prefix, got, wantOrigins)
}
}
}
// tableWritesStore is a real database that hands each write of the routing // tableWritesStore is a real database that hands each write of the routing
// table's changes to written once it is made. // table's changes to written once it is made.
type tableWritesStore struct { type tableWritesStore struct {
@@ -276,9 +644,9 @@ func TestPrefixHandlerWritesTheTableChangesEachSecond(t *testing.T) {
t.Fatalf("wrote %+v, want the pair of %s and AS%d with "+ t.Fatalf("wrote %+v, want the pair of %s and AS%d with "+
"removed %t", changes, prefix, testASNB, step.wantRemoved) "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", t.Fatalf("the routing table's change was not written within %s",
tableWriteTimeout) stepTimeout)
} }
} }
} }
@@ -375,25 +743,32 @@ func (s *tableWriteSizesStore) WriteRouteChanges(
// takes, then flushes three times. The first write must hold as many pairs as // 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 // 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 // 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) { func TestPrefixHandlerWritesManyTableChangesOverSeveralFlushes(t *testing.T) {
t.Parallel() t.Parallel()
const ( const (
pairs = maxTableChangesPerWrite * 3 / 2 pairs = testMaxTableChangesPerWrite * 3 / 2
flushes = 3 flushes = 3
) )
db := newTestDatabase(t) db := newTestDatabase(t)
store := &tableWriteSizesStore{Database: db} store := &tableWriteSizesStore{Database: db}
h := prefixHandlerWithoutTimer(store) table := routetable.New(routetable.Params{})
announceManyPrefixes(h.table, pairs) announceManyPrefixes(table, pairs)
h := newPrefixHandler(store, logger.New(), table, longerThanAnyTest,
testMaxTableChangesPerWrite)
defer stopInTime(t, h)
for range flushes { for range flushes {
h.flushBatch() h.flushBatch()
} }
wantChanges := []int{maxTableChangesPerWrite, pairs - maxTableChangesPerWrite} wantChanges := []int{
testMaxTableChangesPerWrite, pairs - testMaxTableChangesPerWrite,
}
wantNewPeers := []int{1, 0} wantNewPeers := []int{1, 0}
if !slices.Equal(store.changes, wantChanges) || if !slices.Equal(store.changes, wantChanges) ||
@@ -415,11 +790,11 @@ func TestPrefixHandlerWritesManyTableChangesOverSeveralFlushes(t *testing.T) {
// takes. Its last flush writes one write's worth, so Stop must log the pairs // 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 // 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 // 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) { func TestPrefixHandlerStopLogsTheTableChangesLeftUnwritten(t *testing.T) {
t.Parallel() t.Parallel()
const pairs = maxTableChangesPerWrite + 1 const pairs = testMaxTableChangesPerWrite + 1
var logs bytes.Buffer var logs bytes.Buffer
@@ -427,7 +802,8 @@ func TestPrefixHandlerStopLogsTheTableChangesLeftUnwritten(t *testing.T) {
table := routetable.New(routetable.Params{}) table := routetable.New(routetable.Params{})
announceManyPrefixes(table, pairs) announceManyPrefixes(table, pairs)
h := newPrefixHandler(store, newErrorLogger(&logs), table, longerThanAnyTest) h := newPrefixHandler(store, newErrorLogger(&logs), table, longerThanAnyTest,
testMaxTableChangesPerWrite)
h.Stop(t.Context()) h.Stop(t.Context())
written := 0 written := 0
@@ -489,6 +865,7 @@ func TestARestartReadsTheRoutingTableBack(t *testing.T) {
h.HandleMessage(msg) h.HandleMessage(msg)
} }
h.peerDowns.Wait()
h.flushBatch() h.flushBatch()
var logs bytes.Buffer var logs bytes.Buffer
@@ -527,6 +904,7 @@ func TestARestartReadsTheRoutingTableBack(t *testing.T) {
restarted.HandleMessage(msg) restarted.HandleMessage(msg)
} }
h.peerDowns.Wait()
restarted.Stop(t.Context()) restarted.Stop(t.Context())
read, err := db.ReadRouteTable(t.Context()) read, err := db.ReadRouteTable(t.Context())
internal/server/handlers.go
+2
View File
@@ -486,6 +486,7 @@ type HandlerStatsInfo struct {
QueueHighWaterMark int `json:"queue_high_water_mark"` QueueHighWaterMark int `json:"queue_high_water_mark"`
ProcessedCount uint64 `json:"processed_count"` ProcessedCount uint64 `json:"processed_count"`
DroppedCount uint64 `json:"dropped_count"` DroppedCount uint64 `json:"dropped_count"`
HeldBackCount int `json:"held_back_count"`
AvgProcessTimeMs float64 `json:"avg_process_time_ms"` AvgProcessTimeMs float64 `json:"avg_process_time_ms"`
MinProcessTimeMs float64 `json:"min_process_time_ms"` MinProcessTimeMs float64 `json:"min_process_time_ms"`
MaxProcessTimeMs float64 `json:"max_process_time_ms"` MaxProcessTimeMs float64 `json:"max_process_time_ms"`
@@ -570,6 +571,7 @@ func handlerStatsInfo(handlerStats []streamer.HandlerStats) []HandlerStatsInfo {
QueueHighWaterMark: hs.QueueHighWaterMark, QueueHighWaterMark: hs.QueueHighWaterMark,
ProcessedCount: hs.ProcessedCount, ProcessedCount: hs.ProcessedCount,
DroppedCount: hs.DroppedCount, DroppedCount: hs.DroppedCount,
HeldBackCount: hs.HeldBackCount,
AvgProcessTimeMs: float64(hs.AvgProcessTime.Microseconds()) / AvgProcessTimeMs: float64(hs.AvgProcessTime.Microseconds()) /
microsecondsPerMillisecond, microsecondsPerMillisecond,
MinProcessTimeMs: float64(hs.MinProcessTime.Microseconds()) / MinProcessTimeMs: float64(hs.MinProcessTime.Microseconds()) /
internal/server/handlers_internal_test.go
+37
View File
@@ -295,6 +295,43 @@ func TestStatsAnswerCarriesChurnPerMinute(t *testing.T) {
} }
} }
// heldBackMessages is how many messages heldBackHandler holds back.
const heldBackMessages = 7
// heldBackHandler is a stream handler that wants no message and holds back
// heldBackMessages messages.
type heldBackHandler struct{}
func (heldBackHandler) WantsMessage(string) bool { return false }
func (heldBackHandler) HandleMessage(*ristypes.RISMessage) {}
func (heldBackHandler) QueueCapacity() int { return 1 }
func (heldBackHandler) HeldBackCount() int { return heldBackMessages }
// TestStatsAnswerGivesHowManyMessagesAHandlerHoldsBack registers a handler
// that holds back messages. Its figures in /api/v1/stats, which the status
// page shows, must give how many.
func TestStatsAnswerGivesHowManyMessagesAHandlerHoldsBack(t *testing.T) {
t.Parallel()
s := newServerWithTestRoutes(t)
s.streamer.RegisterHandler(heldBackHandler{})
var body struct {
Data StatsResponse `json:"data"`
}
err := json.Unmarshal(get(t, s, statsPath).Body.Bytes(), &body)
if err != nil {
t.Fatalf("decoding the answer: %v", err)
}
stats := body.Data.HandlerStats
if len(stats) != 1 || stats[0].HeldBackCount != heldBackMessages {
t.Errorf("handler figures %+v, want one handler holding back %d "+
"messages", stats, heldBackMessages)
}
}
// fixedIntervalASNFetcher is a WHOIS fetcher that does nothing and reports // fixedIntervalASNFetcher is a WHOIS fetcher that does nothing and reports
// interval as its wait between fetches. // interval as its wait between fetches.
type fixedIntervalASNFetcher struct { type fixedIntervalASNFetcher struct {
internal/server/middleware_internal_test.go
+1 -1
View File
@@ -261,7 +261,7 @@ func checkAnswerCarriesMeta(
) { ) {
t.Helper() t.Helper()
// The values README "API v1" gives the two fields that never change. // The values README "JSON API" gives the two fields that never change.
const ( const (
wantTimeZone = "UTC" wantTimeZone = "UTC"
wantAPIVersion = 1 wantAPIVersion = 1
internal/streamer/streamer.go
+9
View File
@@ -351,6 +351,10 @@ type HandlerStats struct {
AvgProcessTime time.Duration AvgProcessTime time.Duration
MinProcessTime time.Duration MinProcessTime time.Duration
MaxProcessTime time.Duration MaxProcessTime time.Duration
// HeldBackCount is how many messages the handler holds back to apply
// later: what its HeldBackCount method returns, or 0 for a handler
// without one.
HeldBackCount int
} }
// GetHandlerStats returns a snapshot of performance statistics for all registered // GetHandlerStats returns a snapshot of performance statistics for all registered
@@ -392,6 +396,11 @@ func (s *Streamer) GetHandlerStats() []HandlerStats {
info.metrics.mu.Unlock() info.metrics.mu.Unlock()
holder, holdsBack := info.handler.(interface{ HeldBackCount() int })
if holdsBack {
hs.HeldBackCount = holder.HeldBackCount()
}
stats = append(stats, hs) stats = append(stats, hs)
} }
internal/templates/status.html
+4
View File
@@ -541,6 +541,10 @@
<span class="metric-label">Dropped</span> <span class="metric-label">Dropped</span>
<span class="metric-value ${handler.dropped_count > 0 ? 'disconnected' : ''}">${formatNumber(handler.dropped_count)}</span> <span class="metric-value ${handler.dropped_count > 0 ? 'disconnected' : ''}">${formatNumber(handler.dropped_count)}</span>
</div> </div>
<div class="metric">
<span class="metric-label">Held Back</span>
<span class="metric-value">${formatNumber(handler.held_back_count)}</span>
</div>
<div class="metric"> <div class="metric">
<span class="metric-label">Avg Time</span> <span class="metric-label">Avg Time</span>
<span class="metric-value">${formatProcessingTime(handler.avg_process_time_ms)}</span> <span class="metric-value">${formatProcessingTime(handler.avg_process_time_ms)}</span>
internal/whois/whois.go
+82 -36
View File
@@ -12,6 +12,7 @@ import (
"regexp" "regexp"
"strings" "strings"
"sync" "sync"
"syscall"
"time" "time"
"unicode/utf8" "unicode/utf8"
@@ -70,12 +71,12 @@ const nicbrHeader = "% Copyright (c) Nic.br"
// queries to stop the data being taken in bulk. // queries to stop the data being taken in bulk.
const nicbrLimitReached = "Query rate limit exceeded" const nicbrLimitReached = "Query rate limit exceeded"
// NICbrSkipTime is how long the client stops asking NIC.br after NIC.br // PauseTime is how long the client sends an RIR's or NIC.br's server no
// answers that the client is over its query limit. NIC.br publishes // query after that server refuses a query. queryRegistry says what a
// neither the limit nor how long it lasts. An hour outlasts a limit // refusal is. RIPE refuses an address for good when the address keeps
// counted per minute or per hour. The ASes looked up meanwhile get // passing RIPE's limit (see noPersonalFlag). An hour outlasts a limit
// NIC.br's fields when they are next refreshed. // counted per minute or per hour.
const NICbrSkipTime = time.Hour const PauseTime = time.Hour
// RIR identifiers. // RIR identifiers.
const ( const (
@@ -125,6 +126,10 @@ var (
errAnswerTooLarge = errors.New("WHOIS answer reached the size cap") errAnswerTooLarge = errors.New("WHOIS answer reached the size cap")
) )
// ErrPaused is returned when a lookup needs a server that refused a query
// less than PauseTime ago. The client sends that server nothing meanwhile.
var ErrPaused = errors.New("WHOIS server paused after refusing a query")
// ASNInfo contains parsed WHOIS information for an ASN. // ASNInfo contains parsed WHOIS information for an ASN.
type ASNInfo struct { type ASNInfo struct {
ASN int ASN int
@@ -156,12 +161,12 @@ type Client struct {
logger *slog.Logger logger *slog.Logger
// mu guards nicbrSkipUntil. // mu guards pausedUntil.
mu sync.Mutex mu sync.Mutex
// nicbrSkipUntil is when the client next asks NIC.br, after NIC.br // pausedUntil maps a server, given as host:port, to the time the client
// answered that the client is over its query limit. // may ask it again.
nicbrSkipUntil time.Time pausedUntil map[string]time.Time
} }
// NewClient creates a new WHOIS client that logs to logger. // NewClient creates a new WHOIS client that logs to logger.
@@ -172,23 +177,29 @@ func NewClient(logger *slog.Logger) *Client {
DialContext: dialer.DialContext, DialContext: dialer.DialContext,
Now: time.Now, Now: time.Now,
logger: logger, logger: logger,
pausedUntil: make(map[string]time.Time),
} }
} }
// LookupASN asks IANA which RIR holds the given ASN, asks that RIR, and // LookupASN asks IANA which RIR holds the given ASN, asks that RIR, and
// returns what the RIR's answer says. When LACNIC's answer is NIC.br's, it // returns what the RIR's answer says. When LACNIC's answer is NIC.br's, it
// returns what NIC.br's own server says instead, unless that query fails or // returns what NIC.br's own server says instead, unless that query fails or
// is skipped, as askNICbr says. // NIC.br is paused, as askNICbr says.
// //
// It returns ErrNoReferral when IANA refers the AS to no RIR, and another // It returns ErrNoReferral when IANA refers the AS to no RIR. Its error
// error when the query to IANA or to the RIR fails, when the RIR refuses // wraps ErrPaused when the RIR is paused. It returns another error in each
// it, when IANA's answer has neither a referral nor the AS's block, when // of these cases:
// IANA refers the AS to a server none of the five RIRs run, or when the //
// answer carries none of ASNInfo's fields. // - the query to IANA or to the RIR fails
// - the RIR refuses the query
// - IANA's answer has neither a referral nor the AS's block
// - IANA refers the AS to a server none of the five RIRs run
// - the answer carries none of ASNInfo's fields
func (c *Client) LookupASN(ctx context.Context, asn int) (*ASNInfo, error) { func (c *Client) LookupASN(ctx context.Context, asn int) (*ASNInfo, error) {
// Query IANA first to find the authoritative RIR // Query IANA first to find the authoritative RIR
query := fmt.Sprintf("AS%d", asn) query := fmt.Sprintf("AS%d", asn)
// IANA is never paused, because a pause of IANA would stop every lookup.
ianaResp, err := c.query(ctx, whoisServerIANA, query) ianaResp, err := c.query(ctx, whoisServerIANA, query)
if err != nil { if err != nil {
return nil, fmt.Errorf("IANA query failed: %w", err) return nil, fmt.Errorf("IANA query failed: %w", err)
@@ -211,7 +222,7 @@ func (c *Client) LookupASN(ctx context.Context, asn int) (*ASNInfo, error) {
} }
// Query the authoritative RIR // Query the authoritative RIR
rirResp, err := c.queryRIR(ctx, whoisServer, rirQuery(rir, query)) rirResp, err := c.queryRegistry(ctx, whoisServer, rirQuery(rir, query))
if err != nil { if err != nil {
return nil, fmt.Errorf("RIR query failed: %w", err) return nil, fmt.Errorf("RIR query failed: %w", err)
} }
@@ -241,22 +252,19 @@ func (c *Client) LookupASN(ctx context.Context, asn int) (*ASNInfo, error) {
// askNICbr returns lacnicInfo, what LACNIC's answer says, and logs a // askNICbr returns lacnicInfo, what LACNIC's answer says, and logs a
// warning when the query fails, when NIC.br sends the reduced answer for a // warning when the query fails, when NIC.br sends the reduced answer for a
// client over its limit, or when NIC.br's answer carries none of ASNInfo's // client over its limit, or when NIC.br's answer carries none of ASNInfo's
// fields. After the reduced answer, it returns lacnicInfo without asking // fields. The reduced answer pauses NIC.br, as a refusal does. While NIC.br
// NIC.br until NICbrSkipTime has passed. // is paused, askNICbr returns lacnicInfo without a warning. The ASes looked
// up meanwhile get NIC.br's fields when they are next refreshed.
func (c *Client) askNICbr( func (c *Client) askNICbr(
ctx context.Context, asQuery string, lacnicInfo *ASNInfo, ctx context.Context, asQuery string, lacnicInfo *ASNInfo,
) *ASNInfo { ) *ASNInfo {
asn := lacnicInfo.ASN asn := lacnicInfo.ASN
c.mu.Lock() answer, err := c.queryRegistry(ctx, whoisServerNICbr, asQuery)
skipping := c.Now().Before(c.nicbrSkipUntil) if errors.Is(err, ErrPaused) {
c.mu.Unlock()
if skipping {
return lacnicInfo return lacnicInfo
} }
answer, err := c.query(ctx, whoisServerNICbr, asQuery)
if err != nil { if err != nil {
c.logger.Warn("NIC.br query failed, keeping LACNIC's fields", c.logger.Warn("NIC.br query failed, keeping LACNIC's fields",
"asn", asn, "error", err) "asn", asn, "error", err)
@@ -265,13 +273,11 @@ func (c *Client) askNICbr(
} }
if strings.Contains(answer, nicbrLimitReached) { if strings.Contains(answer, nicbrLimitReached) {
c.mu.Lock() c.pause(whoisServerNICbr)
c.nicbrSkipUntil = c.Now().Add(NICbrSkipTime)
c.mu.Unlock()
c.logger.Warn("NIC.br answered that the client is over its query "+ c.logger.Warn("NIC.br answered that the client is over its query "+
"limit, keeping LACNIC's fields and skipping NIC.br", "limit, keeping LACNIC's fields and pausing NIC.br",
"asn", asn, "skip_for", NICbrSkipTime) "asn", asn, "pause_for", PauseTime)
return lacnicInfo return lacnicInfo
} }
@@ -309,25 +315,65 @@ func rirQuery(rir, asQuery string) string {
} }
} }
// queryRIR sends query to an RIR's server and returns the answer. An answer // queryRegistry sends query to the server of an RIR or of NIC.br, and
// holding an error line with which the server refuses the query is an // returns the answer. The client pauses the server for PauseTime when the
// error, and the error holds that line. // server refuses the query. Each of these is a refusal:
func (c *Client) queryRIR( //
// - a refused connection
// - a reset connection
// - an %ERROR:201: or %ERROR:202: line in the answer
//
// A refusal is returned as an error. While the server is paused,
// queryRegistry sends it nothing and returns an error that wraps ErrPaused.
func (c *Client) queryRegistry(
ctx context.Context, server, query string, ctx context.Context, server, query string,
) (string, error) { ) (string, error) {
c.mu.Lock()
pausedUntil := c.pausedUntil[server]
c.mu.Unlock()
if c.Now().Before(pausedUntil) {
return "", fmt.Errorf("%w: %s until %s", ErrPaused, server,
pausedUntil.UTC().Format(time.RFC3339))
}
answer, err := c.query(ctx, server, query) answer, err := c.query(ctx, server, query)
if err == nil {
err = checkRefusal(answer)
}
if errors.Is(err, errRefused) || errors.Is(err, syscall.ECONNREFUSED) ||
errors.Is(err, syscall.ECONNRESET) {
c.pause(server)
}
if err != nil { if err != nil {
return "", err return "", err
} }
return answer, nil
}
// checkRefusal returns an error holding the first line of answer that
// starts with accessDeniedError or accessLimitError. It returns nil when
// answer has no such line.
func checkRefusal(answer string) error {
for line := range strings.SplitSeq(answer, "\n") { for line := range strings.SplitSeq(answer, "\n") {
if strings.HasPrefix(line, accessDeniedError) || if strings.HasPrefix(line, accessDeniedError) ||
strings.HasPrefix(line, accessLimitError) { strings.HasPrefix(line, accessLimitError) {
return "", fmt.Errorf("%w: %s", errRefused, line) return fmt.Errorf("%w: %s", errRefused, line)
} }
} }
return answer, nil return nil
}
// pause stops queryRegistry from querying server until PauseTime has passed.
func (c *Client) pause(server string) {
c.mu.Lock()
defer c.mu.Unlock()
c.pausedUntil[server] = c.Now().Add(PauseTime)
} }
// query performs a raw WHOIS query to the specified server and returns the // query performs a raw WHOIS query to the specified server and returns the
internal/whois/whois_test.go
+142 -5
View File
@@ -718,9 +718,10 @@ func TestLookupASNKeepsLACNICsAnswerWhenNICbrFails(t *testing.T) {
// TestLookupASNSkipsNICbrAfterItsLimit looks up an AS that NIC.br // TestLookupASNSkipsNICbrAfterItsLimit looks up an AS that NIC.br
// registers three times with one client, while NIC.br answers that the // registers three times with one client, while NIC.br answers that the
// client is over its query limit. The first lookup asks NIC.br. The // client is over its query limit. The test sets the client's clock. The
// second, a second before NICbrSkipTime has passed, does not. The third, // first lookup asks NIC.br. The next comes a second before PauseTime has
// once NICbrSkipTime has passed, asks again. Each keeps LACNIC's fields. // passed, and does not ask NIC.br. The last comes at PauseTime and asks
// NIC.br again. Each keeps LACNIC's fields.
func TestLookupASNSkipsNICbrAfterItsLimit(t *testing.T) { func TestLookupASNSkipsNICbrAfterItsLimit(t *testing.T) {
t.Parallel() t.Parallel()
@@ -740,8 +741,8 @@ func TestLookupASNSkipsNICbrAfterItsLimit(t *testing.T) {
wantAsks int wantAsks int
}{ }{
{after: 0, wantAsks: 1}, {after: 0, wantAsks: 1},
{after: whois.NICbrSkipTime - time.Second, wantAsks: 1}, {after: whois.PauseTime - time.Second, wantAsks: 1},
{after: whois.NICbrSkipTime, wantAsks: 2}, {after: whois.PauseTime, wantAsks: 2},
} { } {
now = start.Add(step.after) now = start.Add(step.after)
@@ -785,6 +786,142 @@ func TestLookupASNReportsARefusal(t *testing.T) {
} }
} }
// resetServer starts a TCP server on the loopback address and returns the
// server's address. The server reads one query on each connection, then
// resets the connection.
func resetServer(t *testing.T) string {
t.Helper()
var listenConfig net.ListenConfig
listener, err := listenConfig.Listen(t.Context(), "tcp", "127.0.0.1:0")
if err != nil {
t.Fatalf("listen: %v", err)
}
t.Cleanup(func() { _ = listener.Close() })
go func() {
for {
conn, err := listener.Accept()
if err != nil {
return
}
_, _ = bufio.NewReader(conn).ReadString('\n')
// Closing a connection whose linger time is zero resets it.
if tcpConn, ok := conn.(*net.TCPConn); ok {
_ = tcpConn.SetLinger(0)
}
_ = conn.Close()
}
}()
return listener.Addr().String()
}
// newRIPEClient returns a client whose fake servers send answers. The
// client adds one to *ripeAsks each time it connects to RIPE's server. When
// reset is true, RIPE's server resets the connection instead of answering.
func newRIPEClient(
t *testing.T, answers map[string]string, reset bool, ripeAsks *int,
) *whois.Client {
t.Helper()
dial := fakeServers(t, answers)
resetAddress := resetServer(t)
client := whois.NewClient(slog.New(slog.DiscardHandler))
client.DialContext = func(
ctx context.Context, network, address string,
) (net.Conn, error) {
if address == ripeServer {
*ripeAsks++
}
if address == ripeServer && reset {
var dialer net.Dialer
return dialer.DialContext(ctx, network, resetAddress)
}
return dial(ctx, network, address)
}
return client
}
// TestLookupASNPausesAServerThatRefuses looks up an AS at RIPE while RIPE
// refuses the query, in each of the ways a server refuses. The test sets
// the client's clock. A lookup a second before PauseTime has passed fails
// with ErrPaused and asks RIPE nothing. A lookup of an AS at APNIC succeeds
// during the pause. A lookup at PauseTime asks RIPE again.
func TestLookupASNPausesAServerThatRefuses(t *testing.T) {
t.Parallel()
for name, test := range map[string]struct {
// ripeAnswer is RIPE's answer. With none, RIPE's server refuses
// the connection, or resets it when reset is true.
ripeAnswer string
reset bool
}{
"access denied": {ripeAnswer: ripeRefusal},
"limit reached": {ripeAnswer: ripeLimitReached + "\n"},
"refused connection": {},
"reset connection": {reset: true},
} {
t.Run(name, func(t *testing.T) {
t.Parallel()
answers := map[string]string{
ianaQuery: ianaReferral,
apnicIANAQuery: "refer: whois.apnic.net\n",
apnicQuery: apnicRecord,
}
if test.ripeAnswer != "" {
answers[ripeQuery] = test.ripeAnswer
}
ripeAsks := 0
client := newRIPEClient(t, answers, test.reset, &ripeAsks)
start := time.Date(2026, 11, 2, 0, 0, 0, 0, time.UTC)
now := start
client.Now = func() time.Time { return now }
_, err := client.LookupASN(t.Context(), testASN)
if err == nil || errors.Is(err, whois.ErrPaused) {
t.Fatalf("LookupASN while RIPE refuses: error %v, want a "+
"refusal", err)
}
now = start.Add(whois.PauseTime - time.Second)
_, err = client.LookupASN(t.Context(), testASN)
if !errors.Is(err, whois.ErrPaused) || ripeAsks != 1 {
t.Errorf("LookupASN during the pause: error %v after %d "+
"queries to RIPE, want ErrPaused after 1", err, ripeAsks)
}
_, err = client.LookupASN(t.Context(), apnicASN)
if err != nil {
t.Errorf("LookupASN of an AS at APNIC during RIPE's "+
"pause: %v", err)
}
now = start.Add(whois.PauseTime)
_, _ = client.LookupASN(t.Context(), testASN)
if ripeAsks != 2 {
t.Errorf("RIPE was asked %d times after the pause, want 2",
ripeAsks)
}
})
}
}
// TestLookupASNFailsWhenTheRIRGivesNoAnswer looks up an AS IANA refers to // TestLookupASNFailsWhenTheRIRGivesNoAnswer looks up an AS IANA refers to
// RIPE when RIPE's server refuses the connection, and when it answers only // RIPE when RIPE's server refuses the connection, and when it answers only
// with an error. Neither is a lookup that found the AS. // with an error. Neither is a lookup that found the AS.