Skip to content

fix: fresh node's first query to a service succeeds on the first try - #474

Merged
TeoSlayer merged 5 commits into
mainfrom
fix/first-contact-reliability
Sep 24, 2026
Merged

TeoSlayer merged 5 commits into
mainfrom
fix/first-contact-reliability

Conversation

@TeoSlayer

Copy link
Copy Markdown
Collaborator

Problem

On a clean machine, a fresh node's first pilotctl --json send-message list-agents --data '/data {"search":"weather","limit":1}' --wait usually fails with {"code":"timeout","error":"no reply from \"0:0000.0002.BBE4\" within 30s"}. It typically succeeds on attempt 3, about 135 s in. This is not a v1.13.10 regression (v1.13.9 is worse), and under concurrent load (24 fresh nodes) almost every first attempt fails.

Root cause (two investigations, reconciled)

Two independent traces ran on clean GitHub runners at debug level with pcap. They agree on the client-side mechanisms. They weight the server side differently, and the two accounts are complementary rather than conflicting.

Client side (both traces agree; fixed here):

  1. The reply is dropped by our own trust gate. list-agents replies on a new connection it dials back to our port 1001 (and the handshake accept goes to port 444). A private node (the default) silently drops a SYN from an untrusted peer. That produced about 50 SYN rejected: untrusted source per failed attempt, 244 in total in one trace. Trust only arrives through the handshake, and the relayed handshake is polled every 60 s, which matches "success at ~135 s".
  2. pilotctl blocked about 17-22 s before dialing. The auto-handshake with a trusted agent ran a direct dial to port 444 (timeout 17.25 s), fell back to the registry relay, then waited 5 s for trust. Only after that did the data dial start.
  3. The dial spent its SYN retries while the key exchange was still running. Against a busy list-agents the key exchange took a median of 18.7 s (p90 69 s). The SYNs sat queued with no key while the dial counted retries and queued duplicates (7-39 stale SYNs were then flushed at once toward list-agents' 10/s per-source SYN limit). As a result the dial timed out (cannot connect) in 62 of 96 attempts.
  4. First-contact key-exchange deadlock. A node answers a new peer's PILA exactly once and clears its retransmit state. If that one reply is lost, our retransmits carry the same X25519 key, so the peer treats them as same-session keepalives and never answers. Its InboundDecryptStale recovery never fires, because onKeyInstalled stamps lastInboundDecrypt just before the check. The deadlock lasts until the peer's path watchdog drops its half, and our own PILAs keep postponing that. A failing unit test on main reproduced it.
  5. Stale registry endpoint. list-agents resolves to 34.70.116.35:4615, but it is actually reachable at 34.69.26.204:4615 (the beacon punch target, and where its sibling personas register). Every dial spent 1.75 s of direct retries on the dead address, and 34% of our packets went there.
  6. Registry RPCs on the tunnel read loop. HandleAuthFrame made a synchronous registry CheckTrust for every new peer's PILA only to decide whether an event may name the peer, which stalled every other inbound packet for that time.

Server side (the traces differ in emphasis; needs the asks below): the second trace shows that list-agents' daemon is slow, independent of the directory app. It answers beacon punch commands after a median of 11.5 s (44% never), while pilot-mom takes 0.03 s and sibling personas on the same host take 0.11 s. It answered 6 of 36 port-7 echoes, against 35 of 36 for randomfox on the same host and version. No client change fixes that, but items 3-4 turn that slowness into a hard failure, and fixing them turns it back into latency.

Changes (web4 client + daemon)

Daemon

  • Reply window (pkg/daemon/replywindow.go): the private-node SYN gate works like a stateful firewall. For 5 min after this node dials a peer, or sends it a trust handshake, a SYN from that peer to port 1001 or 444 is admitted. Only the contacted peer is admitted, only on those two ports, and the table is bounded (4096) and pruned by the idle sweep. Everything else still needs trust.
  • Dials wait for the key exchange (DialKeyExchangeWait = 10s): while no session key exists, the dial keeps one queued SYN (no duplicates) and does not count retries. The queued SYN is flushed the moment the key arrives. If the key never arrives, the error is key exchange with peer did not complete, which wraps protocol.ErrDialTimeout, so existing errors.Is checks still hold.
  • Relay-first when relay is the only proven path: if the peer's key arrived over the relay and nothing has ever been decrypted from its direct address, the dial starts on the relay instead of spending 1.75 s on the direct path. relayProbeLoop still tries to upgrade to direct.
  • Key request (PILK nudge) breaks the deadlock in item 4 against the unfixed fleet. When our first-contact PILA is unanswered and we hold no key, each retransmit also carries an unauthenticated PILK, with the same relay copy. Every released daemon answers a PILK from a known identity by rejecting it and sending its own authenticated PILA, marked pending and therefore retransmitted (HandleUnauthFrame). The same PILK goes out when a peer sends us AEAD frames we have no key for. A PILK installs nothing on such a peer and costs 40 bytes per retransmit.
  • No registry call on the read loop for event redaction: SetPeerTrustFn(d.handshakeTrusts) uses local trust. A peer trusted only through the registry gets the redacted tunnel.established event, which is the conservative side.
  • info reports features (reply_window, dial_awaits_key, key_request), so pilotctl can adapt to the daemon version it is talking to without comparing version strings.

pilotctl send-message --wait

  • No blocking auto-handshake when the daemon has reply_window. With an older daemon the previous behaviour is kept. A private peer we don't trust is still refused up front.

  • First contact is detected from the daemon's peer table (no encrypted session yet). On first contact, a dial that fails while the path is converging (timeout or key exchange) is retried once. If the SDK itself timed out, the retry uses a fresh driver connection.

  • --wait matches the reply to the request:

    • the inbox is snapshotted before the send, so files already present are ignored (an earlier request's reply, or a service's late duplicate);
    • the oldest new file from the peer wins;
    • the window is counted from the receiver's ACK, not from before the dial.
  • One re-send on first contact: if no reply has arrived by mid-window (at most 15 s), the request is sent once more on a new stream, and the window is extended so the second request gets at least half a window. The re-send is skipped with --no-resend, for governed sends, and when the window is shorter than 6 s.

  • Actionable errors: the timeout keeps its no reply from "<addr>" within 30s message, so scripts that match on it keep working, and adds a hint that names the step that failed:

    • the key exchange never completed;
    • the service dialed its reply back but no data arrived (counted from the daemon's connection table);
    • no reply connection was seen at all.

    JSON output also carries first_contact, dial_attempts, resent and reply_after_ms.

Deliberately not done

  • Pre-handshaking the directory at registration. Every node would open a tunnel to list-agents on every start, which adds load to the network's hottest and already-lagging node. That is not fleet-safe until the server asks below land.
  • --wait / pilotctl inbox still read $HOME/.pilot/inbox rather than honouring PILOT_HOME. Both use the same path, so they stay consistent with each other; a separate fix can change both together.

Measurements (clean GitHub runners)

I ran an interleaved A/B on clean runners with the onboarding harness steps: official installer (stable v1.13.10), then pilot-daemon and pilotctl swapped for one of two source builds, main (9adaede) or this branch. Each run did pilotctl daemon start and then the same send-message list-agents ... --wait query, up to 3 attempts. The matrix was ubuntu-latest, ubuntu-24.04-arm, macos-15 and macos-15-intel, × 3 reps × 2 variants, run as 2 rounds with max-parallel 4 so that each wave paired main and fix on the same OS (run 35990469128, attempts 1-2).

first query OK on attempt 1 never OK in 3 attempts attempt-1 latency (median / max)
main 20/24 2/24 3 s / 19 s
this PR 24/24 0/24 1 s / 36 s
  • main's failures:
    • ubuntu-latest: 3 × cannot connect. The log shows 14 no key and 18 gave up, which is the key-exchange deadlock signature.
    • macos-15-intel: cannot connect / cannot resolve on all 3 attempts.
    • arm and macos-15: once each, no reply within 30s on attempt 1, then OK on attempt 2.
  • This PR: 2 of 24 needed the second first-contact dial (dial_attempts: 2, 30 s and 36 s end to end); every other query finished within 14 s. No re-send was needed in any job.
  • One job was excluded from both columns: on the fix build, the daemon did not become ready within 15 s at startup. That is before any query, in registration, which this PR does not touch. The job passed first try when rerun (attempt 3).
  • Caveat: list-agents was in one of its healthier periods during these runs, since main also did better than in the original report (1/5 to 3/5). The 24-fresh-nodes-at-once load case was not rerun because the verification limit is 4 concurrent jobs. The PILK key request and dial-awaits-key paths are what cover the slow and deadlocked cases; unit tests reproduce both.

Server-side asks (not in this PR)

  1. list-agents registry entry (node 179172, 0:0000.0002.BBE4).
    • It advertises 34.70.116.35:4615, which answers no ICMP and no UDP. The live host is 34.69.26.204:4615.
    • Re-register it with the live address (drop any fixed -endpoint), or run it -relay-only.
    • Audit all ~436 personas on pilot-service-agents for a stale real_addr.
    • Reserve a static IP for the VM.
    • Update the registry rate-limit whitelist entry that still lists 34.70.116.35 as "service-agents".
  2. list-agents daemon saturation.
    • On pilot-service-agents, collect for UDP port 4615: nstat -az UdpRcvbufErrors UdpInErrors and ss -uamp sport = :4615.
    • Grep its debug log for key exchange rate-limited, cannot verify peer identity from registry and registry reconnect storms.
    • Raise the socket rcvbuf.
    • Consider sharding the directory across several nodes: it is the network's hottest node and a single point of failure.
  3. Upgrade the service-agent fleet off daemon v1.13.5. It lacks daemon: stop the KX rate limiter wedging key exchange permanently #436: the KX source-IP limiter map is never pruned, so after 4096 distinct source IPs every new direct PILA is dropped. Include this PR's daemon changes in the same upgrade.
  4. Responder-side key exchange (pkg/daemon/keyexchange, a follow-up PR).
    • (a) Keep the reply to a new peer's PILA armed for retransmit until the first AEAD frame from that peer decrypts, instead of calling ClearPendingRekey in the !hadCrypto branch (handle.go:186-187).
    • (b) Gate the asymmetric-recovery reply (handle.go:206) on "no AEAD decrypt since install" rather than on lastInboundDecrypt, which onKeyInstalled stamps just before the check. This is daemon: path reset keeps the session so rekey desync can recover without a restart #465's stated follow-up.
    • (c) Send reply PILAs with a relay copy, as the initiator already does.
    • (d) Put a deadline on lookupPeerPubKey (d.reg().Lookup has none today) and move it off the single read goroutine.
  5. Responder (pilot-agents/responder, live-service-agents list-agents).
    • Double replies (sweep item 11): every request gets 2-4 identical replies (pre-fetch optimistic send, post-fetch optimistic send, fallback). Send exactly once and set ReplyTo to the request's MessageID. This PR makes the client ignore duplicates, but they still cost the service a dial-back each.
    • Reply budget: the 0.5 s optimistic budget is shorter than any relay dial-back (the direct phase alone is 1.75 s), and killing the helper cancels the daemon dial. Keep a reply retry loop running for at least 60 s with backoff.
    • Unreachable marking: don't mark a peer unreachable for 300 s after one failure.
    • Fallback trust: isNATed is true for every 0: address and stdin-mode Handshake is a no-op, so the fallback never establishes trust.
    • Empty reply connections: 83 of 171 reply connections completed the handshake but carried no payload. Log whether each send was acknowledged.
    • Longer term: reply on the requester's own stream (feat: reply-on-connection — daemon --auto-answer + pilotctl --reply-on-conn #230, dataexchange Unit 2: Registry audit trail — structured mutation logging #19). That removes the dial-back, the client trust gate and NAT traversal from the reply path.
  6. Directory data: list-agents returns agents the registry no longer knows. For example, the top weather hit, open-meteo-air-quality at 0:0000.0000.4BBA, gets "node not found", as do open-meteo-flood, restcountries-all and dblp-publ-search. Prune them.
  7. Handshake ordering on services: with -trust-auto-approve, ReportTrust and sendAccept are fired as concurrent goroutines. Sequence ReportTrust first, so the accept passes the client's registry trust check. Also raise or whitelist the default SYN limits (100/s global, 10/s per source) for directory agents; deploy-one.sh passes none.
  8. Registry (sweep item 5).
    • It sends FIN on fresh clients' TCP connections about 6 s after connect (rapid_close, rate_limit_suspected=true in 20 of 21 CI job logs). Send an error frame instead of a silent close.
    • Size the per-IP and global buckets for agent VMs where many daemons share one egress IP.
    • Relayed handshakes are delivered only through 60 s polls: add a push path or a faster poll.
  9. Beacon.
    • maxPunchPerSecond = 10 is fleet-wide (one punch per 100 ms for the whole network): make it per-target or raise it.
    • Count per-source relay-limiter drops in relayDropped.

Tests

GOWORK=off go test ./cmd/... ./pkg/daemon/... -count=1 passes. New tests:

  • pkg/daemon/zz_first_contact_test.go:
    • lost first-contact key reply recovers through the key request;
    • no key request while a session is up;
    • a no-key frame triggers a key request;
    • a dial waits for the key without duplicate SYNs;
    • the key-exchange dial error wraps ErrDialTimeout;
    • relay-only detection;
    • reply window: admits a dial-back, admits a handshake accept, covers only the reply ports, expires, is bounded, and is opened by a dial;
    • a key install does not wait on the registry trust check.
  • pkg/daemon/keyexchange/zz_key_request_test.go: the key request rides on retransmits only, the due-mark sends it on the first try, no key request once a session is installed, and the peer answers a key request with a retransmitted PILA.
  • cmd/pilotctl/zz_firstcontact_test.go: inbox snapshot and ordering, re-send once, window extension, resend-failure reporting, reply-connection counting, hints, dial-error classification, and the auto-handshake that no longer blocks (while kept for older daemons).
  • TestCmdSendMessageJSONWaitSingleDoc now writes its reply after the send, since a pre-existing file is (correctly) no longer taken as the reply.

🤖 Generated with Claude Code

A fresh node's first `send-message list-agents --wait` failed most of the
time on clean runners. The causes stack; this fixes the client half.

daemon:
- Reply window: a private node admits a SYN to port 1001/444 from a peer
  it dialed or sent a handshake to in the last 5 min, so a service's
  dial-back reply no longer needs a trust handshake first (was ~50
  "SYN rejected: untrusted source" per failed first query).
- Dials wait up to 10 s for the first-contact key exchange before
  spending SYN retries, queue one SYN instead of duplicates, and report
  "key exchange with peer did not complete" (wraps ErrDialTimeout).
- A peer whose key arrived only over the relay is dialed via relay
  first (a stale registry endpoint no longer costs 1.75 s per dial).
- Key request: an unanswered first-contact PILA is followed by a PILK,
  which every released daemon answers with a retransmitted PILA. Breaks
  the deadlock where the service's single reply was lost and it treats
  our same-key retransmits as keepalives. Also sent when a peer sends us
  encrypted frames we have no key for.
- The key-exchange peer-trust check (event redaction only) uses local
  trust, not a synchronous registry CheckTrust on the read loop.
- info reports "features" so pilotctl can adapt to the daemon.

pilotctl send-message --wait:
- no blocking auto-handshake when the daemon has the reply window;
- one more dial on first contact while the path is converging;
- the wait counts from the receiver's ack, ignores inbox files present
  before the send and takes the oldest new reply from the peer;
- on first contact, re-sends the request once on a new stream if no
  reply by mid-window (--no-resend opts out; never for governed sends);
- timeout and dial errors name the step that failed.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Comment thread cmd/pilotctl/main.go
tracef("connectDriver")
defer d.Close()
// d may be replaced by a fresh connection when a dial is retried.
defer func() { d.Close() }()
Comment thread cmd/pilotctl/main.go
// The SDK gave up waiting, the daemon may still be
// dialing: use a fresh connection so a late reply to
// the first dial cannot be taken for the second.
d.Close()
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@TeoSlayer
TeoSlayer enabled auto-merge (squash) September 24, 2026 18:20
teovl and others added 2 commits September 24, 2026 21:23
…iability

# Conflicts:
#	cmd/pilotctl/main.go
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@TeoSlayer
TeoSlayer merged commit 66e5458 into main Sep 24, 2026
15 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants