test(#1598): red — relay participation must refresh nodes.last_seen

Pins the behaviour that has been silently broken since #1283/#1289.

The server's touchRelayLastSeen (cmd/server/store.go) calls
TouchNodeLastSeen, which issues `UPDATE nodes SET last_seen`. The server
opens SQLite with mode=ro (cmd/server/db.go:54), so that UPDATE fails with
"attempt to write a readonly database" on every call. The call site
discards the error:

    if err := s.db.TouchNodeLastSeen(pk, ts); err == nil {
            s.lastSeenTouched[pk] = now
    }

Net effect: nodes.last_seen tracks ADVERT arrivals only. Relay
participation has never refreshed it, so infra nodes on long advert
cadences look stale while actively carrying traffic.

Verified against a production store (live.saarmesh.de, 1388 nodes): 1362
have last_seen within one minute of their own most recent ADVERT.

Five tests, all against the ingestor (the writer-owning process, which
already resolves hop prefixes to full pubkeys for observations.resolved_path
since #1547):

  - AdvancesLastSeen      — the core regression
  - NeverGoesBackwards    — monotonic guard for out-of-order ingest
  - Debounces             — write amplification guard on the hot path
  - IgnoresEmptyAndUnknown— unresolved hops must not create rows
  - MalformedTimestamp    — unparsable rxTime is a no-op

TouchRelayNodes is stubbed as a no-op and Stats.RelayTouches added so the
suite compiles and reds on assertions rather than on a build error
(AGENTS.md § Test-First red-commit bar).

Red output:
  --- FAIL: TestTouchRelayNodes_AdvancesLastSeen
      last_seen = "2026-07-01T00:00:00Z", want "2026-07-10T12:00:00Z"
      RelayTouches = 0, want 1
  --- FAIL: TestTouchRelayNodes_Debounces
      RelayTouches = 0, want 1 (second touch should be debounced)

Refs #1598, #1611
Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
SaarMesh-Bot
2026-07-19 10:16:54 +00:00
parent a06ac8aceb
commit 573bbde30b
2 changed files with 154 additions and 0 deletions
+8
View File
@@ -28,6 +28,9 @@ type DBStats struct {
ObserverUpserts atomic.Int64
WriteErrors atomic.Int64
SignatureDrops atomic.Int64
// RelayTouches counts nodes.last_seen refreshes driven by relay
// participation rather than an ADVERT (#1598).
RelayTouches atomic.Int64
// WALCommits tracks every successful tx.Commit() that may have flushed
// WAL pages.
WALCommits atomic.Int64
@@ -1461,6 +1464,11 @@ func (s *Store) LogStats() {
)
}
// TouchRelayNodes refreshes nodes.last_seen for nodes observed as relay
// hops. STUB — implementation follows in the green commit; see
// relay_touch_test.go for the specified behaviour.
func (s *Store) TouchRelayNodes(pubkeys []string, rxTime string) {}
// MoveStaleNodes moves nodes not seen in nodeDays to the inactive_nodes table.
// Returns the number of nodes moved.
func (s *Store) MoveStaleNodes(nodeDays int) (int64, error) {
+146
View File
@@ -0,0 +1,146 @@
package main
import (
"testing"
"time"
)
// Issue #1598 / #1611 — the relay-aware last_seen touch.
//
// History: the server had touchRelayLastSeen (cmd/server/store.go), which
// called TouchNodeLastSeen → UPDATE nodes SET last_seen. Since #1283/#1289
// the server opens SQLite with mode=ro, so that UPDATE has failed with
// "attempt to write a readonly database" on every call, and the error was
// discarded at the call site. Net effect: nodes.last_seen has tracked
// ADVERT arrivals only, and relay participation has never refreshed it.
//
// The writer lives in the ingestor, which since #1547 already resolves hop
// prefixes to full pubkeys for observations.resolved_path. These tests pin
// the touch to that existing resolution point.
// helper: seed a node so the prefix index can resolve a hop to it.
func seedRelayNode(t *testing.T, s *Store, pubkey, name, lastSeen string) {
t.Helper()
if err := s.UpsertNode(pubkey, name, "repeater", nil, nil, lastSeen); err != nil {
t.Fatalf("seed node %s: %v", name, err)
}
}
func nodeLastSeen(t *testing.T, s *Store, pubkey string) string {
t.Helper()
var ls string
if err := s.db.QueryRow(`SELECT COALESCE(last_seen,'') FROM nodes WHERE public_key=?`, pubkey).Scan(&ls); err != nil {
t.Fatalf("read last_seen for %s: %v", pubkey, err)
}
return ls
}
// TestTouchRelayNodes_AdvancesLastSeen is the core regression: a node that
// appears as a resolved relay hop must have its last_seen advanced, even
// though it sent no ADVERT of its own.
func TestTouchRelayNodes_AdvancesLastSeen(t *testing.T) {
store := newTestStore(t)
const relay = "aa11223344556677889900aabbccddeeff00112233445566778899aabbccddee"
seedRelayNode(t, store, relay, "RelayOnly", "2026-07-01T00:00:00Z")
rxTime := "2026-07-10T12:00:00Z"
store.TouchRelayNodes([]string{relay}, rxTime)
got := nodeLastSeen(t, store, relay)
if got != rxTime {
t.Errorf("last_seen = %q, want %q — relay participation did not refresh the node", got, rxTime)
}
if n := store.Stats.RelayTouches.Load(); n != 1 {
t.Errorf("RelayTouches = %d, want 1", n)
}
}
// TestTouchRelayNodes_NeverGoesBackwards guards the monotonic invariant.
// Out-of-order ingest (a late observation with an older rxTime) must not
// rewind a node's last_seen.
func TestTouchRelayNodes_NeverGoesBackwards(t *testing.T) {
store := newTestStore(t)
const relay = "bb11223344556677889900aabbccddeeff00112233445566778899aabbccddee"
seedRelayNode(t, store, relay, "Backbone", "2026-07-10T12:00:00Z")
store.TouchRelayNodes([]string{relay}, "2026-07-09T00:00:00Z")
if got := nodeLastSeen(t, store, relay); got != "2026-07-10T12:00:00Z" {
t.Errorf("last_seen went backwards: got %q, want 2026-07-10T12:00:00Z", got)
}
}
// TestTouchRelayNodes_Debounces pins the write-amplification guard. The
// ingest path is hot; a backbone repeater appears in thousands of paths per
// hour and must not produce one UPDATE per observation.
func TestTouchRelayNodes_Debounces(t *testing.T) {
store := newTestStore(t)
const relay = "cc11223344556677889900aabbccddeeff00112233445566778899aabbccddee"
seedRelayNode(t, store, relay, "Chatty", "2026-07-01T00:00:00Z")
base := time.Date(2026, 7, 10, 12, 0, 0, 0, time.UTC)
store.TouchRelayNodes([]string{relay}, base.Format(time.RFC3339))
// Second hit two minutes later — inside the debounce window, no write.
store.TouchRelayNodes([]string{relay}, base.Add(2*time.Minute).Format(time.RFC3339))
if n := store.Stats.RelayTouches.Load(); n != 1 {
t.Errorf("RelayTouches = %d, want 1 (second touch should be debounced)", n)
}
if got := nodeLastSeen(t, store, relay); got != base.Format(time.RFC3339) {
t.Errorf("last_seen = %q, want %q", got, base.Format(time.RFC3339))
}
// Past the debounce window the write goes through again.
later := base.Add(6 * time.Minute)
store.TouchRelayNodes([]string{relay}, later.Format(time.RFC3339))
if n := store.Stats.RelayTouches.Load(); n != 2 {
t.Errorf("RelayTouches = %d, want 2 after debounce window elapsed", n)
}
if got := nodeLastSeen(t, store, relay); got != later.Format(time.RFC3339) {
t.Errorf("last_seen = %q, want %q", got, later.Format(time.RFC3339))
}
}
// TestTouchRelayNodes_IgnoresEmptyAndUnknown covers the unresolved-hop case:
// resolvePathWithContext yields nil for ambiguous or unknown prefixes, and
// unknown pubkeys must not create rows.
func TestTouchRelayNodes_IgnoresEmptyAndUnknown(t *testing.T) {
store := newTestStore(t)
store.TouchRelayNodes(nil, "2026-07-10T12:00:00Z")
store.TouchRelayNodes([]string{}, "2026-07-10T12:00:00Z")
store.TouchRelayNodes([]string{""}, "2026-07-10T12:00:00Z")
store.TouchRelayNodes([]string{"ff99887766554433221100ffeeddccbbaa99887766554433221100ffeeddccbb"}, "2026-07-10T12:00:00Z")
var count int
if err := store.db.QueryRow(`SELECT COUNT(*) FROM nodes`).Scan(&count); err != nil {
t.Fatal(err)
}
if count != 0 {
t.Errorf("nodes count = %d, want 0 — touch must never insert rows", count)
}
if n := store.Stats.RelayTouches.Load(); n != 0 {
t.Errorf("RelayTouches = %d, want 0", n)
}
}
// TestTouchRelayNodes_MalformedTimestamp: rxTime that does not parse must be
// a no-op rather als writing a garbage timestamp into the node directory.
func TestTouchRelayNodes_MalformedTimestamp(t *testing.T) {
store := newTestStore(t)
const relay = "dd11223344556677889900aabbccddeeff00112233445566778899aabbccddee"
seedRelayNode(t, store, relay, "Fine", "2026-07-01T00:00:00Z")
store.TouchRelayNodes([]string{relay}, "not-a-timestamp")
if got := nodeLastSeen(t, store, relay); got != "2026-07-01T00:00:00Z" {
t.Errorf("last_seen = %q, want it unchanged on malformed rxTime", got)
}
if n := store.Stats.RelayTouches.Load(); n != 0 {
t.Errorf("RelayTouches = %d, want 0", n)
}
}