Skip to content

Commit cb9ce2d

Browse files
committed
v1.9.1-rc2
Release candidate 2. The headline fix is the relay-flag flap that caused "pings work for a minute then dial timeout for minutes" against NAT'd peers (most commonly GCP service agents). ### Relay-flag flap (the "ping dies after a minute" bug) clearRelayOnDirectLocked auto-flipped the relay flag back to direct after 3 non-beacon-sourced packets. In production, that "non-beacon" detection was unreliable: GCP NAT-port-rewrite of beacon-originated UDP, beacon-mesh forwards from a different IP, and stray punch/ICMP replies all looked non-beacon to the IP+port equality check. After the flip, writeFrame happily sent to the unreachable direct address and only the silent-detection 60 s later flipped back to relay — during which encrypted sends dropped and rekey rotated session keys faster than they could settle. Fixes: * pkg/daemon/tunnel.go: clearRelayOnDirectLocked auto-recovery disabled. Once a peer is on relay, only explicit operator action (SetRelayPeer(node, false)) clears the flag. * pkg/daemon/tunnel.go: handleAuthKeyExchange + handleKeyExchange now ALWAYS overwrite tm.peers[X] to the beacon and set+pin the relay flag when fromRelay=true, regardless of whether ensureTunnel pre-registered the peer with its registry-published direct address. The old "only if unknown" gate (issue #199) left relayPeers[X]=false for peers that ensureTunnel had pre-registered → writeFrame sent to unreachable direct addr → 60 s silent before flip. * pkg/daemon/tunnel.go: new relayPinned map. SetRelayPeerPinned() marks the relay flag as authoritative — registry relay_only=true, dial-time direct-failure switch, ICMP-unreachable threshold, and beacon-sourced key exchanges all pin. Pinned peers cannot be auto-cleared. Wired into the four call sites that flip to relay. ### Performance — pilotctl cold latency * pkg/daemon/ipc.go: hostname cache (60 s) on the resolve_hostname IPC handler. Persisted to ~/.pilot/hostname_cache.json so daemon restart starts warm. Async resolve prewarm after a successful lookup so the follow-up DialAddr skips the second registry round-trip. * pkg/daemon/policy_runner.go: fetchMembers exponential backoff (5 s → 10 s → ... → 5 min cap) so a doomed list_nodes no longer holds the regConn mutex every 5 s and starves co-tenant calls. * pkg/daemon/daemon.go: DialInitialRTO 1 s → 250 ms. Three direct retries now total ~1.75 s before relay flip (was ~7 s). * cmd/pilotctl/main.go: PILOTCTL_TRACE_TIME=1 env flag dumps per-step timings to stderr for latency debugging. Result: send-message 10–30 s → ~600 ms cold / ~170 ms warm. pilotctl ping list-agents holds for 10+ minutes; previous builds dropped after ~60–90 s. ### Other * pkg/daemon/tunnel.go: ErrPendingDropped sentinel. DialConnection no longer aborts when a SYN is queued during tunnel-handshake startup — falls through to its existing 6-retry loop instead. * cmd/pilotctl/main.go: classifyDaemonError() recognizes pending- queue and dial-timeout patterns and surfaces an actionable hint instead of generic "check ping" boilerplate. * cmd/pilotctl/main.go: pilotctl ping SetReadDeadline before the echo read so a relay-degraded peer reports timeout instead of hanging forever. * pkg/skillinject: config-file overlay support for skill paths.
1 parent 2f880f9 commit cb9ce2d

11 files changed

Lines changed: 546 additions & 104 deletions

File tree

CHANGELOG.md

Lines changed: 105 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,111 @@ Detailed per-release notes for tagged versions are published on the
99

1010
## [Unreleased]
1111

12+
## [1.9.1-rc2] - 2026-05-03
13+
14+
Release candidate 2. Builds on rc1 with three classes of fixes:
15+
16+
### Performance — cold pilotctl latency
17+
18+
- pilotctl `send-message` cold latency cut from 10–30 s to ~600 ms; warm
19+
to ~170 ms. Combination of:
20+
- Daemon-side hostname cache (60 s, persisted to
21+
`~/.pilot/hostname_cache.json`, reloaded at startup).
22+
- PolicyRunner `fetchMembers` exponential backoff so a doomed
23+
`list_nodes` no longer holds the regConn mutex every 5 s.
24+
- `DialInitialRTO` 1 s → 250 ms — three direct retries now total
25+
~1.75 s before relay flip (was ~7 s).
26+
- Background pre-warm of the registry resolve cache for trusted
27+
peers at daemon start.
28+
- Resolve prewarm runs in a goroutine after a successful
29+
`resolve_hostname` so the follow-up `DialAddr` skips the second
30+
registry round-trip.
31+
32+
### Reliability
33+
34+
- Beacon `--advertise-addr` flag — MIG instances behind a public DNAT
35+
now register the public ingress address instead of their internal
36+
VPC IP. Without this, `beacon_list` returned 10.x addresses that
37+
off-VPC clients couldn't reach (silent black-hole). Daemon-side
38+
filter (`filterUnreachable` in `beacon_select.go`) drops RFC1918 /
39+
loopback / link-local literals from discovered lists as a safety
40+
net.
41+
- `ErrPendingDropped` sentinel in `pkg/daemon/tunnel.go`.
42+
`DialConnection` no longer aborts when a SYN is queued during
43+
tunnel-handshake startup — falls through to its existing 6-retry
44+
loop instead. Eliminates the spurious "send SYN: pending queue
45+
full" failures users saw immediately after daemon restart.
46+
- `pilotctl ping` — added `SetReadDeadline` before the echo read so a
47+
relay-degraded peer reports timeout instead of hanging forever.
48+
- `pilotctl connections``PEERWIN` no longer renders as
49+
`17179869184.0 GB` for connections in `SYN_SENT`. Was a `int(-1)`
50+
`uint64` wrap in the formatter.
51+
52+
### CLI / docs
53+
54+
- 56 doc files corrected (formal `web/src/pages/docs/` + `plain/docs/`
55+
twins, plus 47 blog posts) — stale trust/discovery/pubsub/network-
56+
join/tag/install patterns updated to current command surface.
57+
- `pilotctl` friendlier hints: `classifyDaemonError` recognizes
58+
`pending queue full` and `dial timeout` patterns and surfaces an
59+
actionable message instead of generic "check ping" boilerplate.
60+
61+
### Fixed — relay-flag flap (the "ping works for a minute then dies" bug)
62+
63+
- `clearRelayOnDirectLocked` (the relay→direct auto-recovery heuristic)
64+
was unreliable: after 3 consecutive non-beacon-sourced packets it
65+
flipped the relay flag back to direct, the next outgoing packet went
66+
direct (against a peer genuinely behind NAT), and writeFrame's silent-
67+
detection took ~60 s to flip BACK to relay. During that window
68+
encrypted sends to a now-direct peer dropped, and rekey attempts
69+
rotated session keys faster than they settled — user-visible symptom
70+
was "ping works for the first burst, then dial timeout for minutes".
71+
Triggered in production by GCP NAT-port-rewrite of beacon-originated
72+
UDP replies (made beacon packets look non-beacon-sourced) and by
73+
beacon-mesh forwards that arrive from a different IP.
74+
- The auto-recovery is now disabled. Once a peer is on relay, only an
75+
explicit operator action (`SetRelayPeer(node, false)`) clears the
76+
flag. Recovery to direct will happen naturally on the next dial cycle.
77+
- `handleAuthKeyExchange` and `handleKeyExchange` now ALWAYS overwrite
78+
the peer's UDP entry to the beacon and set+pin the relay flag when
79+
`fromRelay=true`, regardless of whether `ensureTunnel` previously
80+
registered the peer with its registry-published direct address. The
81+
old "only if peer was unknown" gate (issue #199) was leaving the
82+
relay flag false for peers that ensureTunnel had pre-registered, so
83+
writeFrame would happily send to the (unreachable) direct address
84+
until silent-detection eventually flipped it.
85+
- New `relayPinned` map tracks "relay flag set by an authoritative
86+
signal" — registry's `relay_only=true`, dial-time direct-failure
87+
switch, ICMP-unreachable threshold, or beacon-sourced key exchange.
88+
Pinned peers cannot be auto-cleared.
89+
90+
### Performance — cold pilotctl latency
91+
92+
- pilotctl `send-message` cold latency cut from 10–30 s to ~600 ms; warm
93+
to ~170 ms. Combination of:
94+
- Daemon-side hostname cache (60 s, persisted to
95+
`~/.pilot/hostname_cache.json`, reloaded at startup).
96+
- PolicyRunner `fetchMembers` exponential backoff so a doomed
97+
`list_nodes` no longer holds the regConn mutex every 5 s.
98+
- `DialInitialRTO` 1 s → 250 ms — three direct retries now total
99+
~1.75 s before relay flip (was ~7 s).
100+
- Async pre-warm of the registry resolve cache after a successful
101+
`resolve_hostname` so the follow-up `DialAddr` skips the second
102+
registry round-trip.
103+
104+
### Reverted
105+
106+
- An earlier rc2-dev variant pre-warmed encrypted tunnels for trusted
107+
peers at daemon start by firing ECDH key exchanges in a 350 ms
108+
burst. Triggered a rekey thundering-herd: every prewarm call marked
109+
`pendingRekey`, the retransmit loop pounded all peers at once, and
110+
peers' replies were interpreted as fresh requests, rotating session
111+
keys faster than encrypted packets could decrypt. A second variant
112+
(resolve-cache-only prewarm) caused a NAT-punch wave that took
113+
~70 s to settle. Both reverted to lazy-on-first-use; the only
114+
prewarm that survives is the per-call resolve prewarm in the
115+
`resolve_hostname` IPC handler.
116+
12117
## [1.8.0] - 2026-04-20
13118

14119
## [1.7.2] - 2026-04-10

cmd/pilotctl/main.go

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4315,10 +4315,24 @@ func cmdPing(args []string) {
43154315
count := flagInt(flags, "count", 4)
43164316
timeout := flagDuration(flags, "timeout", 30*time.Second)
43174317

4318+
// Optional per-step timing trace. Set PILOTCTL_TRACE_TIME=1 to see
4319+
// where the latency goes (binary startup, IPC connect, hostname
4320+
// lookup, dial, echo). Helps when "ping feels slow before the
4321+
// first packet" — the answer is almost always step 3.
4322+
traceTime := os.Getenv("PILOTCTL_TRACE_TIME") != ""
4323+
t0 := time.Now()
4324+
tracef := func(label string) {
4325+
if traceTime {
4326+
fmt.Fprintf(os.Stderr, "TRACE %-22s %12.3fms\n", label, float64(time.Since(t0).Microseconds())/1000.0)
4327+
}
4328+
}
4329+
43184330
d := connectDriver()
4331+
tracef("connectDriver")
43194332
defer d.Close()
43204333

43214334
target, err := parseAddrOrHostname(d, pos[0])
4335+
tracef("parseAddrOrHostname")
43224336
if err != nil {
43234337
fatalCode("not_found", "%v", err)
43244338
}

pkg/daemon/daemon.go

Lines changed: 66 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -800,12 +800,36 @@ func (d *Daemon) Start() error {
800800
// hash-pick lands on a fresher beacon.
801801
go d.beaconRefreshLoop()
802802

803-
// 12b. Pre-warm encrypted tunnels for trusted peers so the first
804-
// `pilotctl send-message <peer>` after a daemon restart skips the
805-
// 2-RTT key-exchange + SYN/SYN-ACK and only pays the 1-RTT
806-
// SYN/SYN-ACK relay cost. Background; failures are harmless (the
807-
// dial path will redo whatever didn't stick).
808-
go d.prewarmTrustedTunnels()
803+
// 12b. Earlier rc2-dev iterations pre-warmed trusted peers at
804+
// startup. Two variants were tried and both made things worse:
805+
//
806+
// (1) sendKeyExchangeToNode for each peer → rekey storm. Every
807+
// call marked pendingRekey; the retransmit loop pounded all
808+
// peers simultaneously; each peer's reply was interpreted as
809+
// a fresh key-exchange request that rotated session keys
810+
// mid-flight. Pings worked for a few seconds then dial
811+
// timed out for minutes.
812+
//
813+
// (2) ensureTunnel only (no key exchange) → NAT-punch wave.
814+
// ensureTunnel still issues a punch via beacon for non-
815+
// relay-only peers, and the dial path that owns the punch
816+
// takes 7-15s per peer to time out and flip to relay. With
817+
// 7 peers in a 1.4s burst, the daemon was busy doing
818+
// dial-fail-over for ~70s after start. User pings during
819+
// that window collided with the prewarm activity.
820+
//
821+
// Neither variant survives contact with a fleet that has many
822+
// trusted peers. Lazy-on-first-use is the right behavior: pay the
823+
// 600ms cold cost on the first send-message and let warm cache
824+
// handle everything after.
825+
//
826+
// Latency wins kept (independent of prewarm):
827+
// - DialInitialRTO 1s → 250ms
828+
// - hostname cache (in-memory + disk-persisted)
829+
// - fetchMembers exponential backoff
830+
// - resolve cache pre-warm via the resolve_hostname IPC handler
831+
// (warms ONLY the peer the user just asked about, not the
832+
// entire trust list)
809833

810834
// 13. Trusted-agents fetcher: hourly refresh of the auto-accept
811835
// list from GitHub. Embedded blob in the binary is the bootstrap.
@@ -2509,10 +2533,17 @@ func (d *Daemon) dialConnectionLocked(ctx context.Context, dstAddr protocol.Addr
25092533
case <-timer.C:
25102534
retries++
25112535

2512-
// Switch to relay mode after direct retries exhaust
2536+
// Switch to relay mode after direct retries exhaust. Pin the
2537+
// relay flag so clearRelayOnDirectLocked won't bounce us back
2538+
// to direct on a stray non-beacon-sourced packet (NAT-port-
2539+
// rewrite of beacon replies, ICMP-unreachable from the
2540+
// rendezvous, beacon mesh forwarding from a different IP).
2541+
// The peer just demonstrated direct doesn't work — observation
2542+
// of one or two seemingly-direct packets shouldn't override
2543+
// that empirical signal.
25132544
if retries == directRetries && d.config.BeaconAddr != "" && !relayActive {
25142545
slog.Info("direct dial timed out, switching to relay", "node_id", dstAddr.Node)
2515-
d.tunnels.SetRelayPeer(dstAddr.Node, true)
2546+
d.tunnels.SetRelayPeerPinned(dstAddr.Node, true)
25162547
relayActive = true
25172548
rto = DialInitialRTO // reset backoff for relay phase
25182549
}
@@ -3272,28 +3303,26 @@ func (d *Daemon) cacheResolve(nodeID uint32, resp map[string]interface{}) {
32723303
d.resolveCacheMu.Unlock()
32733304
}
32743305

3275-
// prewarmTrustedTunnels iterates trusted peers and fires a key_exchange
3276-
// at each one so the encrypted tunnel is established BEFORE the user's
3277-
// first send-message. Without this, the first dial pays:
3278-
//
3279-
// 1 RTT registry resolve_node (~150ms)
3280-
// 1 RTT ECDH key exchange (~170ms via relay)
3281-
// 1 RTT SYN / SYN-ACK (~170ms via relay)
3282-
//
3283-
// = ~500ms cold. With prewarm, only the SYN/SYN-ACK round trip remains
3284-
// (~170ms), because both the resolve cache and the encrypted tunnel
3285-
// are already warm.
3306+
// prewarmTrustedResolves iterates trusted peers and warms the registry
3307+
// resolve cache for each. After this, ensureTunnel() on the dial path
3308+
// hits the in-memory cache instead of paying a registry round-trip.
32863309
//
3287-
// Spaced out (50ms between peers) so that 50 trusted peers don't all
3288-
// fire key_exchange at the same beacon at once. The beacon's per-peer
3289-
// reflection queue can absorb bursts but smoothing the registration
3290-
// reduces tail latency for everyone.
3291-
func (d *Daemon) prewarmTrustedTunnels() {
3310+
// Does NOT fire ECDH key exchanges. An earlier version did, and the
3311+
// ~7-trusted-peer fleet observed here triggered a feedback storm:
3312+
// every sendKeyExchangeToNode marked the peer pendingRekey, the
3313+
// retransmit loop fired against ~7 peers simultaneously, and each
3314+
// peer's reply was interpreted by our handler as a fresh key-exchange
3315+
// request that rotated session keys mid-flight. Resulting symptom:
3316+
// pings worked for 5-10 seconds after restart, then dial timed out
3317+
// for minutes as session keys rotated faster than encrypted packets
3318+
// could decrypt. The encryption layer is intentionally left for the
3319+
// first real dial; we just want the resolve cache warm.
3320+
func (d *Daemon) prewarmTrustedResolves() {
32923321
if d.handshakes == nil {
32933322
return
32943323
}
32953324
// Brief delay so registration + beacon-refresh have settled before
3296-
// we start hammering the registry with resolves.
3325+
// we hit the registry.
32973326
select {
32983327
case <-time.After(2 * time.Second):
32993328
case <-d.stopCh:
@@ -3303,30 +3332,28 @@ func (d *Daemon) prewarmTrustedTunnels() {
33033332
if len(peers) == 0 {
33043333
return
33053334
}
3306-
slog.Info("prewarming encrypted tunnels for trusted peers", "count", len(peers))
3335+
slog.Info("prewarming resolve cache for trusted peers", "count", len(peers))
33073336
warmed := 0
33083337
for _, rec := range peers {
33093338
if d.stopping() {
33103339
return
33113340
}
33123341
// ensureTunnel fetches the peer's UDP endpoint (real_addr / relay)
3313-
// and registers it with the tunnel manager. Cheap if cached.
3342+
// and registers it with the tunnel manager. Populates resolveCache
3343+
// and epCache as a side effect. NO key exchange.
33143344
if err := d.ensureTunnel(rec.NodeID); err != nil {
33153345
slog.Debug("prewarm: ensureTunnel failed", "peer", rec.NodeID, "err", err)
33163346
continue
33173347
}
3318-
// Fire a key_exchange; the peer's reply derives the session key
3319-
// on both sides. After this, the peer is in tm.encKeys and the
3320-
// next call goes encrypted without re-keying.
3321-
d.tunnels.sendKeyExchangeToNode(rec.NodeID)
33223348
warmed++
3349+
// 200ms gap so a 50-peer fleet doesn't pile up at the registry.
33233350
select {
3324-
case <-time.After(50 * time.Millisecond):
3351+
case <-time.After(200 * time.Millisecond):
33253352
case <-d.stopCh:
33263353
return
33273354
}
33283355
}
3329-
slog.Info("prewarm fired", "peers", warmed)
3356+
slog.Info("prewarm complete", "peers_warmed", warmed)
33303357
}
33313358

33323359
// hostnameCachePath returns the on-disk location of the persisted
@@ -3508,7 +3535,12 @@ func (d *Daemon) ensureTunnel(nodeID uint32) error {
35083535
// flow A → beacon → B as MsgRelay frames.
35093536
relayOnly, _ := resp["relay_only"].(bool)
35103537
if relayOnly {
3511-
d.tunnels.SetRelayPeer(nodeID, true)
3538+
// Pin the relay flag — the registry's relay_only=true is an
3539+
// authoritative signal. clearRelayOnDirectLocked must not
3540+
// auto-flip pinned peers back to direct based on observed
3541+
// non-beacon source addresses (NAT-port-rewrite, beacon mesh
3542+
// forward from a different IP, etc).
3543+
d.tunnels.SetRelayPeerPinned(nodeID, true)
35123544
d.tunnels.AddPeer(nodeID, udpAddr) // udpAddr is already the beacon (substituted by registry)
35133545
slog.Debug("peer is RelayOnly, skipping hole punch", "node_id", nodeID)
35143546
return nil

pkg/daemon/ipc.go

Lines changed: 27 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -854,10 +854,17 @@ func (s *IPCServer) handleResolveHostname(conn *ipcConn, payload []byte) {
854854

855855
// Cache the successful response. Only cache positive results so
856856
// transient registry hiccups don't poison the cache with a bogus
857-
// "not found".
858-
s.daemon.hostnameCacheMu.Lock()
859-
s.daemon.hostnameCache[hostname] = &hostnameCacheEntry{resp: result, cachedAt: now}
860-
s.daemon.hostnameCacheMu.Unlock()
857+
// "not found". Skip caching when the result points at our own
858+
// node — local hostname state is owned by the daemon and changes
859+
// through paths that don't always invalidate the cache (admin
860+
// tools talking directly to the registry, tests bypassing IPC).
861+
if nidVal, ok := result["node_id"].(float64); ok && uint32(nidVal) == s.daemon.NodeID() {
862+
// fall through — no cache write, no prewarm, no disk persist
863+
} else {
864+
s.daemon.hostnameCacheMu.Lock()
865+
s.daemon.hostnameCache[hostname] = &hostnameCacheEntry{resp: result, cachedAt: now}
866+
s.daemon.hostnameCacheMu.Unlock()
867+
}
861868

862869
// Pre-warm the node-resolve cache so a follow-up DialAddr call from the
863870
// same pilotctl invocation skips the second registry round-trip in
@@ -897,6 +904,11 @@ func (s *IPCServer) handleResolveHostname(conn *ipcConn, payload []byte) {
897904

898905
func (s *IPCServer) handleSetHostname(conn *ipcConn, payload []byte) {
899906
hostname := string(payload)
907+
// Snapshot the previous hostname so we can invalidate it from the
908+
// cache regardless of whether this is a set, change, or clear.
909+
s.daemon.addrMu.RLock()
910+
prevHostname := s.daemon.config.Hostname
911+
s.daemon.addrMu.RUnlock()
900912
result, err := s.daemon.regConn.SetHostname(s.daemon.NodeID(), hostname)
901913
if err != nil {
902914
s.sendError(conn, fmt.Sprintf("set_hostname: %v", err))
@@ -906,6 +918,17 @@ func (s *IPCServer) handleSetHostname(conn *ipcConn, payload []byte) {
906918
s.daemon.addrMu.Lock()
907919
s.daemon.config.Hostname = hostname
908920
s.daemon.addrMu.Unlock()
921+
// Invalidate any cache entries that this change could have made stale:
922+
// the old name (we may have cached resolutions for it) and the new
923+
// name (could be a re-bind from another node we previously cached).
924+
s.daemon.hostnameCacheMu.Lock()
925+
if prevHostname != "" {
926+
delete(s.daemon.hostnameCache, prevHostname)
927+
}
928+
if hostname != "" {
929+
delete(s.daemon.hostnameCache, hostname)
930+
}
931+
s.daemon.hostnameCacheMu.Unlock()
909932
data, err := json.Marshal(result)
910933
if err != nil {
911934
s.sendError(conn, fmt.Sprintf("set_hostname marshal: %v", err))

0 commit comments

Comments
 (0)