swactor/examples/pipeline-parallel-inference/N3_POSTMORTEM_2026-05-25_1779733878.md

# N=3 vast.ai deployment post-mortem — 2026-05-25 (run `1779733878`)

Second N=3 deployment of 2026-05-25, and the **first run on the
observability upgrade** (commit `e8be135`, the work specified in
`N3_OBSERVABILITY_UPGRADE_SPEC.md` and motivated by
`N3_DATA_GAPS.md`). Companion to the earlier post-mortem
`N3_POSTMORTEM_2026-05-25.md` (run `1779720002`), whose failure this
deployment was meant to (a) avoid and (b) make diagnosable.

One invocation of `pp-smoke-run --vastai --num-stages 3` (stub worker)
on 2026-05-25 (`vastai-N3-1779733878`). The cluster came up cleanly,
all three stage workers reached `ready`, the request was sent — and
then SWIM membership flapped continuously and no `InferenceResponse`
ever returned. The operator declared a deadstop at ~7 min and killed
the orchestrator. Unlike last time, the bundle was recovered through
the collector's own endpoint (gap 7), and the new diagnostics
**attributed the failure to a specific edge**: the response path from
the last stage back to the (NAT'd, locally-run) orchestrator.

## Outcome in one line

Not a worker bug and not the relay-session loss of run `1779720002`.
The stage chain was healthy; the weak link was reaching the
orchestrator over the relay. Per-peer dial data (gap 9) shows dials
**to the orchestrator failing 7/11 with `Timeout`** while every
inter-stage dial succeeded (19/19). This was indistinguishable in the
previous bundle and is a one-table answer now.

## Cleanup note

The run was terminated with `SIGTERM` (operator kill on deadstop),
which — like the previous `SIGKILL` — skips the orchestrator's
destroy-on-exit handler. Three rentals (`37803546`, `37803550`,
`37803555`) were destroyed via `DELETE /api/v0/instances/<id>/`
(HTTP 200 each). Post-cleanup instance count = 0, verified. No leak
from the earlier failed lease attempt either (see Sequence).

## Sequence

Orchestrator runs locally (behind home NAT, no direct port); three
stages on vast.ai RTX 4090 hosts; relay + collector on docean
(`146.190.110.128`).

```
t=—      first launch dies instantly: lease_chain failed,
         "no offers available (after geo/exclusion filter)".
         Root cause: --gpu RTX_4090 (underscore) matches 0 vast.ai
         offers; the API uses "RTX 4090" (space). 0 instances leased.
t=0      relaunch with --gpu "RTX 4090": orchestrator node 146aef53,
         custom-relay banner emitted.
t=~135s  contracts 37803546/37803550/37803555 reach running,
         leased as stage-0 (aa0ef1c5), stage-1 (32abf9d6),
         stage-2 (a1ebaa08).
         "waiting for SWIM convergence (3 alive)" → converges.
t=~150s  registered pp-orchestrator; pp-entry resolved; one
         InferenceRequest sent. Enter await_response (600s budget).
t=~165s+ SWIM begins flapping. Members oscillate, e.g.:
           +63s : 32abf9d6=suspect
           +79s : 32abf9d6=dead, a1ebaa08=dead
           +94s : 32abf9d6=dead (others alive)
           +194s: 32abf9d6=dead, a1ebaa08=suspect
           +216s: aa0ef1c5=suspect
         iroh keeps exchanging messages throughout; connect-timeout
         count to peers is 0 (contrast 1779720002).
t=~419s  await_response still open, members momentarily all-alive,
         still no InferenceResponse.
t≈7min   operator declares deadstop (a peer Dead across two
         consecutive 45s heartbeats with zero forward progress),
         kills orchestrator (SIGTERM). No finalize record written.
```

## Bundle recovery (gap 7 — worked, with a caveat)

`GET /diag/bundle/vastai-N3-1779733878` returned **HTTP 200** with a
usable tarball — no hand tar/scp/reshape, unlike last time. The
gap-7 synthesis-from-staging path is the intended fix and it
functioned.

Caveat surfaced by this run: the run id was **reused across the
failed first lease attempt**. That attempt's orchestrator
(`e8151ed8`) called `finalize("lease_chain_error")`, which made the
collector build and cache a tiny (5.3 KB) canonical bundle from the
staging that existed *at that moment* — orchestrator + relay only, no
stages. Because `finalize_received` was then true, the first `GET`
served that **stale canonical bundle** rather than synthesizing from
current staging. Removing the cached bundle and the junk `e8151ed8`
node forced re-synthesis → full **9.3 MB** bundle with all five real
nodes. Two residual quirks observed even after removal:

- `finalize_received` stayed `true` (the collector retains an
  in-memory finalize record that outlives deletion of the on-disk
  `finalize-*.json`).
- the synthesized `MANIFEST.json` still listed the deleted `e8151ed8`
  node (with `finalize_recorded: true`) although no such directory
  was in the tarball.

Neither blocked analysis, but both are worth hardening: gap-7 assumed
finalize == end-of-run, and run-id reuse breaks that assumption.

## Bundle findings

### Volume

| node                       | role         | snapshots | events |
|----------------------------|--------------|-----------|--------|
| `146aef53` orchestrator    | orchestrator | 409       | 4385   |
| `1c8357a1` relay (docean)  | relay        | 186       | 187    |
| `aa0ef1c5` stage-0         | stage        | 771       | 8638   |
| `32abf9d6` stage-1         | stage        | 305       | 3234   |
| `a1ebaa08` stage-2         | stage        | 535       | 5963   |

`run_start_ms=1779734098442`, `run_end_ms=1779735024439`
(`duration_ms=925997`; the tail includes the relay's continued
periodic reporting after the orchestrator died — the relay on docean
is still pinned to this run id, see Infra state).

### Subprocess lifecycle (gap 4) — decisive

`SubprocessSpawned: 3`. `Custom(worker_starting): 3`,
`Custom(worker_ready): 3`, `Custom(worker_heartbeat): 37`. No
`SubprocessExited`.

**All three stage workers spawned and became ready and stayed up.**
This is the single fact the `1779720002` bundle could not establish
(there, stage-2 emitted neither `worker_starting` nor `worker_ready`,
and we could not tell "never spawned" from "spawned and died"). The
worker is conclusively ruled out as the cause this time.

### Per-peer dials (gap 9) — the attribution

Totals: `started=50, succeeded=42, failed=7, in-flight=1`.

| peer                  | started | ok | failed | in-flight | last_outcome | at_ms          |
|-----------------------|---------|----|--------|-----------|--------------|----------------|
| orchestrator-146aef53 | 11      | 3  | **7**  | 1         | **Timeout**  | 1779734955567  |
| stage-0 (aa0ef1c5)    | 1       | 1  | 0      | 0         | Success      | 1779734410397  |
| stage-1 (32abf9d6)    | 19      | 19 | 0      | 0         | Success      | 1779734518356  |
| stage-2 (a1ebaa08)    | 19      | 19 | 0      | 0         | Success      | 1779734522415  |

Every dial *between stages* succeeded. Only dials *to the
orchestrator* failed, and they failed by timeout. The last stage's
`InferenceResponse` is addressed to the orchestrator's inbox; if it
cannot dial the orchestrator, the response never lands. This table is
the proximate cause of the empty result.

### Relay-session field (gap 2) and conn type

stage-2's latest snapshot `body.iroh.relay_session`:

```
relay_url:           http://146.190.110.128:7843/
status:              connected
status_changed_at_ms:1779734401024
status_entered_at_ms:1779734401024
status_source:       derived
```

The tunnel to the relay was **connected**, with `status_source:
derived` honestly flagging that iroh does not expose this natively
(per spec §2). So the failure is *not* "tunnel died" — it is "tunnel
alive, peer-connection-through-tunnel to the orchestrator dead." That
distinction was the explicit acceptance criterion for gap 2, and it
holds here.

`First peer to go Dead`: stage-2 marked stage-1 (`32abf9d6`) Dead at
`t=1779734428439`, reason `suspicion-timeout`. Both sides
`conn_type=Relay` (no direct hole-punch anywhere in the run). Observer
`probes_ok=yes`, peer `probes_ok=no`.

### SWIM churn and relay events (gap 3)

`SwimTransition: 1701` over a ~7-minute run — heavy flapping,
consistent with the relay-mediated reachability of a NAT'd
orchestrator and the §10.3 self-incarnation flap (see
`SWIM_TUNING_REPORT`). `RelaySessionStateChanged: 8`, `RelayChanged:
4`, `IrohConnTypeChanged: 8` — relay/transport flips are now on the
event stream, not just counter deltas.

### Kernel network drops (gap 11)

`udp.no_ports` delta across the run:

| node              | udp.no_ports |
|-------------------|--------------|
| orchestrator      | +1           |
| stage-0           | +139         |
| stage-1           | +134         |
| stage-2           | **+1424**    |

stage-2 took ~10× the no-listening-port UDP drops of its siblings —
an interface-level corroboration of localized relay/hole-punch path
instability, surfaced automatically in the summary.

### Gossip receipts (gap 10)

| node         | swim_piggyback | bytes  | items |
|--------------|----------------|--------|-------|
| orchestrator | 806            | 263825 | 1607  |
| stage-0      | 1589           | 522855 | 3178  |
| stage-1      | 563            | 194236 | 1183  |
| stage-2      | 1082           | 340115 | 2069  |

Every node received gossip. Gossip starvation is ruled out — the
flap is not "a node never heard membership," it is "membership churned
because the underlying relay path to a peer was unreliable."

### UDP echo probes (collector tier-2)

| node         | result                          |
|--------------|---------------------------------|
| orchestrator | ok, rtt=293 ms, 34/35           |
| stage-0      | ok, rtt=181 ms, 55/55           |
| stage-1      | ok, rtt=405 ms, 27/28           |
| stage-2      | ok, rtt=184 ms, 38/38           |

All nodes had clean tier-2 reachability to docean:9081 — i.e. the
hosts themselves were on the network. The failure was at the iroh
peer-connection layer, not raw host reachability.

### iroh version honesty (gap 6)

`iroh_version: "0.98.2"` on every node and in every
`iroh_api_missing` event (4 total) — matches `Cargo.lock`. The
hard-coded `"0.96"` literal from `1779720002` is gone. The API-gap
list now also carries the `RelayTunnel.*` derived-field markers.

## Observability upgrade scorecard

What this run confirms the upgrade delivers, versus what it doesn't:

| gap | status | evidence |
|-----|--------|----------|
| 2 relay-session field        | ✅ | `relay_session.status=connected, status_source=derived` |
| 3 relay events               | ✅ | `RelaySessionStateChanged: 8`, `RelayChanged: 4` |
| 4 subprocess introspector    | ✅ | `SubprocessSpawned: 3`; worker ruled out |
| 6 iroh version honesty       | ✅ | `0.98.2` everywhere, lockfile match |
| 7 bundle without finalize    | ✅¹ | `GET` returned a usable 9.3 MB bundle; ¹run-id reuse exposed stale-canonical serve + sticky finalize flag |
| 9 per-peer dials             | ✅ | the orchestrator-reachability table (the headline finding) |
| 10 gossip receipts           | ✅ | per-node `swim_piggyback` breakdown |
| 11 kernel counters           | ✅ | stage-2 `udp.no_ports +1424` surfaced |
| 1 relay observability        | ◐ | relay reports identity + 186 snapshots, but per-session lifecycle is the documented skeleton: `active=0 opens=0 closes=0` (iroh-relay exposes no session hooks) |
| 5 host metadata              | ◐ | `container_id`/`hostname`/`git_sha`/`iroh_version`/`binary_version` present; `host_ip_public`/`datacenter_id`/`host_country`/`vastai_contract_id` still **null** — provider fields not forwarded. (The contract id does arrive, but in `container_id`, not `vastai_contract_id`.) |
| 8 relay-port probe           | ✗ | not present: stage probe arrays carry only `collector_udp_echo` (:9081); no relay-port (:7843) probe |

A+B+C (the tiers the previous investigation needed) all landed and
were load-bearing here. The polish/robustness tiers (5 ip/dc/country,
7 finalize edge cases, 8 relay probe, 1 relay session lifecycle) have
remaining work.

## Data-collection / deployment gaps surfaced by this run

1. **Host provider fields not forwarded (gap 5 incomplete).** The
   orchestrator has each rental's public IP, datacenter, country, and
   contract id at `lease_chain` return, but only the docker container
   id (landing in `container_id`) and hostname reach the boot record.
   `host_ip_public`/`datacenter_id`/`host_country`/`vastai_contract_id`
   /`home_relay_url_at_boot` are still null. "Which rental was
   stage-2" is answerable only via the `container_id`↔contract map,
   not the dedicated fields.

2. **gap-7 stale-canonical serve on run-id reuse.** A finalize from an
   earlier phase of the same run id pins a stale cached bundle, and
   `finalize_received` is sticky in collector memory across staging
   deletion. Serve logic should prefer the richer of {canonical,
   synthesized-from-current-staging} or rebuild canonical when staging
   has grown past the cached bundle.

3. **No relay-port reachability probe (gap 8 absent).** Whether
   stage-2 could reach docean:7843 (the relay) at moment T is still
   inferred from a different port (:9081 echo). The exact gap the
   previous post-mortem flagged remains open.

4. **Relay per-session lifecycle still skeleton (gap 1).** The relay
   reports into the bundle but cannot yet say "who closed session X
   and why" because `iroh_relay::server` exposes no session hooks.
   Until it does, "was this a relay-side eviction" is unanswerable
   from the relay side; we relied on node-side dial outcomes instead.

5. **No response-leg instrumentation.** The conclusion "last stage
   could not deliver the response" was inferred from dial timeouts +
   absence of an inbound response, not from a typed event on the last
   stage ("attempted to send InferenceResponse to orchestrator,
   outcome=…"). A response-send event would make this a direct read
   rather than an inference.

6. **Environmental: orchestrator topology is the root cause.** A
   locally-run, NAT'd orchestrator with no direct port is reachable
   only via the relay, and the relay path to it proved unreliable
   under load (7/11 inbound dials timed out, 1701 SWIM transitions).
   Running the orchestrator on a reachable host (e.g. docean) or
   giving it a direct/forwarded port is the likely fix to test next.

7. **`DEPLOYMENT_TEST.md` GPU flag is wrong.** Line 84 shows
   `--gpu RTX_4090`; vast.ai matches `gpu_name` literally and the
   underscore form returns 0 offers. The orchestrator's own default
   is the correct `"RTX 4090"`. Fix the runbook example.

## Artifacts

In `.vastai-logs/` (gitignored) after recovery:

```
vastai-N3-1779733878.bundle.tar.gz        full synthesized bundle (9.3 MB, 5 nodes)
vastai-N3-1779733878.staging-full.tar.gz  raw collector staging backup (~10 MB)
vastai-N3-1779733878.tar.gz               the stale 5.3 KB canonical bundle (kept for reference)
vastai-N3-1779733878.log                  orchestrator stdout (both launch attempts)
vastai-N3-1779733878.out/summary.md       postproc summary
vastai-N3-1779733878.out/reachability.tsv
vastai-N3-1779733878.out/timeline-*.tsv   per-link timelines
```

Staging copy retained on docean at
`/var/lib/swactor-diag/vastai-N3-1779733878/` (minus the removed
`e8151ed8` junk node).

## Infrastructure state at end of session

- docean (`146.190.110.128`): collector and relay running (rebuilt
  static-musl binaries from `e8be135`). The relay is **still pinned to
  `SWACTOR_DIAG_RUN_ID=vastai-N3-1779733878`** and continues appending
  periodic snapshots to that run's staging; the next run's redeploy
  re-pins it. Re-pulling the bundle later will include those extra
  relay snapshots.
- vast.ai instances under `$VAST_API_KEY`: **0** (verified).