Author SHA1 Message Date
clawbot b4dee48401 Exit with status 1 when the web server cannot listen (closes #73)
check / check (push) Waiting to run
`Server.Start` opened its port inside a goroutine and returned nil at once, so a port already in use was only logged and the daemon kept running with no web server. It now opens the listener before returning and returns that error; serving runs in the background on the open listener. `CLIEntry` turns an error from `Run` into an fx shutdown with exit status 1, after the normal stop sequence, so a container restart policy can act. A serving error after a successful listen is still only logged.

Model: opus-5-5
2026-10-14 18:26:04 +02:00
9 changed files with 142 additions and 349 deletions
-4
View File
@@ -230,10 +230,6 @@ What happens at each limit:
keeps running.
- Handler queues: each of the four handler queues holds at most 20,000 messages.
When a queue fills, the streamer drops messages instead of blocking.
- Handler batches: while the AS, peer or prefix handler writes a batch to the
database, the updates that arrive collect in its next batch, which has no size
limit. A database that stays slower than the feed grows memory instead of
dropping updates.
With `DEBUG=routewatch` the daemon logs a `System stats` line every 60 seconds
with the goroutine count and Go memory figures.
+27 -49
View File
@@ -32,15 +32,12 @@ type ASHandler struct {
db database.Store
logger *logger.Logger
// Batching. mu guards batch only: the flush goroutine takes the batch
// under mu and writes it after releasing mu, so HandleMessage never
// waits for a database write.
mu sync.Mutex
batch []asnOp
batchFullCh chan struct{} // wakes the flush goroutine when batch is full
lastFlush time.Time // used only by the flush goroutine
stopCh chan struct{}
wg sync.WaitGroup
// Batching
mu sync.Mutex
batch []asnOp
lastFlush time.Time
stopCh chan struct{}
wg sync.WaitGroup
}
type asnOp struct {
@@ -55,12 +52,11 @@ type asnOp struct {
// background goroutine is terminated.
func NewASHandler(db database.Store, logger *logger.Logger) *ASHandler {
h := &ASHandler{
db: db,
logger: logger,
batch: make([]asnOp, 0, asnBatchSize),
batchFullCh: make(chan struct{}, 1),
lastFlush: time.Now(),
stopCh: make(chan struct{}),
db: db,
logger: logger,
batch: make([]asnOp, 0, asnBatchSize),
lastFlush: time.Now(),
stopCh: make(chan struct{}),
}
// Start the flush timer goroutine
@@ -89,8 +85,8 @@ func (h *ASHandler) QueueCapacity() int {
// HandleMessage processes a RIS Live BGP message by extracting all ASNs from
// the AS path and queuing them for batch insertion into the database. The
// origin ASN (last element in the path) and all transit ASNs are recorded
// with their associated timestamps. When the batch reaches the configured size
// threshold, the flush goroutine is woken to write it.
// with their associated timestamps. The batch is automatically flushed when
// it reaches the configured size threshold.
func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) {
// Use the pre-parsed timestamp
timestamp := msg.ParsedTimestamp
@@ -122,18 +118,13 @@ func (h *ASHandler) HandleMessage(msg *ristypes.RISMessage) {
}
}
// A full batch wakes the flush goroutine. If it is writing, the wake-up
// waits in batchFullCh and the batch keeps growing until the write ends.
// Check if we need to flush
if len(h.batch) >= asnBatchSize {
select {
case h.batchFullCh <- struct{}{}:
default: // already woken
}
h.flushBatchLocked()
}
}
// flushLoop runs in a goroutine, the only one that writes the batch: it
// flushes when the batch is full, periodically, and once more on Stop.
// flushLoop runs in a goroutine and periodically flushes batches
func (h *ASHandler) flushLoop() {
defer h.wg.Done()
ticker := time.NewTicker(asnBatchTimeout)
@@ -142,46 +133,31 @@ func (h *ASHandler) flushLoop() {
for {
select {
case <-ticker.C:
h.mu.Lock()
if time.Since(h.lastFlush) >= asnBatchTimeout {
h.flushBatch()
h.flushBatchLocked()
}
case <-h.batchFullCh:
h.flushBatch()
h.mu.Unlock()
case <-h.stopCh:
// Final flush
h.flushBatch()
h.mu.Lock()
h.flushBatchLocked()
h.mu.Unlock()
return
}
}
}
// takeBatch returns the pending operations and leaves an empty batch in their
// place for HandleMessage to fill.
func (h *ASHandler) takeBatch() []asnOp {
h.mu.Lock()
defer h.mu.Unlock()
// flushBatchLocked flushes the ASN batch to the database (must be called with mutex held)
func (h *ASHandler) flushBatchLocked() {
if len(h.batch) == 0 {
return nil
}
batch := h.batch
h.batch = make([]asnOp, 0, asnBatchSize)
return batch
}
// flushBatch takes the pending batch and writes it to the database, without
// holding the mutex during the write.
func (h *ASHandler) flushBatch() {
batch := h.takeBatch()
if len(batch) == 0 {
return
}
// Process ASNs first (deduped)
asnMap := make(map[int]time.Time)
for _, op := range batch {
for _, op := range h.batch {
if existing, ok := asnMap[op.number]; !ok || op.timestamp.After(existing) {
asnMap[op.number] = op.timestamp
}
@@ -192,6 +168,8 @@ func (h *ASHandler) flushBatch() {
h.logger.Error("Failed to process ASN batch", "error", err, "count", len(asnMap))
}
// Clear batch
h.batch = h.batch[:0]
h.lastFlush = time.Now()
}
-192
View File
@@ -1,192 +0,0 @@
package routewatch
import (
"slices"
"sync"
"testing"
"time"
"git.eeqj.de/sneak/routewatch/internal/database"
"git.eeqj.de/sneak/routewatch/internal/logger"
"git.eeqj.de/sneak/routewatch/internal/ristypes"
)
// handleMessageTimeout is how long a test waits for HandleMessage to return,
// or for a write to start, before it fails.
const handleMessageTimeout = 2 * time.Second
// blockingStore is a mockStore whose batch writes for the AS, peer and prefix
// handlers wait until the test closes release. writeStarted is closed when the
// first of them starts. It records what each write was given.
type blockingStore struct {
*mockStore
release chan struct{}
writeStarted chan struct{}
startOnce sync.Once
mu sync.Mutex
prefixes map[string]bool
asns map[int]bool
peers map[string]bool
}
func newBlockingStore() *blockingStore {
return &blockingStore{
mockStore: newMockStore(),
release: make(chan struct{}),
writeStarted: make(chan struct{}),
prefixes: make(map[string]bool),
asns: make(map[int]bool),
peers: make(map[string]bool),
}
}
func (s *blockingStore) waitForRelease() {
s.startOnce.Do(func() { close(s.writeStarted) })
<-s.release
}
func (s *blockingStore) UpsertLiveRouteBatch(routes []*database.LiveRoute) error {
s.waitForRelease()
s.mu.Lock()
defer s.mu.Unlock()
for _, route := range routes {
s.prefixes[route.Prefix] = true
}
return nil
}
func (s *blockingStore) GetOrCreateASNBatch(asns map[int]time.Time) error {
s.waitForRelease()
s.mu.Lock()
defer s.mu.Unlock()
for asn := range asns {
s.asns[asn] = true
}
return nil
}
func (s *blockingStore) UpdatePeerBatch(peers map[string]database.PeerUpdate) error {
s.waitForRelease()
s.mu.Lock()
defer s.mu.Unlock()
for peerIP := range peers {
s.peers[peerIP] = true
}
return nil
}
// returnsInTime reports whether f returns within handleMessageTimeout.
func returnsInTime(f func()) bool {
done := make(chan struct{})
go func() {
f()
close(done)
}()
select {
case <-done:
return true
case <-time.After(handleMessageTimeout):
return false
}
}
// handleWhileAWriteIsBlocked hands h the messages in fill, which fill its
// batch so that the handler writes it to store, waits until the write starts,
// and hands h the message extra while store holds the write. HandleMessage
// must return each time. Then it lets the writes finish and stops h, which
// writes what it holds.
func handleWhileAWriteIsBlocked(
t *testing.T,
store *blockingStore,
h interface {
HandleMessage(*ristypes.RISMessage)
Stop()
},
fill []*ristypes.RISMessage,
extra *ristypes.RISMessage,
) {
t.Helper()
defer h.Stop()
defer close(store.release)
if !returnsInTime(func() {
for _, msg := range fill {
h.HandleMessage(msg)
}
}) {
t.Fatal("HandleMessage did not return after filling the batch: it waits for the database write")
}
select {
case <-store.writeStarted:
case <-time.After(handleMessageTimeout):
t.Fatal("the handler did not write its full batch")
}
if !returnsInTime(func() { h.HandleMessage(extra) }) {
t.Fatal("HandleMessage did not return while a database write was blocked")
}
}
func TestPrefixHandlerHandlesMessagesWhileAWriteIsBlocked(t *testing.T) {
const (
fillPrefix = "192.0.2.0/24"
extraPrefix = "198.51.100.0/24"
)
announce := func(prefixes []string) *ristypes.RISMessage {
return &ristypes.RISMessage{
Peer: testPeerIP,
Path: ristypes.ASPath{testASNA},
Announcements: []ristypes.RISAnnouncement{{NextHop: testPeerIP, Prefixes: prefixes}},
}
}
store := newBlockingStore()
h := NewPrefixHandler(store, logger.New())
handleWhileAWriteIsBlocked(t, store, h,
[]*ristypes.RISMessage{announce(slices.Repeat([]string{fillPrefix}, prefixBatchSize))},
announce([]string{extraPrefix}))
store.mu.Lock()
defer store.mu.Unlock()
if !store.prefixes[extraPrefix] {
t.Errorf("Stop did not write %s, handled while a write was blocked", extraPrefix)
}
}
func TestASHandlerHandlesMessagesWhileAWriteIsBlocked(t *testing.T) {
store := newBlockingStore()
h := NewASHandler(store, logger.New())
handleWhileAWriteIsBlocked(t, store, h,
[]*ristypes.RISMessage{{Path: slices.Repeat(ristypes.ASPath{testASNA}, asnBatchSize)}},
&ristypes.RISMessage{Path: ristypes.ASPath{testASNB}})
store.mu.Lock()
defer store.mu.Unlock()
if !store.asns[testASNB] {
t.Errorf("Stop did not write AS%d, handled while a write was blocked", testASNB)
}
}
func TestPeerHandlerHandlesMessagesWhileAWriteIsBlocked(t *testing.T) {
const otherPeerIP = "2001:db8:ffff::2"
store := newBlockingStore()
h := NewPeerHandler(store, logger.New())
handleWhileAWriteIsBlocked(t, store, h,
slices.Repeat([]*ristypes.RISMessage{{Peer: testPeerIP}}, peerBatchSize),
&ristypes.RISMessage{Peer: otherPeerIP})
store.mu.Lock()
defer store.mu.Unlock()
if !store.peers[otherPeerIP] {
t.Errorf("Stop did not write peer %s, handled while a write was blocked", otherPeerIP)
}
}
+5
View File
@@ -20,6 +20,8 @@ const (
debugInterval = 60 * time.Second
// bytesPerMB is bytes per megabyte
bytesPerMB = 1024 * 1024
// failureExitCode is the exit status when RouteWatch stops on an error
failureExitCode = 1
)
// logDebugStats logs goroutine count and memory usage
@@ -83,6 +85,9 @@ func CLIEntry() {
go func() {
if err := rw.Run(ctx); err != nil {
logger.Error("RouteWatch error", "error", err)
if err := shutdowner.Shutdown(fx.ExitCode(failureExitCode)); err != nil {
logger.Error("Failed to shutdown gracefully", "error", err)
}
}
}()
+27 -49
View File
@@ -35,15 +35,12 @@ type PeerHandler struct {
db database.Store
logger *logger.Logger
// Batching. mu guards peerBatch only: the flush goroutine takes the batch
// under mu and writes it after releasing mu, so HandleMessage never
// waits for a database write.
mu sync.Mutex
peerBatch []peerUpdate
batchFullCh chan struct{} // wakes the flush goroutine when peerBatch is full
lastFlush time.Time // used only by the flush goroutine
stopCh chan struct{}
wg sync.WaitGroup
// Batching
mu sync.Mutex
peerBatch []peerUpdate
lastFlush time.Time
stopCh chan struct{}
wg sync.WaitGroup
}
type peerUpdate struct {
@@ -59,12 +56,11 @@ type peerUpdate struct {
// should be stopped by calling Stop when it is no longer needed.
func NewPeerHandler(db database.Store, logger *logger.Logger) *PeerHandler {
h := &PeerHandler{
db: db,
logger: logger,
peerBatch: make([]peerUpdate, 0, peerBatchSize),
batchFullCh: make(chan struct{}, 1),
lastFlush: time.Now(),
stopCh: make(chan struct{}),
db: db,
logger: logger,
peerBatch: make([]peerUpdate, 0, peerBatchSize),
lastFlush: time.Now(),
stopCh: make(chan struct{}),
}
// Start the flush timer goroutine
@@ -91,8 +87,8 @@ func (h *PeerHandler) QueueCapacity() int {
// HandleMessage processes a RIS message to track peer information.
// It extracts the peer IP address and ASN from the message and adds
// the update to an internal batch. The flush goroutine writes the batch to the
// database when it reaches peerBatchSize or the batch timeout expires.
// the update to an internal batch. When the batch reaches peerBatchSize
// or the batch timeout expires, the batch is flushed to the database.
func (h *PeerHandler) HandleMessage(msg *ristypes.RISMessage) {
// Parse peer ASN from string
peerASN := 0
@@ -113,18 +109,13 @@ func (h *PeerHandler) HandleMessage(msg *ristypes.RISMessage) {
timestamp: msg.ParsedTimestamp,
})
// 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.
// Check if we need to flush
if len(h.peerBatch) >= peerBatchSize {
select {
case h.batchFullCh <- struct{}{}:
default: // already woken
}
h.flushBatchLocked()
}
}
// flushLoop runs in a goroutine, the only one that writes the batch: it
// flushes when the batch is full, periodically, and once more on Stop.
// flushLoop runs in a goroutine and periodically flushes batches
func (h *PeerHandler) flushLoop() {
defer h.wg.Done()
ticker := time.NewTicker(peerBatchTimeout)
@@ -133,46 +124,31 @@ func (h *PeerHandler) flushLoop() {
for {
select {
case <-ticker.C:
h.mu.Lock()
if time.Since(h.lastFlush) >= peerBatchTimeout {
h.flushBatch()
h.flushBatchLocked()
}
case <-h.batchFullCh:
h.flushBatch()
h.mu.Unlock()
case <-h.stopCh:
// Final flush
h.flushBatch()
h.mu.Lock()
h.flushBatchLocked()
h.mu.Unlock()
return
}
}
}
// takeBatch returns the pending updates and leaves an empty batch in their
// place for HandleMessage to fill.
func (h *PeerHandler) takeBatch() []peerUpdate {
h.mu.Lock()
defer h.mu.Unlock()
// flushBatchLocked flushes the peer batch to the database (must be called with mutex held)
func (h *PeerHandler) flushBatchLocked() {
if len(h.peerBatch) == 0 {
return nil
}
batch := h.peerBatch
h.peerBatch = make([]peerUpdate, 0, peerBatchSize)
return batch
}
// flushBatch takes the pending batch and writes it to the database, without
// holding the mutex during the write.
func (h *PeerHandler) flushBatch() {
batch := h.takeBatch()
if len(batch) == 0 {
return
}
// Deduplicate by peer IP, keeping the latest update for each peer
peerMap := make(map[string]peerUpdate)
for _, update := range batch {
for _, update := range h.peerBatch {
if existing, ok := peerMap[update.peerIP]; !ok || update.timestamp.After(existing.timestamp) {
peerMap[update.peerIP] = update
}
@@ -194,6 +170,8 @@ func (h *PeerHandler) flushBatch() {
h.logger.Error("Failed to process peer batch", "error", err, "count", len(dbPeerMap))
}
// Clear batch
h.peerBatch = h.peerBatch[:0]
h.lastFlush = time.Now()
}
+26 -48
View File
@@ -40,15 +40,12 @@ type PrefixHandler struct {
logger *logger.Logger
metrics *metrics.Tracker
// Batching. mu guards batch only: the flush goroutine takes the batch
// under mu and writes it after releasing mu, so HandleMessage never
// waits for a database write.
mu sync.Mutex
batch []prefixUpdate
batchFullCh chan struct{} // wakes the flush goroutine when batch is full
lastFlush time.Time // used only by the flush goroutine
stopCh chan struct{}
wg sync.WaitGroup
// Batching
mu sync.Mutex
batch []prefixUpdate
lastFlush time.Time
stopCh chan struct{}
wg sync.WaitGroup
}
type prefixUpdate struct {
@@ -63,12 +60,11 @@ type prefixUpdate struct {
// NewPrefixHandler creates a new batched prefix tracking handler
func NewPrefixHandler(db database.Store, logger *logger.Logger) *PrefixHandler {
h := &PrefixHandler{
db: db,
logger: logger,
batch: make([]prefixUpdate, 0, prefixBatchSize),
batchFullCh: make(chan struct{}, 1),
lastFlush: time.Now(),
stopCh: make(chan struct{}),
db: db,
logger: logger,
batch: make([]prefixUpdate, 0, prefixBatchSize),
lastFlush: time.Now(),
stopCh: make(chan struct{}),
}
// Start the flush timer goroutine
@@ -144,18 +140,13 @@ func (h *PrefixHandler) HandleMessage(msg *ristypes.RISMessage) {
}
}
// A full batch wakes the flush goroutine. If it is writing, the wake-up
// waits in batchFullCh and the batch keeps growing until the write ends.
// Check if we need to flush
if len(h.batch) >= prefixBatchSize {
select {
case h.batchFullCh <- struct{}{}:
default: // already woken
}
h.flushBatchLocked()
}
}
// flushLoop runs in a goroutine, the only one that writes the batch: it
// flushes when the batch is full, periodically, and once more on Stop.
// flushLoop runs in a goroutine and periodically flushes batches
func (h *PrefixHandler) flushLoop() {
defer h.wg.Done()
ticker := time.NewTicker(prefixBatchTimeout)
@@ -164,45 +155,30 @@ func (h *PrefixHandler) flushLoop() {
for {
select {
case <-ticker.C:
h.mu.Lock()
if time.Since(h.lastFlush) >= prefixBatchTimeout {
h.flushBatch()
h.flushBatchLocked()
}
case <-h.batchFullCh:
h.flushBatch()
h.mu.Unlock()
case <-h.stopCh:
// Final flush
h.flushBatch()
h.mu.Lock()
h.flushBatchLocked()
h.mu.Unlock()
return
}
}
}
// takeBatch returns the pending updates and leaves an empty batch in their
// place for HandleMessage to fill.
func (h *PrefixHandler) takeBatch() []prefixUpdate {
h.mu.Lock()
defer h.mu.Unlock()
// flushBatchLocked flushes the prefix batch to the database (must be called with mutex held)
func (h *PrefixHandler) flushBatchLocked() {
if len(h.batch) == 0 {
return nil
}
batch := h.batch
h.batch = make([]prefixUpdate, 0, prefixBatchSize)
return batch
}
// flushBatch takes the pending batch and writes it to the database, without
// holding the mutex during the write.
func (h *PrefixHandler) flushBatch() {
batch := h.takeBatch()
if len(batch) == 0 {
return
}
startTime := time.Now()
batchSize := len(batch)
batchSize := len(h.batch)
// For each prefix and peer, keep only the last update the feed delivered.
// Updates from different peers for the same prefix are all kept. Arrival
@@ -210,7 +186,7 @@ func (h *PrefixHandler) flushBatch() {
// updates within one second carry the same one.
type prefixAndPeer struct{ prefix, peer string }
lastUpdates := make(map[prefixAndPeer]prefixUpdate)
for _, update := range batch {
for _, update := range h.batch {
lastUpdates[prefixAndPeer{update.prefix, update.peer}] = update
}
@@ -285,6 +261,8 @@ func (h *PrefixHandler) flushBatch() {
"duration_ms", elapsed.Milliseconds(),
)
// Clear batch
h.batch = h.batch[:0]
h.lastFlush = time.Now()
}
+10 -3
View File
@@ -30,6 +30,11 @@ func TestPrefixHandlerStoresPrefixesTheIPLookupFinds(t *testing.T) {
// Built without NewPrefixHandler's flush timer, so the test flushes itself.
h := &PrefixHandler{db: db, logger: logger.New()}
flush := func() {
h.mu.Lock()
defer h.mu.Unlock()
h.flushBatchLocked()
}
ts := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC)
h.HandleMessage(&ristypes.RISMessage{
@@ -41,7 +46,7 @@ func TestPrefixHandlerStoresPrefixesTheIPLookupFinds(t *testing.T) {
Prefixes: []string{"2001:db8:1::/48", "192.0.2.0/24"},
}},
})
h.flushBatch()
flush()
for ip, want := range map[string]string{
"2001:db8:1::1": "2001:db8:1::/48",
@@ -61,7 +66,7 @@ func TestPrefixHandlerStoresPrefixesTheIPLookupFinds(t *testing.T) {
ParsedTimestamp: ts.Add(time.Minute),
Withdrawals: []string{"2001:db8:1:0:0:0:0:0/48", "192.0.2.0/24"},
})
h.flushBatch()
flush()
for _, ip := range []string{"2001:db8:1::1", "192.0.2.1"} {
if info, err := db.GetIPInfo(ip); !errors.Is(err, database.ErrNoRoute) {
@@ -159,7 +164,9 @@ func TestPrefixHandlerAppliesEachPeersLastUpdateInABatch(t *testing.T) {
for _, msg := range batch {
h.HandleMessage(msg)
}
h.flushBatch()
h.mu.Lock()
h.flushBatchLocked()
h.mu.Unlock()
}
ctx := context.Background()
+14 -4
View File
@@ -3,6 +3,8 @@ package server
import (
"context"
"fmt"
"net"
"net/http"
"strconv"
"time"
@@ -53,9 +55,12 @@ func New(db database.Store, streamer *streamer.Streamer, logger *logger.Logger,
return s
}
// Start starts the HTTP server
// Start listens on the configured port and serves HTTP in the background.
// It returns an error if it cannot listen, for example because the port is
// already in use.
func (s *Server) Start() error {
const (
network = "tcp"
readHeaderTimeout = 40 * time.Second
readTimeout = 60 * time.Second
writeTimeout = 60 * time.Second
@@ -73,10 +78,15 @@ func (s *Server) Start() error {
s.logger.Info("Starting HTTP server", "port", s.port, "addr", s.srv.Addr)
// Start in goroutine but log when actually listening
listener, err := net.Listen(network, s.srv.Addr)
if err != nil {
return fmt.Errorf("starting HTTP server: %w", err)
}
s.logger.Info("HTTP server listening", "addr", listener.Addr().String())
go func() {
s.logger.Info("HTTP server listening", "addr", s.srv.Addr)
if err := s.srv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
if err := s.srv.Serve(listener); err != nil && err != http.ErrServerClosed {
s.logger.Error("HTTP server error", "error", err)
}
}()
+33
View File
@@ -0,0 +1,33 @@
package server
import (
"context"
"net"
"testing"
"git.eeqj.de/sneak/routewatch/internal/config"
"git.eeqj.de/sneak/routewatch/internal/logger"
"git.eeqj.de/sneak/routewatch/internal/metrics"
"git.eeqj.de/sneak/routewatch/internal/streamer"
)
// TestStartFailsWhenPortIsHeld holds a port with a listener of its own and
// checks that Start on that port returns an error. Before the fix Start
// listened in a goroutine, only logged the failure and returned nil, so the
// daemon kept running without its web server.
func TestStartFailsWhenPortIsHeld(t *testing.T) {
held, err := net.Listen("tcp", ":0")
if err != nil {
t.Fatalf("failed to open the test listener: %v", err)
}
defer func() { _ = held.Close() }()
port := held.Addr().(*net.TCPAddr).Port
log := logger.New()
s := New(nil, streamer.New(log, metrics.New()), log, &config.Config{Port: port})
defer func() { _ = s.Stop(context.Background()) }()
if err := s.Start(); err == nil {
t.Fatalf("Start returned nil while port %d was held by another listener", port)
}
}