Nostr DM delivery flakiness across CLI process boundaries (intermittent receiver miss)

[vrogojin]

Filing as a focused follow-up to #455 / #464 / #465. The mux dispatch await fix (PR #465) closed the in-process race where receive() resolved before handleIncomingTransfer completed. A separate cross-process race remains, surfaced during the sphere-sdk#456 swap-roundtrip soak (2026-06-10).

Symptom

In manual-test-swap-roundtrip.sh Scenario A:

1. Alice spawns a CLI process, runs sphere swap propose --to @bob --offer 50 UCT --want 5 ETH --escrow @escrow-test-02. The proposal returns status: proposed. Alice's process exits.
2. Bob spawns a fresh CLI process, runs sphere swap list --role acceptor. Returns "No swaps found".
3. Bob's soak loop polls every 3 s (each iteration a fresh CLI process, fresh sphere instance) for up to 90 s.
4. Intermittently: bob never sees the proposal. 90 s timeout fires.

Same soak retried within the next minute: passes cleanly.

Same class of flakiness was already observed in #455 (single-coin faucet) and root-caused there to the in-process mux-dispatch await gap — that fix is necessary but is not sufficient for the cross-process case.

Why it's bad

This is the canonical handoff shape for any CLI-driven swap, accounting, or DM workflow:

• A → B handoff via Nostr DM, where A's process exits between send and B's first poll.
• Multi-step soaks where each section is a separate CLI invocation.
• Real users running sphere ad-hoc from a terminal (`sphere swap propose ...; sphere swap list` in a script).
• Background daemons that batch-poll on a timer rather than holding a long-running subscription.

Anything that depends on "the receiver's next poll catches the sender's last write" is fragile under this race.

Likely contributing mechanisms

These overlap and stack — no single hypothesis fully explains the observed pattern. Investigation should distinguish.

M1. `since` cursor advances before delivery.
`NostrTransportProvider` persists `last_wallet_event_ts` / `last_dm_event_ts` per pubkey prefix. On reconnect, the next subscription's `since` filter starts from that timestamp. A receiver whose previous boot saw events up to T1 will not re-fetch events with `created_at < T1`. If a sender's DM was published at T0 but the receiver advanced past T0 before processing it (or the relay's clock drift puts T0 in the future at write time and the receiver's now-clock has moved past it), the DM is permanently invisible to this receiver on the relay's `since`-filtered subscription.

M2. NIP-17 ±2-day created_at randomization vs since filter.
NIP-17 gift-wrap (kind 1059) deliberately randomizes `created_at` by ±2 days for sender privacy (`transport/MultiAddressTransportMux.ts:986+`). The mux compensates by using `globalDmSince - NIP17_TIMESTAMP_RANDOMIZATION` for chat subscriptions, but only if the persisted dmSince includes that buffer. Fresh CLI boots may compute since=now without that look-back, missing recent DMs whose randomized `created_at` already advanced past now.

M3. Subscription armed AFTER the relay's "since now" cutoff.
The mux gate (issue #442 fix) suppresses subscriptions until armSubscriptions() runs after module load. For a fresh CLI boot:

• `now_at_subscribe = T_arm` is some milliseconds-to-seconds after `now_at_init`.
• The relay receives `since=T_subscribe` and returns events with `created_at >= T_subscribe`.
• Any DM published between `T_subscribe` and the relay applying the filter is in a microscopic but real race window.

M4. EOSE delivered before backlog drained.
Some relays send EOSE optimistically. The receiver's `fetchPendingEvents` wait loop may resolve on EOSE while the relay is still streaming buffered events. Subsequent events arrive but the receiver has already returned to caller ("No swaps found").

M5. Relay event retention / propagation.
Public testnet relay may evict recent events under load, or have multi-replica state that hasn't converged. A sender's write to replica A may not be visible to a receiver's read from replica B within the polling window.

What we know

• PR fix(transport)(sphere-sdk#464): mux dispatch await gap #465 (mux dispatch await) is merged on main and the CLI's bundled SDK has it. It fixes the in-process variant but not the cross-process one.
• The escrow's own DM handling (which is also Nostr-based) always works in the soak — pings, swap announces, deposits all land. Difference: the escrow holds a long-running subscription rather than re-booting per operation.
• A bob CLI invocation that runs `sphere payments sync` first does NOT always recover. The poll loop retries every 3 s and still misses.

Suggested investigation

1. Reproduce deterministically. Wrap the soak's bob-poll loop in a script that captures: per-iteration since timestamp, subscription filter wire payload, EOSE timing, and raw event count returned. Run alice in a fresh shell, capture her DM's `created_at`. Diff against bob's per-iteration since cursor.

2. Instrument NostrTransportProvider. Add [Nostr] subscribe filter={...} since=N and [Nostr] eose_received traces visible at `DEBUG=Nostr`. The mux already has `logger.debug('Mux', 'updateSubscriptions...')` — extend to log filter wire bytes.

3. Test each mechanism in isolation.

   • M1: drive the receiver with an explicit `since=0` filter and see if the missed DMs reappear.
   • M2: bump the chat subscription's look-back buffer by 10× and re-run; does flakiness drop?
   • M3: measure `T_subscribe - T_send` distribution; correlate with miss rate.
   • M4: count events received post-EOSE; if non-zero on miss runs, the mux is closing the wait window too early.
   • M5: query the same DM event from two different SDK instances back-to-back, with relay-side timestamps. If only one sees it, it's a replica / retention issue.

4. Fix candidates (depending on which mechanism wins):

   • For M1/M3: persist `since = T_subscribe - K` for some K (e.g. 5 minutes) instead of `= T_subscribe`, accepting one tier of duplicate event processing.
   • For M2: increase the chat look-back constant; the SDK already has a NIP-17 buffer but it may be too tight.
   • For M4: wait for first event or N seconds, whichever later, instead of EOSE alone.
   • For M5: query multiple relays and union. Today the mux subscribes via a single `NostrClient` per relay; a quorum-of-N approach would mask single-relay state divergence.

Acceptance

• 10 consecutive successful runs of `manual-test-swap-roundtrip.sh` Scenario A against testnet with no retries.
• A unit/integration test that simulates the sender-exits-then-receiver-boots flow with a mock relay that has clock skew + delayed event propagation, and asserts the receiver still sees the DM within a documented bound.
• Operator-facing documentation: any soak / CLI workflow that depends on cross-process DM handoff has a known retry contract (e.g. "poll for up to N seconds with a since-buffer of M seconds").

Related

• Investigate single-coin faucet flakiness — service-side or SDK-side? #455 — single-coin faucet flakiness (closed via PR docs(uxf)(sphere-sdk#455): investigation of single-coin faucet flakiness #462 investigation + fix(transport)(sphere-sdk#464): mux dispatch await gap #465 fix; in-process variant only)
• transport(mux): MuxAdapter.dispatchTokenTransfer (and siblings) discard async-handler Promise — receive() resolves before handleIncomingTransfer completes #464 — mux dispatch await gap (closed via PR fix(transport)(sphere-sdk#464): mux dispatch await gap #465)
• Register all module DM handlers BEFORE Nostr subscription opens (cross-process delivery gap) #442 / fix(transport)(sphere-sdk#442): gate mux relay sub until module handlers register #443 — mux subscription gating
• @escrow-testnet nametag does not resolve on testnet relay (swap soak blocked) #456 — escrow nametag rotation; the soak that surfaced this issue at PR-time

Workaround for soaks until this lands

`manual-test-swap-roundtrip.sh` Scenario A passes on retry within ~1 min. Soaks can wrap the bob-poll section in a retry loop with a max-retry count. This is a band-aid — the underlying flakiness needs a real fix because real users do not retry.

[vrogojin]

PR #476 ships the smallest defensive fix for this.

Root cause (full investigation lives at docs/uxf/ISSUE-473-INVESTIGATION.md on feat/474-trader-roundtrip-soak, opened as PR #475): M1 is BLOCKING. MultiAddressTransportMux.routeGiftWrap advances lastDmEventTs to wall-clock-now the moment NIP17.unwrap succeeds, BEFORE the async dispatch chain (AddressTransportAdapter.dispatchMessage → SwapModule.handleIncomingDM, AccountingModule, etc.) runs to completion. CLI exits during the soak's 3-second poll loop kill the handler mid-flight; the cursor advance persists; the relay's since-filtered subscription excludes the event on every subsequent boot. The chat filter's -NIP17_TIMESTAMP_RANDOMIZATION buffer only catches the publish-time-to-cursor-advance gap, NOT the cursor-advance-to-handler-completion gap.

Ranking of the 5 mechanisms:

• M1 BLOCKING — cursor advance past created_at (root cause)
• M2 UNLIKELY — NIP-17 ±2-day randomization (chat filter already applies the buffer; wallet events go through same path)
• M3 UNLIKELY — Sub uses since = lastDmTs - buffer, not since = now
• M4 CONTRIBUTORY as the EOSE-before-handler-completion derivative; same fix addresses it
• M5 INCONCLUSIVE — relay state divergence; out of scope (would need quorum-of-N reads)

Fix in #476:

1. routeGiftWrap restructured into per-address unwrap → try/finally with a dispatched flag. Cursor advance fires only inside the finally, after a terminal dispatch branch sets dispatched = true. The persistent processedEventIds dedup (perf: cross-process Nostr dedup persistence (#274 follow-up — 71% of §C runtime is duplicate dispatch) #275) absorbs any re-delivery from the look-back window.
2. Chat subscription look-back buffer doubled (Mux:998 + NostrTransportProvider:3152). Belt-and-braces against residual clock skew + relay propagation lag.

All four existing Mux test suites pass (39/39). Acceptance bar: 10 consecutive manual-test-swap-roundtrip.sh Scenario A runs with zero proposal-ingest-timeout retries.

A deterministic unit test for the cursor-advance ordering requires heavy Mux + NIP17 fixture plumbing; deferred as a small follow-up. The diff is small enough for review by eye, and the soak loop is the canonical signal.

[vrogojin]

Cross-link: filed #555 covering the per-run-amplification side of this story observed during PR #552 soak verification on 2026-06-15. The §4 ACP probe latency grew monotonically across 4 consecutive soak runs (3:04 → 3:27 → 3:21 → 6:22) on the same testnet — too consistent for the pure-cursor-race story in this issue alone. The hypothesis there is that the §4 retry loop (one fresh CLI process per 5s tick) floods the relay with kind-1059 NIP-17 events that linger thanks to the ±2-day created_at randomization, amplifying the M1/M2 races filed here. Tagging here so the two surfaces stay linked.

[trcevalker]

Real-world confirmation from a live testnet2 dApp

Filing this as additional evidence — we hit exactly this symptom in production on a live dApp (a betting game where a persistent Node.js bot pays out winnings to players' browser-connected Sphere Wallets over payments.send()), and spent a long debugging session ruling out everything else before concluding it matches #473.

Setup: bot = persistent Node.js Sphere instance (createNodeProviders, @unicitylabs/sphere-sdk@0.10.1), always subscribed. Recipient = a real player connected via the Sphere Wallet popup flow (autoConnect()), not the browser extension.

Symptom: payments.send() reliably resolves status: "completed" (aggregator-certified), but the amount never appears in the recipient's wallet balance/history, even when the player keeps the tab open and actively watches for 90+ seconds, and even when we call the receive intent explicitly before each balance check.

What we ruled out before landing on this issue (each independently verified against real testnet2):

• Sender identity — bypassed our whole app and sent directly from the bot's real mnemonic straight to the player's @nametag; still didn't arrive.
• Recipient encoding — tried @nametag, the resolved chainPubkey (66-hex, compressed), the stripped 64-hex transportPubkey, and directAddress. All four resolve correctly via sphere.resolve() and all four deliver correctly to a live Node.js recipient in a controlled test — the encoding itself is fine.
• Network — confirmed via client.walletNetwork that the connected wallet reports {id: 4} (testnet2), matching what we send on.
• Relay — diffed the Sphere Wallet webapp's own bundle against our bot's config: both resolve to the same default TEST_NOSTR_RELAYS = ["wss://nostr-relay.testnet.unicity.network"], no override on either side.
• Predicate type — compared against state-transition-sdk's own tests/examples/transfer/ExampleTest.ts: both our code and the reference use SignaturePredicate, not Masked/Unmasked — no discrepancy.
• coinId — sourced live from the recipient's own sphere_getBalance response, matches what their wallet already displays for existing balance.
• SDK version — reproduced the same non-delivery sending via 0.11.3 as well as our pinned 0.10.1 (can't independently confirm the fix side since I don't hold the test recipient's keys, but the send-side behavior — status: completed, no error — was identical on both versions).

Two live-recipient controlled tests, for contrast: a bare createNodeProviders sender and receiver in the same script, both freshly generated, reliably deliver instantly when the receiver is continuously live. The same sender→offline-then-reconnected receiver (destroy + fresh Sphere.init from the same data dir) never recovers the transfer, even calling payments.receive() explicitly on reconnect ({ transfers: [] }). This matches #223/#464's "same-process works, cross-process doesn't" pattern exactly, and matches this issue's framing that PR #465 fixed the in-process race but not the cross-process one.

Given the real Sphere Wallet (not just a bare SDK instance) shows the identical failure mode against a continuously-live sender, this looks like the live production-impact case #473 is asking for. Happy to share full repro scripts/logs if useful — everything above was run against real testnet2, not a mock.