[GH-ISSUE #138] fix(p2p): sandbox veth churn kills the iroh endpoint ~1.3s after startup, disabling P2P for the process lifetime #46

New issue

Open

opened 2026-10-29 14:18:47 +00:00 by bsakaguchi · 4 comments

bsakaguchi commented 2026-10-29 14:18:47 +00:00

Owner

Copy link

Originally created by @dushulin on GitHub (Aug 7, 2026).
Original GitHub issue: https://github.com/kvcache-ai/AgentENV/issues/138

Summary

With [p2p].enabled = true, the iroh endpoint and the iroh-blobs store are torn
down ~1.3 s after node startup, before a single artifact is ever served. On an
8-node cluster, 7 of 8 nodes died this way; the 8th survived only by winning a race.
Once dead, nothing ever restarts the transport, so P2P is silently unavailable for
the entire lifetime of the process and every overlaybd read falls back to the origin
registry.

The trigger is AgentENV's own warm-pool priming: the veth-* interfaces it creates
in the runtime pod's network namespace are seen by netwatch as a major link
change, which makes iroh rebind its UDP socket — and that rebind is not recoverable
when it fails.

Environment

AgentENV runtime	v0.1.3
iroh	1.0.0-rc.0 (also reproduces by inspection on 1.0.3)
netwatch	0.19.1 (unmodified from crates.io)
Kernel	6.8, cgroup v2
Deployment	Kubernetes DaemonSet, pod has its own netns (hostNetwork unset)
Config	[p2p] enabled=true, transport="iroh", listen_addr="0.0.0.0:0", [snapshot] p2p_enabled=true, [ublk] download_enable=true
Scale	8 runtime nodes, all with identical config

Reproduction

Enable P2P with the default listen_addr = "0.0.0.0:0" and start the node. The
failing log lines are debug-level only, so an info log shows nothing at all —
this is why the failure went unnoticed. Use:

RUST_LOG=info,iroh=debug,iroh_blobs=debug,netwatch=debug,noq=debug

Observed on 7 of 8 nodes, marker counts byte-identical on every one of them
(rebinding=1, Address already in use=3, socket closed=2, closing database=1):

13.572  iroh::socket::transports::ip: binding addr=0.0.0.0:0
13.572  iroh::socket::transports::ip: successfully bound local_addr=0.0.0.0:51871
13.597  iroh::_events::direct_addrs: addrs={10.126.17.156:51871 Local}
13.597  iroh::endpoint: iroh endpoint bound iroh_version=1.0.0-rc.0
13.607  agentenv::p2p::iroh::transport: iroh artifact transport started
13.760  agentenv::sandbox::firecracker::pool: priming firecracker pool low_watermark=2
14.723  agentenv::sandbox::firecracker::pool: firecracker pool primed warm=2 elapsed_ms=962
14.794  iroh::_events::link_change: state=State { interfaces: {...} }
14.795  iroh::socket: link change detected is_major=true
14.795  netwatch::udp: rebinding 0.0.0.0:51871
14.795  netwatch::udp: rebind failed, will retry on next attempt: Address already in use (os error 98)
14.795  WARN  iroh::socket::transports: failed to rebind Os { code: 98, kind: AddrInUse }
14.795  WARN  iroh::socket: failed to rebind transports: Os { code: 98, kind: AddrInUse }
14.795  iroh::_events::direct_addrs: addrs={10.12.0.2:51871, 10.12.0.4:51871, 10.126.17.156:51871}
14.795  WARN  netwatch::udp: socket closed
14.795  ERROR noq::endpoint: I/O error: socket closed
14.796  iroh_blobs::store::fs::meta: closing database
14.799  iroh::protocol: Shutting down remaining tasks

After this point the process logs no further iroh activity for its whole lifetime.

Root cause

Three separate defects compose into the failure. Only the first is AgentENV's.

1. Sandbox veth churn is reported as a major link change (AgentENV + netwatch)

10.12.0.2 and 10.12.0.4 are host-side ends of sandbox veth pairs, inside
[network].veth_cidr = 10.12.0.0/16. They appear in direct_addrs in the same
millisecond as is_major=true, immediately after firecracker pool primed warm=2.
So AgentENV's own routine warm-pool priming is what knocks out its own P2P transport.

On Linux, netwatch treats every interface as relevant
(netwatch-0.19.1/src/netmon/linux.rs):

pub(crate) fn is_interesting_interface(_name: &str) -> bool {
    true
}

Sandbox veths are node-local plumbing and can never carry P2P traffic, so they should
not influence the endpoint's address set or force a rebind. On a busy node these are
created and destroyed constantly, so this is not a one-shot startup problem — it is a
permanent source of endpoint churn.

2. netwatch's rebind destroys a working socket before it knows it can replace it (upstream)

netwatch-0.19.1/src/udp.rs (verified byte-identical to the crates.io release):

fn rebind(&mut self) -> io::Result<()> {
    let addr = match self { /* resolved local addr, i.e. 0.0.0.0:51871, not 0.0.0.0:0 */ };
    debug!("rebinding {}", addr);

    // Transition to Closed first to drop the old socket.
    // This is needed so the port is released before we try to bind again.
    if let Self::Connected { state, .. } = self {
        *self = SocketState::Closed { addr, .. };   // <-- working socket dropped here
    }

    match Self::bind(addr) {
        Ok(new_state) => { *self = new_state; Ok(()) }
        Err(err) => {
            // Stay in Closed state but allow future rebind attempts
            debug!("rebind failed, will retry on next attempt: {}", err);
            Err(err)
        }
    }
}

Two problems:

• The healthy socket is dropped before a replacement is known to be obtainable.
  Any transient bind failure therefore costs the endpoint permanently.
• The "will retry on next attempt" comment is not honoured in practice. No retry ever
  fires in our logs — a single failure is terminal. The next is_major link change
  would be needed to try again, and none arrives, because once the warm pool is primed
  the interface set stops changing.

The resulting Closed state makes every subsequent send/recv return
BrokenPipe: socket closed, which noq escalates to I/O error: socket closed, which
in turn closes the iroh-blobs store.

3. The EADDRINUSE is a race, and AgentENV never notices the endpoint is gone

One node out of eight ran the identical sequence and its rebind succeeded; its
endpoint is still healthy hours later. So this is a timing race on re-binding a
just-released ephemeral port (the pod's range is 32768–60999), not a structural
conflict.

We ruled out a duplicated/retained fd inside the stack:

• netwatch/src/udp.rs exposes no fd-escaping API (no as_raw_fd, into_inner,
  dup, ManuallyDrop, mem::forget).
• noq_udp::UdpSockRef<'a> is socket2::SockRef<'a> — a borrow. UdpSocketState
  stores no fd.
• iroh/src/socket/transports/ip.rs:277 only delegates: self.socket.rebind()?.
• iroh binds exactly one socket; there is no second (v6) socket to conflict with.

Independently of who wins the port race, AgentENV has no supervision of the P2P
transport: a dead endpoint is never detected, never reported, and never restarted.
A p2p.enabled = true node that lost its endpoint is indistinguishable from a healthy
one from the outside, and simply serves every read from the origin registry.

Suggested fixes

1. Do not let sandbox veths drive endpoint rebinds. Filter AgentENV's own
   veth-* prefix out of netwatch's interface interest set (and out of the reported
   address set), so warm-pool and sandbox churn is invisible to iroh.
2. Make rebind non-destructive. Retry the same port a small number of times, and
   if it stays unavailable, fall back to binding port 0. A fresh ephemeral port is
   strictly better than a dead endpoint — address changes are exactly what the rebind
   path is designed to handle. Worth reporting upstream to netwatch/iroh.
3. Supervise the transport. Surface endpoint liveness (heartbeat / node metrics)
   and re-create the endpoint when it dies, so this can never again be a silent
   degradation.

Second, independent finding: the overlaybd layer catalog is never populated

Even with a healthy endpoint, the overlaybd P2P path cannot hit. Across all 8 nodes
there has never been a single overlaybd-layer/v1/sha256:* key in the iroh catalog
(the current catalog WAL is 0 bytes on every node; the only keys present anywhere are
snapshot/v1/artifacts/*). Three reasons, all in code:

• The only publisher of overlaybd-layer/v1/* is publish_completed_layer()
  (storage/overlaybd/src/bk_download.rs:275, invoked at :736 and :770), which
  runs only after a complete background layer download. Locally complete commits
  that need no download are also gated behind the same path.
• DownloadConfig::default() (storage/overlaybd/src/config.rs:116-129) sets
  delay: 300, delay_extra: 30, inherited verbatim by src/setup/deps.rs:286-288 via
  ..Default::default(). So no background download even starts for 300–330 s, and
  any sandbox shorter-lived than that publishes nothing, ever.
• Meanwhile the descriptor miss TTL is 5 s (src/overlaybd/p2p/facade.rs:32-33), so an
  empty catalog means a fresh full lookup every 5 s on the block-read critical
  path, with lookup_peers handshaking peers sequentially
  (src/p2p/iroh/transport.rs:218-249, carrying // TODO: parallelize lookups to multiple peers.). This is the mechanism behind the measured exec p50 of 28.7 ms
  (P2P off) vs 2766.7 ms (P2P on, empty catalog).

Suggested fix: publish already-complete local layers immediately instead of only as a
side effect of a delayed background download, and avoid broad peer polling when the
scheduler artifact index returns no hint. (Lookup fan-out itself is tracked in #95.)

Originally created by @dushulin on GitHub (Aug 7, 2026). Original GitHub issue: https://github.com/kvcache-ai/AgentENV/issues/138 ## Summary With `[p2p].enabled = true`, the iroh endpoint and the `iroh-blobs` store are torn down **~1.3 s after node startup, before a single artifact is ever served**. On an 8-node cluster, 7 of 8 nodes died this way; the 8th survived only by winning a race. Once dead, nothing ever restarts the transport, so P2P is silently unavailable for the entire lifetime of the process and every overlaybd read falls back to the origin registry. The trigger is AgentENV's own warm-pool priming: the `veth-*` interfaces it creates in the runtime pod's network namespace are seen by `netwatch` as a *major* link change, which makes iroh rebind its UDP socket — and that rebind is not recoverable when it fails. ## Environment | | | |---|---| | AgentENV runtime | `v0.1.3` | | iroh | `1.0.0-rc.0` (also reproduces by inspection on `1.0.3`) | | netwatch | `0.19.1` (unmodified from crates.io) | | Kernel | 6.8, cgroup v2 | | Deployment | Kubernetes DaemonSet, pod has its **own** netns (`hostNetwork` unset) | | Config | `[p2p] enabled=true, transport="iroh", listen_addr="0.0.0.0:0"`, `[snapshot] p2p_enabled=true`, `[ublk] download_enable=true` | | Scale | 8 runtime nodes, all with identical config | ## Reproduction Enable P2P with the default `listen_addr = "0.0.0.0:0"` and start the node. The failing log lines are **debug-level only**, so an `info` log shows nothing at all — this is why the failure went unnoticed. Use: ``` RUST_LOG=info,iroh=debug,iroh_blobs=debug,netwatch=debug,noq=debug ``` Observed on 7 of 8 nodes, marker counts byte-identical on every one of them (`rebinding`=1, `Address already in use`=3, `socket closed`=2, `closing database`=1): ``` 13.572 iroh::socket::transports::ip: binding addr=0.0.0.0:0 13.572 iroh::socket::transports::ip: successfully bound local_addr=0.0.0.0:51871 13.597 iroh::_events::direct_addrs: addrs={10.126.17.156:51871 Local} 13.597 iroh::endpoint: iroh endpoint bound iroh_version=1.0.0-rc.0 13.607 agentenv::p2p::iroh::transport: iroh artifact transport started 13.760 agentenv::sandbox::firecracker::pool: priming firecracker pool low_watermark=2 14.723 agentenv::sandbox::firecracker::pool: firecracker pool primed warm=2 elapsed_ms=962 14.794 iroh::_events::link_change: state=State { interfaces: {...} } 14.795 iroh::socket: link change detected is_major=true 14.795 netwatch::udp: rebinding 0.0.0.0:51871 14.795 netwatch::udp: rebind failed, will retry on next attempt: Address already in use (os error 98) 14.795 WARN iroh::socket::transports: failed to rebind Os { code: 98, kind: AddrInUse } 14.795 WARN iroh::socket: failed to rebind transports: Os { code: 98, kind: AddrInUse } 14.795 iroh::_events::direct_addrs: addrs={10.12.0.2:51871, 10.12.0.4:51871, 10.126.17.156:51871} 14.795 WARN netwatch::udp: socket closed 14.795 ERROR noq::endpoint: I/O error: socket closed 14.796 iroh_blobs::store::fs::meta: closing database 14.799 iroh::protocol: Shutting down remaining tasks ``` After this point the process logs no further iroh activity for its whole lifetime. ## Root cause Three separate defects compose into the failure. Only the first is AgentENV's. ### 1. Sandbox `veth` churn is reported as a major link change (AgentENV + netwatch) `10.12.0.2` and `10.12.0.4` are host-side ends of sandbox veth pairs, inside `[network].veth_cidr = 10.12.0.0/16`. They appear in `direct_addrs` in the *same millisecond* as `is_major=true`, immediately after `firecracker pool primed warm=2`. So AgentENV's own routine warm-pool priming is what knocks out its own P2P transport. On Linux, netwatch treats every interface as relevant (`netwatch-0.19.1/src/netmon/linux.rs`): ```rust pub(crate) fn is_interesting_interface(_name: &str) -> bool { true } ``` Sandbox veths are node-local plumbing and can never carry P2P traffic, so they should not influence the endpoint's address set or force a rebind. On a busy node these are created and destroyed constantly, so this is not a one-shot startup problem — it is a permanent source of endpoint churn. ### 2. `netwatch`'s rebind destroys a working socket before it knows it can replace it (upstream) `netwatch-0.19.1/src/udp.rs` (verified byte-identical to the crates.io release): ```rust fn rebind(&mut self) -> io::Result<()> { let addr = match self { /* resolved local addr, i.e. 0.0.0.0:51871, not 0.0.0.0:0 */ }; debug!("rebinding {}", addr); // Transition to Closed first to drop the old socket. // This is needed so the port is released before we try to bind again. if let Self::Connected { state, .. } = self { *self = SocketState::Closed { addr, .. }; // <-- working socket dropped here } match Self::bind(addr) { Ok(new_state) => { *self = new_state; Ok(()) } Err(err) => { // Stay in Closed state but allow future rebind attempts debug!("rebind failed, will retry on next attempt: {}", err); Err(err) } } } ``` Two problems: - The healthy socket is dropped **before** a replacement is known to be obtainable. Any transient bind failure therefore costs the endpoint permanently. - The "will retry on next attempt" comment is not honoured in practice. No retry ever fires in our logs — a single failure is terminal. The next `is_major` link change would be needed to try again, and none arrives, because once the warm pool is primed the interface set stops changing. The resulting `Closed` state makes every subsequent send/recv return `BrokenPipe: socket closed`, which `noq` escalates to `I/O error: socket closed`, which in turn closes the `iroh-blobs` store. ### 3. The `EADDRINUSE` is a race, and AgentENV never notices the endpoint is gone One node out of eight ran the identical sequence and its rebind *succeeded*; its endpoint is still healthy hours later. So this is a timing race on re-binding a just-released ephemeral port (the pod's range is 32768–60999), not a structural conflict. We ruled out a duplicated/retained fd inside the stack: - `netwatch/src/udp.rs` exposes no fd-escaping API (no `as_raw_fd`, `into_inner`, `dup`, `ManuallyDrop`, `mem::forget`). - `noq_udp::UdpSockRef<'a>` is `socket2::SockRef<'a>` — a borrow. `UdpSocketState` stores no fd. - `iroh/src/socket/transports/ip.rs:277` only delegates: `self.socket.rebind()?`. - iroh binds exactly one socket; there is no second (v6) socket to conflict with. Independently of who wins the port race, AgentENV has no supervision of the P2P transport: a dead endpoint is never detected, never reported, and never restarted. A `p2p.enabled = true` node that lost its endpoint is indistinguishable from a healthy one from the outside, and simply serves every read from the origin registry. ## Suggested fixes 1. **Do not let sandbox veths drive endpoint rebinds.** Filter AgentENV's own `veth-*` prefix out of netwatch's interface interest set (and out of the reported address set), so warm-pool and sandbox churn is invisible to iroh. 2. **Make rebind non-destructive.** Retry the same port a small number of times, and if it stays unavailable, fall back to binding port `0`. A fresh ephemeral port is strictly better than a dead endpoint — address changes are exactly what the rebind path is designed to handle. Worth reporting upstream to `netwatch`/`iroh`. 3. **Supervise the transport.** Surface endpoint liveness (heartbeat / node metrics) and re-create the endpoint when it dies, so this can never again be a silent degradation. ## Second, independent finding: the overlaybd layer catalog is never populated Even with a healthy endpoint, the overlaybd P2P path cannot hit. Across all 8 nodes there has never been a single `overlaybd-layer/v1/sha256:*` key in the iroh catalog (the current catalog WAL is 0 bytes on every node; the only keys present anywhere are `snapshot/v1/artifacts/*`). Three reasons, all in code: - The only publisher of `overlaybd-layer/v1/*` is `publish_completed_layer()` (`storage/overlaybd/src/bk_download.rs:275`, invoked at `:736` and `:770`), which runs **only after a complete background layer download**. Locally complete commits that need no download are also gated behind the same path. - `DownloadConfig::default()` (`storage/overlaybd/src/config.rs:116-129`) sets `delay: 300, delay_extra: 30`, inherited verbatim by `src/setup/deps.rs:286-288` via `..Default::default()`. So no background download even *starts* for 300–330 s, and any sandbox shorter-lived than that publishes nothing, ever. - Meanwhile the descriptor miss TTL is 5 s (`src/overlaybd/p2p/facade.rs:32-33`), so an empty catalog means a fresh full lookup every 5 s **on the block-read critical path**, with `lookup_peers` handshaking peers sequentially (`src/p2p/iroh/transport.rs:218-249`, carrying `// TODO: parallelize lookups to multiple peers.`). This is the mechanism behind the measured exec p50 of 28.7 ms (P2P off) vs 2766.7 ms (P2P on, empty catalog). Suggested fix: publish already-complete local layers immediately instead of only as a side effect of a delayed background download, and avoid broad peer polling when the scheduler artifact index returns no hint. (Lookup fan-out itself is tracked in #95.)

bsakaguchi commented 2026-10-29 14:18:48 +00:00

Author

Owner

Copy link

@dushulin commented on GitHub (Aug 7, 2026):

Correction to the "empty layer catalog" part of the report above — I said the overlaybd layer catalog is never populated. That is too strong, and the precise shape of the failure matters for the fix.

overlaybd-layer/v1/* has two key families, and only one of them is broken:

key family	publisher	entries per node
uuid/<uuid>	src/snapshot/p2p.rs (snapshot-produced layers)	28–29 — healthy
sha256:<digest>	bk_download::publish_completed_layer (registry-downloaded layers)	0 and 1

Measured 2026-08-07 on the two nodes that hold a warm image cache, by extracting keys directly from {p2p store}/iroh/catalog.db/*.sst:

node A: sha256-keys 0    uuid-keys 29    local *.commit 265
node B: sha256-keys 1    uuid-keys 28    local *.commit 139

The digest family is the one a cold overlaybd read looks up, so 0–1 entries against 139–265 complete local commits is why reads still go to the origin registry even on a node that already has the bytes.

Cause: the only publisher of the digest family is publish_completed_layer, reached only after a background layer download that first waits out DownloadConfig::default().delay (300 s + 30 s extra). A layer that is already complete on disk never takes that path, so it is never advertised — and a sandbox shorter-lived than the delay advertises nothing at all.

Two practical consequences:

1. Verifying P2P health by catalog size or by the catalog WAL being non-zero is misleading — the uuid family populates it regardless. The check has to be specifically on overlaybd-layer/v1/sha256:* key count versus the node's *.commit count.
2. Lowering delay does not fix it. The publish needs to be decoupled from the download entirely: a layer that is already complete and checksum-valid locally should be advertised immediately, without any registry traffic and without consuming a download attempt.

<!-- gh-comment-id:5215387843 --> @dushulin commented on GitHub (Aug 7, 2026): Correction to the "empty layer catalog" part of the report above — I said the overlaybd layer catalog is never populated. That is too strong, and the precise shape of the failure matters for the fix. `overlaybd-layer/v1/*` has two key families, and only one of them is broken: | key family | publisher | entries per node | |---|---|---| | `uuid/<uuid>` | `src/snapshot/p2p.rs` (snapshot-produced layers) | 28–29 — healthy | | `sha256:<digest>` | `bk_download::publish_completed_layer` (registry-downloaded layers) | **0 and 1** | Measured 2026-08-07 on the two nodes that hold a warm image cache, by extracting keys directly from `{p2p store}/iroh/catalog.db/*.sst`: ``` node A: sha256-keys 0 uuid-keys 29 local *.commit 265 node B: sha256-keys 1 uuid-keys 28 local *.commit 139 ``` The digest family is the one a cold overlaybd read looks up, so 0–1 entries against 139–265 complete local commits is why reads still go to the origin registry even on a node that already has the bytes. Cause: the only publisher of the digest family is `publish_completed_layer`, reached only *after* a background layer download that first waits out `DownloadConfig::default().delay` (300 s + 30 s extra). A layer that is already complete on disk never takes that path, so it is never advertised — and a sandbox shorter-lived than the delay advertises nothing at all. Two practical consequences: 1. Verifying P2P health by catalog size or by the catalog WAL being non-zero is misleading — the uuid family populates it regardless. The check has to be specifically on `overlaybd-layer/v1/sha256:*` key count versus the node's `*.commit` count. 2. Lowering `delay` does not fix it. The publish needs to be decoupled from the download entirely: a layer that is already complete and checksum-valid locally should be advertised immediately, without any registry traffic and without consuming a download attempt.

bsakaguchi commented 2026-10-29 14:18:48 +00:00

Author

Owner

Copy link

@dushulin commented on GitHub (Aug 7, 2026):

Third defect, and this one is the reason P2P still served nothing after the first two were fixed: the consumer and the publisher key the same layer differently whenever the registry redirects blob GETs to an object store.

What happens

registryfs_v2::fetch_range_response resolves the blob URL first, then hands the accelerator the post-redirect URL:

let raw_actual_url = match info.mode {
    UrlMode::Redirect => info.info.clone(),   // <- the object-store URL
    UrlMode::SelfAuth => url.to_string(),
};
if let Some(accelerated) = self.with_accelerate_url(&raw_actual_url) { ... }

CanonicalBlobIdentity::from_origin_url recovers the digest by looking for sha256:<64hex> in the URL path. An object-store URL has no digest in it, so the key falls back to:

None => format!("{KEY_PREFIX}/url/{}", sha256_hex(canonical.key.as_bytes()))

Publishing, meanwhile, always uses the digest family (overlaybd-layer/v1/sha256:<digest>). So every foreground lookup misses by construction, and every read silently falls back to the origin registry.

This affects any registry that 307s blob GETs to object storage — Harbor+ceph, ECR+S3, GCR, ACR. UrlMode::SelfAuth registries are unaffected, which is why it does not show up in the unit tests.

Measured

Harbor 2.3.1 fronting ceph, 8 nodes, P2P on, one cold node with its remote-blocks block cache cleared so reads had to leave the machine:

agentenv_overlaybd_remote_read_duration_seconds_count{source="registry_p2p",...} 313
agentenv_overlaybd_remote_read_bytes_total{source="registry_p2p",...}            82051072

which looks like a success until you read the lookup keys in the log:

iroh::_events::conn::connected: side=Client remote_id=1729de4e20
  alpn=/agentenv/artifact-catalog/v1
  key=overlaybd-layer/v1/url/c78a1895ec45b4918e52e52fcc70359edbdbeb49b33e642490c219b1348ad7eb
  hints_len=0

10 distinct layers × 7 peers = 70 catalog connections, all on url/ keys, all missing against the peers' sha256: entries.

Two things that make this hard to see

1. source="registry_p2p" does not mean P2P served the read. metrics::registry_source labels by whether accelerate_address is non-empty, i.e. whether the request went through the facade. The facade's internal fallback to origin is still counted as registry_p2p. So the metric cannot distinguish "served by a peer" from "proxied to the registry".
2. A clean miss logs nothing. In handle_http_facade_result, a lookup_descriptor returning Ok(Ok(None)) falls through to fetch_origin_range_stream with no log line, and a hit logs nothing either. Only failures log. So neither success nor the interesting failure mode is observable at any log level.

Fix

The pre-redirect URL is available at the call site — it is the url argument to fetch_range_response. Pass it along on the accelerated request and let the facade key on it, while still fetching the fallback from the (presigned, unauthenticated) redirect target:

• registryfs_v2: send x-agentenv-origin-blob-url: {url} on accelerated range requests.
• facade: derive CanonicalBlobIdentity from that header when present, falling back to the request path.

The header is never forwarded to the origin (forwarded_headers only passes Authorization and User-Agent) and is never fetched, so it is a key hint only.

Also worth doing, separately: log the hit path, and either relabel or add a metric that distinguishes peer-served bytes from facade-proxied bytes.

<!-- gh-comment-id:5217138567 --> @dushulin commented on GitHub (Aug 7, 2026): Third defect, and this one is the reason P2P still served nothing after the first two were fixed: **the consumer and the publisher key the same layer differently whenever the registry redirects blob GETs to an object store.** ### What happens `registryfs_v2::fetch_range_response` resolves the blob URL first, then hands the accelerator the *post-redirect* URL: ```rust let raw_actual_url = match info.mode { UrlMode::Redirect => info.info.clone(), // <- the object-store URL UrlMode::SelfAuth => url.to_string(), }; if let Some(accelerated) = self.with_accelerate_url(&raw_actual_url) { ... } ``` `CanonicalBlobIdentity::from_origin_url` recovers the digest by looking for `sha256:<64hex>` in the URL path. An object-store URL has no digest in it, so the key falls back to: ```rust None => format!("{KEY_PREFIX}/url/{}", sha256_hex(canonical.key.as_bytes())) ``` Publishing, meanwhile, always uses the digest family (`overlaybd-layer/v1/sha256:<digest>`). So **every foreground lookup misses by construction**, and every read silently falls back to the origin registry. This affects any registry that 307s blob GETs to object storage — Harbor+ceph, ECR+S3, GCR, ACR. `UrlMode::SelfAuth` registries are unaffected, which is why it does not show up in the unit tests. ### Measured Harbor 2.3.1 fronting ceph, 8 nodes, P2P on, one cold node with its `remote-blocks` block cache cleared so reads had to leave the machine: ``` agentenv_overlaybd_remote_read_duration_seconds_count{source="registry_p2p",...} 313 agentenv_overlaybd_remote_read_bytes_total{source="registry_p2p",...} 82051072 ``` which looks like a success until you read the lookup keys in the log: ``` iroh::_events::conn::connected: side=Client remote_id=1729de4e20 alpn=/agentenv/artifact-catalog/v1 key=overlaybd-layer/v1/url/c78a1895ec45b4918e52e52fcc70359edbdbeb49b33e642490c219b1348ad7eb hints_len=0 ``` 10 distinct layers × 7 peers = 70 catalog connections, all on `url/` keys, all missing against the peers' `sha256:` entries. ### Two things that make this hard to see 1. **`source="registry_p2p"` does not mean P2P served the read.** `metrics::registry_source` labels by whether `accelerate_address` is non-empty, i.e. whether the request went *through* the facade. The facade's internal fallback to origin is still counted as `registry_p2p`. So the metric cannot distinguish "served by a peer" from "proxied to the registry". 2. **A clean miss logs nothing.** In `handle_http_facade_result`, a `lookup_descriptor` returning `Ok(Ok(None))` falls through to `fetch_origin_range_stream` with no log line, and a hit logs nothing either. Only failures log. So neither success nor the interesting failure mode is observable at any log level. ### Fix The pre-redirect URL is available at the call site — it is the `url` argument to `fetch_range_response`. Pass it along on the accelerated request and let the facade key on it, while still fetching the fallback from the (presigned, unauthenticated) redirect target: - `registryfs_v2`: send `x-agentenv-origin-blob-url: {url}` on accelerated range requests. - facade: derive `CanonicalBlobIdentity` from that header when present, falling back to the request path. The header is never forwarded to the origin (`forwarded_headers` only passes `Authorization` and `User-Agent`) and is never fetched, so it is a key hint only. Also worth doing, separately: log the hit path, and either relabel or add a metric that distinguishes peer-served bytes from facade-proxied bytes.

bsakaguchi commented 2026-10-29 14:18:48 +00:00

Author

Owner

Copy link

@yingdi-shan commented on GitHub (Aug 7, 2026):

Thanks for your contribution! Since P2P support is still experimental and hasn't been widely tested in production environments, your feedback is extremely valuable and will help us improve it significantly. We should probably also add a note to the documentation (or comments) to make users aware that the P2P feature is still experimental and its maturity is limited.

<!-- gh-comment-id:5217459032 --> @yingdi-shan commented on GitHub (Aug 7, 2026): Thanks for your contribution! Since P2P support is still experimental and hasn't been widely tested in production environments, your feedback is extremely valuable and will help us improve it significantly. We should probably also add a note to the documentation (or comments) to make users aware that the P2P feature is still experimental and its maturity is limited.

bsakaguchi commented 2026-10-29 14:18:48 +00:00

Author

Owner

Copy link

@dushulin commented on GitHub (Aug 7, 2026):

Fourth defect. With the first three fixed, most nodes served every read from a peer — but some cold creates still sent a burst of 57 range reads / 10 MB straight to the origin registry before P2P kicked in, and it was not reproducible on every node. Root cause: the accelerate address is only probed inside create_image_file, but remote_runtime is a OnceCell that any caller can initialize first.

What happens

enable_acceleration() is the only thing that probes the local P2P facade and flips accelerated:

// image_service.rs
pub async fn create_image_file(&self, ...) -> Result<ImageFile> {
    let _ = self.enable_acceleration();   // <- the ONLY probe site
    ...
}

build_remote_runtime() reads the address that probe produces:

async fn build_remote_runtime(&self) -> Result<RemoteRuntime> {
    let underlay_registryfs = RegistryFsV2::from_global_config(&self.inner.global_config)?;
    let addr = self.current_accelerate_address();   // "" if not probed yet
    underlay_registryfs.set_accelerate_address(addr);
    ...
}

and current_accelerate_address() returns "" while accelerated is still its false default.

Every open_*_blob_with_size path goes through remote_runtime().await? (get_or_try_init). So whichever caller touches remote_runtime first wins the OnceCell — and if that caller is not create_image_file, the shared RegistryFsV2 is built with an empty accelerate address. create_image_file probes a moment later and patches the address onto the already-built registryfs, so all subsequent reads are accelerated. The opening burst is not.

Measured

Cold create on one node, overlaybd::image::image_service=debug + overlaybd::backend::registryfs_v2=debug:

12:48:33.556863  building remote runtime  accelerate_address=        <- empty
12:48:33.731549  registry range read not accelerated  url=.../sha256:...  offset=0 count=262144
   ... 57 such lines, 12:48:33.731549 – 12:48:33.795091 ...
12:48:33.811271  p2p acceleration probe  accelerated=true            <- 255 ms too late

57 reads, 10,039,296 bytes, 31 distinct blobs, all at offset=0 — i.e. the layer index reads at the head of each blob, exactly the reads that decide how fast a cold create starts.

Why it looked flaky

A node that already holds a local .commit for every layer resolves the whole image locally and never calls remote_runtime() at all, so it shows a perfectly clean not-accelerated=0. Only nodes that actually have to leave the machine hit the window. That made this look like a per-node environment problem rather than an ordering bug.

Fix

Probe in build_remote_runtime rather than only in create_image_file. RegistryFsV2::from_global_config is constructed at exactly one site, so one line covers every caller:

 async fn build_remote_runtime(&self) -> Result<RemoteRuntime> {
     let underlay_registryfs = RegistryFsV2::from_global_config(&self.inner.global_config)?;
+    // Probe here, not only in `create_image_file`: whichever caller first
+    // touches `remote_runtime` wins the OnceCell, and an unprobed
+    // `accelerated` is false, which silently sends that caller's whole burst
+    // of layer index reads to the origin registry instead of to a peer.
+    self.enable_acceleration();
     let addr = self.current_accelerate_address();
     underlay_registryfs.set_accelerate_address(addr);

After the fix the same log shows the probe before the build:

13:43:17.049378  p2p acceleration probe  accelerated=true  runtime_initialized=false
13:43:17.049434  building remote runtime  accelerate_address=http://127.0.0.1:38167/p2p-http

Result with all four fixes

8 nodes, remote-blocks block cache cleared on every node, all pods restarted:

• 6 of 8 nodes served 100% of their remote reads from peers (263–357 reads / 68–89 MB each)
• zero source="registry_direct", zero registry range read not accelerated, zero falling back to origin
• p2p layer range served from peer line count matched the registry_p2p metric total (273/273, 357/357, 319/319, 263/263, 273/273; one node 321/327)
• logs clean: 0 closing database, 0 socket closed, 0 rebinding, 0 P2P ERROR

The remaining 2 nodes issued no remote reads at all because they hold local commits for every layer — they were the seeders the other six pulled from. Re-tested as consumers (local commits parked, block cache and P2P store wiped) they also served everything from peers: 354/357 and 100%.

Note on method: wiping both seeders at once briefly leaves the swarm with no seeder for the image, which looks exactly like a P2P failure. Retire one seeder at a time.

Two diagnostics worth keeping regardless of this fix

Neither of these existed, and without them none of the four defects was visible:

• debug!(%url, offset, count, "registry range read not accelerated") on the non-accelerated branch of fetch_range_response — this is what made this defect visible at all, and it is the only way to attribute a registry_direct metric to a concrete blob.
• debug!(accelerate_address, accelerated, runtime_initialized, ...) at both places that set the address — the pair that distinguishes an ordering bug from a dead facade.

---

Fifth defect, found while chasing the last few origin reads on a cold node: a lookup timeout is stored as a negative cache entry, so one transient overshoot demotes that whole layer to the origin registry for the miss TTL.

lookup_descriptor treats all three non-hit outcomes identically and falls through to the cache insert:

let descriptor = match tokio::time::timeout(state.lookup_timeout, state.transport.lookup(artifact_key)).await {
    Ok(Ok(descriptor)) => descriptor,
    Ok(Err(err)) => { debug!(...); None }
    Err(_)        => { debug!(... "p2p lookup timed out; treating as miss"); None }   // <-- cached
};
...
state.descriptor_cache.insert(artifact_key.clone(), descriptor.clone());

A timeout is "unknown", not "absent". DEFAULT_LOOKUP_TIMEOUT is 300 ms and DEFAULT_DESCRIPTOR_MISS_CACHE_TTL is 5 s — and a cold create's entire read burst completes in well under 5 s, so a single 300 ms overshoot on the first lookup for a layer sends every remaining read of that layer to the origin, silently (the cached-miss path logs nothing).

Measured

Cold node, no local commits, no block cache, empty P2P store, 7 healthy peers:

served from peer          336
p2p lookup timed out        2      <- 2 distinct layers
p2p range fetch failed      2
registry_p2p metric total  357

336 + 2 + 19 = 357. The 2 timeouts accounted for 19 reads, not 2: 2 initial plus 17 subsequent reads on those two now-negatively-cached layers. Both timeouts landed in the first 500 ms of the burst, when there is no scheduler hint yet and each lookup pays a fresh QUIC handshake against up to 7 peers — exactly when a 300 ms budget is most likely to be missed, and exactly when poisoning is most expensive.

A second run of the same node with a stable swarm served 100% from peers, 0 timeouts, 0 fallbacks — so this only bites the cold-start window, but the cold-start window is the whole point of P2P.

Fix

Don't cache the timeout branch:

     Err(_) => {
+        // A timeout is "unknown", not "absent" -- caching it would demote
+        // every remaining read of this layer to the origin registry for the
+        // whole miss TTL, which is longer than a cold create's read burst.
         debug!(
             key = %artifact_key,
             timeout_ms = state.lookup_timeout.as_millis(),
-            "p2p lookup timed out; treating as miss"
+            "p2p lookup timed out; retrying on next read rather than caching a miss"
         );
-        None
+        return None;
     }

Covered by a new test (lookup_timeouts_are_not_cached_as_misses): a lookup slower than lookup_timeout must leave the cache untouched, so the second read looks up again instead of going to the origin.

Worth considering separately, not changed here:

• Ok(Err(_)) is arguably also not evidence of absence, and is currently cached by lookup_errors_are_cached_as_short_misses on purpose. Same argument as the timeout, different risk profile.
• A cached miss serving a read logs nothing at any level, which is why 17 of these 19 reads were invisible. The hit path is equally silent.

<!-- gh-comment-id:5218154647 --> @dushulin commented on GitHub (Aug 7, 2026): Fourth defect. With the first three fixed, most nodes served every read from a peer — but some cold creates still sent a burst of **57 range reads / 10 MB straight to the origin registry** before P2P kicked in, and it was not reproducible on every node. Root cause: **the accelerate address is only probed inside `create_image_file`, but `remote_runtime` is a `OnceCell` that any caller can initialize first.** ### What happens `enable_acceleration()` is the only thing that probes the local P2P facade and flips `accelerated`: ```rust // image_service.rs pub async fn create_image_file(&self, ...) -> Result<ImageFile> { let _ = self.enable_acceleration(); // <- the ONLY probe site ... } ``` `build_remote_runtime()` reads the address that probe produces: ```rust async fn build_remote_runtime(&self) -> Result<RemoteRuntime> { let underlay_registryfs = RegistryFsV2::from_global_config(&self.inner.global_config)?; let addr = self.current_accelerate_address(); // "" if not probed yet underlay_registryfs.set_accelerate_address(addr); ... } ``` and `current_accelerate_address()` returns `""` while `accelerated` is still its `false` default. Every `open_*_blob_with_size` path goes through `remote_runtime().await?` (`get_or_try_init`). So whichever caller touches `remote_runtime` first wins the `OnceCell` — and if that caller is not `create_image_file`, the shared `RegistryFsV2` is built with an **empty** accelerate address. `create_image_file` probes a moment later and patches the address onto the already-built registryfs, so all *subsequent* reads are accelerated. The opening burst is not. ### Measured Cold create on one node, `overlaybd::image::image_service=debug` + `overlaybd::backend::registryfs_v2=debug`: ``` 12:48:33.556863 building remote runtime accelerate_address= <- empty 12:48:33.731549 registry range read not accelerated url=.../sha256:... offset=0 count=262144 ... 57 such lines, 12:48:33.731549 – 12:48:33.795091 ... 12:48:33.811271 p2p acceleration probe accelerated=true <- 255 ms too late ``` 57 reads, 10,039,296 bytes, 31 distinct blobs, all at `offset=0` — i.e. the layer index reads at the head of each blob, exactly the reads that decide how fast a cold create starts. ### Why it looked flaky A node that already holds a local `.commit` for every layer resolves the whole image locally and never calls `remote_runtime()` at all, so it shows a perfectly clean `not-accelerated=0`. Only nodes that actually have to leave the machine hit the window. That made this look like a per-node environment problem rather than an ordering bug. ### Fix Probe in `build_remote_runtime` rather than only in `create_image_file`. `RegistryFsV2::from_global_config` is constructed at exactly one site, so one line covers every caller: ```rust async fn build_remote_runtime(&self) -> Result<RemoteRuntime> { let underlay_registryfs = RegistryFsV2::from_global_config(&self.inner.global_config)?; + // Probe here, not only in `create_image_file`: whichever caller first + // touches `remote_runtime` wins the OnceCell, and an unprobed + // `accelerated` is false, which silently sends that caller's whole burst + // of layer index reads to the origin registry instead of to a peer. + self.enable_acceleration(); let addr = self.current_accelerate_address(); underlay_registryfs.set_accelerate_address(addr); ``` After the fix the same log shows the probe *before* the build: ``` 13:43:17.049378 p2p acceleration probe accelerated=true runtime_initialized=false 13:43:17.049434 building remote runtime accelerate_address=http://127.0.0.1:38167/p2p-http ``` ### Result with all four fixes 8 nodes, `remote-blocks` block cache cleared on every node, all pods restarted: - 6 of 8 nodes served **100%** of their remote reads from peers (263–357 reads / 68–89 MB each) - **zero** `source="registry_direct"`, **zero** `registry range read not accelerated`, **zero** `falling back to origin` - `p2p layer range served from peer` line count matched the `registry_p2p` metric total (273/273, 357/357, 319/319, 263/263, 273/273; one node 321/327) - logs clean: 0 `closing database`, 0 `socket closed`, 0 `rebinding`, 0 P2P `ERROR` The remaining 2 nodes issued no remote reads at all because they hold local commits for every layer — they were the seeders the other six pulled from. Re-tested as consumers (local commits parked, block cache and P2P store wiped) they also served everything from peers: 354/357 and 100%. Note on method: wiping *both* seeders at once briefly leaves the swarm with no seeder for the image, which looks exactly like a P2P failure. Retire one seeder at a time. ### Two diagnostics worth keeping regardless of this fix Neither of these existed, and without them none of the four defects was visible: - `debug!(%url, offset, count, "registry range read not accelerated")` on the non-accelerated branch of `fetch_range_response` — this is what made this defect visible at all, and it is the only way to attribute a `registry_direct` metric to a concrete blob. - `debug!(accelerate_address, accelerated, runtime_initialized, ...)` at both places that set the address — the pair that distinguishes an ordering bug from a dead facade. --- Fifth defect, found while chasing the last few origin reads on a cold node: **a lookup *timeout* is stored as a negative cache entry**, so one transient overshoot demotes that whole layer to the origin registry for the miss TTL. `lookup_descriptor` treats all three non-hit outcomes identically and falls through to the cache insert: ```rust let descriptor = match tokio::time::timeout(state.lookup_timeout, state.transport.lookup(artifact_key)).await { Ok(Ok(descriptor)) => descriptor, Ok(Err(err)) => { debug!(...); None } Err(_) => { debug!(... "p2p lookup timed out; treating as miss"); None } // <-- cached }; ... state.descriptor_cache.insert(artifact_key.clone(), descriptor.clone()); ``` A timeout is "unknown", not "absent". `DEFAULT_LOOKUP_TIMEOUT` is 300 ms and `DEFAULT_DESCRIPTOR_MISS_CACHE_TTL` is 5 s — and a cold create's entire read burst completes in well under 5 s, so a single 300 ms overshoot on the *first* lookup for a layer sends **every remaining read of that layer** to the origin, silently (the cached-miss path logs nothing). ### Measured Cold node, no local commits, no block cache, empty P2P store, 7 healthy peers: ``` served from peer 336 p2p lookup timed out 2 <- 2 distinct layers p2p range fetch failed 2 registry_p2p metric total 357 ``` 336 + 2 + 19 = 357. The 2 timeouts accounted for **19** reads, not 2: 2 initial plus 17 subsequent reads on those two now-negatively-cached layers. Both timeouts landed in the first 500 ms of the burst, when there is no scheduler hint yet and each lookup pays a fresh QUIC handshake against up to 7 peers — exactly when a 300 ms budget is most likely to be missed, and exactly when poisoning is most expensive. A second run of the same node with a stable swarm served **100% from peers, 0 timeouts, 0 fallbacks** — so this only bites the cold-start window, but the cold-start window is the whole point of P2P. ### Fix Don't cache the timeout branch: ```rust Err(_) => { + // A timeout is "unknown", not "absent" -- caching it would demote + // every remaining read of this layer to the origin registry for the + // whole miss TTL, which is longer than a cold create's read burst. debug!( key = %artifact_key, timeout_ms = state.lookup_timeout.as_millis(), - "p2p lookup timed out; treating as miss" + "p2p lookup timed out; retrying on next read rather than caching a miss" ); - None + return None; } ``` Covered by a new test (`lookup_timeouts_are_not_cached_as_misses`): a lookup slower than `lookup_timeout` must leave the cache untouched, so the second read looks up again instead of going to the origin. Worth considering separately, not changed here: - `Ok(Err(_))` is arguably also not evidence of absence, and is currently cached by `lookup_errors_are_cached_as_short_misses` on purpose. Same argument as the timeout, different risk profile. - A cached miss serving a read logs nothing at any level, which is why 17 of these 19 reads were invisible. The hit path is equally silent.

bsakaguchi referenced this issue 2026-10-29 14:20:07 +00:00

[PR #48] [MERGED] feat(sandbox): add Firecracker disk I/O rate limiting (bandwidth + IOPS) #138

Sign in to join this conversation.

No Branch/Tag specified

Branches Tags

main

coverage-data

gh-pages

v0.3.0-rc.1

v0.2.4

v0.2.3

v0.2.2

v0.2.1

v0.2.0

v0.1.3

v0.1.2

v0.1.1

v0.1.0

Labels

Clear labels   

bug

  

documentation

  

enhancement

  

enhancement

  

pull-request

Mirrored from GitHub Pull Request

No labels

bug

documentation

enhancement

enhancement

pull-request

Milestone

Clear milestone

No items

No milestone

Projects

Clear projects

No items

No project

Assignees

Clear assignees

No assignees

1 participant

Notifications

Subscribe

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

kvcache-ai/AgentENV#46

No description provided.