Fresh-wallet chat-subscription backlog + sendDM resolve outlier (follow-up to #555)

[vrogojin]

Follow-up to #555 filed after running the M9 diagnostic patch against the trader soak on 2026-06-15.

TL;DR

• M9 (EARLY_MESSAGE_CAP=32 silent drop) is RULED OUT as a §4 failure mechanism. The cap was nowhere near being hit on any ACP DM call across an entire soak (peak buffered=14/32, drops=0/0 across 8 measured calls).
• §4 failure is non-deterministic across runs. Three consecutive trader soaks on the same machine: 2 failed §4, 1 passed §4 cleanly — with no code change between the failing-2 and passing-1. This is consistent with the relay-state-pressure framing in Nostr relay degradation across consecutive trader-soak runs — retry-loop flooding hypothesis + amplification of #473 #555, not a deterministic SDK bug.
• A new anomaly surfaced that wasn't in Nostr relay degradation across consecutive trader-soak runs — retry-loop flooding hypothesis + amplification of #473 #555's M1–M7: every fresh CLI invocation sees 3–14 NIP-17 gift-wrap events arrive on its chat subscription within 140–900 ms of subscribe, on a brand-new wallet whose #p filter should match nothing in the relay's index. The decoded DMs sit in the early-message buffer until sendDM resolves resolvedPubkey. This isn't the §4 cause but it's relay-side noise that needs explaining.

Diagnostic patch used

Temporary instrumentation in sphere-cli/src/trader/acp-transport.ts (not landed). On every acp.command send:

• [acp-m9] resolvedPubkey set t+Nms, buffered=K/32 dropCount=0 command=X — fires when sendDM resolves, recording the resolve window and how many backlog DMs were buffered during it.
• [acp-m9] early-message cap reached t+Nms, ... — fires when earlyMessages.length === EARLY_MESSAGE_CAP (silent-drop path).

Patch lives at the head of AcpDmTransportImpl.handleIncoming and inside the comms.sendDM(...).then((sent) => ...) callback. Easy to re-apply if needed — see #558 for the SDK side.

Data from one full soak (8 ACP DM calls)

Section	Caller	Command	resolve t+ms	buffered/32	dropCount
§3 spawn	alice	SET_STRATEGY	142	4	0
§3 spawn	bob	SET_STRATEGY	198	3	0
§4 probe	alice	GET_PORTFOLIO	886	11	0
§4 probe	bob	GET_PORTFOLIO	147	4	0
§5 pre	alice	GET_PORTFOLIO	136	12	0
§5 pre	bob	GET_PORTFOLIO	150	5	0
§6 sell	alice	CREATE_INTENT	144	14	0
§7 buy	bob	CREATE_INTENT	145	7	0

(Snapshot dir preserved at /tmp/trader-roundtrip-2967836/ via KEEP=1 for reference. Raw [acp-m9] lines are in each snapshots/*-acp-probe.log and the per-command snapshots.)

What ruled out

• M9 silent-drop. Cap=32, observed peak=14/32 (44 %). Even if the run-1 failure had been the failing condition, the cap was untouched. Drop this from the active hypothesis list.

What remains open

A) Fresh-wallet backlog anomaly (NEW)

Every fresh CLI process — fresh wallet, fresh #p filter — finds 3–14 NIP-17 gift-wrap events arriving on the chat subscription within ~200 ms of subscribe. The decoded events make it through the receiver's NIP-17 unwrap (otherwise they wouldn't reach handleIncoming), so each successfully decrypted to something targeting this controller's transport pubkey.

For a brand-new pubkey there should be nothing matching on the relay. Possibilities:

1. Relay filter looseness. The testnet relay may be returning kind=1059 events that don't actually match #p:[fresh_pubkey] — for example, by widening the filter under load, or because the #p index isn't applied before the since window. Cheap to verify with nostr-tool sub --kinds 1059 --p <fresh_pubkey> against the same relay from a clean Node script — should return 0 events; if it returns N, that's the bug.
2. Tenant or escrow side-channel publishes. Something in the spawned stack (HM-tenant ACK, hello, escrow ping, market-API DMs) is publishing kind-1059 events targeting the fresh controller pubkey before the controller even sends its first DM. Plausible since the controller's pubkey is in trader spawn metadata.
3. HD-derivation collision. The wallet generates multiple addresses and adds all transport pubkeys to allPubkeys for the chat subscription. If any of these derivations collide with previously-used pubkeys on the relay (BIP-32 path reuse, tenant key derivation overlap, etc.), the filter would match historical events. Less likely but worth checking by counting how many distinct senderPubkeys appear in the buffered messages.

The anomaly doesn't break §4 — the buffer drains cleanly when resolvedPubkey resolves and the sender filter throws out anything that isn't the tenant — but it does mean the buffer is starting each session at 30–40 % full of something, which materially shifts the headroom for the EARLY_MESSAGE_CAP discussion above.

B) The 886 ms resolve outlier

Alice's first §4 ACP probe took 886 ms to resolve sendDM, vs 136–198 ms for every other call in the same soak. All other calls (including bob's same-section probe) clustered at 142–198 ms. Hypotheses:

1. Nametag resolution cache cold-start. sendDM resolves @tenant_nt → tenant pubkey via NostrTransportProvider.resolveNametagInfo which issues a separate REQ on the same socket. First-ever @tenant resolution on a fresh wallet should cost one extra round-trip; cache hits should be ms-fast. Confirm with a debug log around queryBindingByNametag.
2. REQ multiplexing contention on the shared socket. The chat subscription opens first and immediately starts streaming the (mystery) backlog. The nametag REQ goes out on the same socket — depending on the relay's REQ-serialization behavior, the nametag response can wait behind the chat backlog stream. The 886 ms outlier correlates with the bigger backlog (11 messages) on the same call.

(B) and (A) interact — if the relay is dumping unexpected backlog on the chat subscription, the nametag REQ on the same socket pays for it. The fix surface is shared.

C) M10b (per-IP rate-limit) — still untested

Strongest remaining hypothesis for the cross-run monotonic creep in #555. Cheapest discriminator: run §4 from a different egress IP after a slow day on the dev box. Hasn't been attempted.

Suggested next actions

1. Verify (A) with a clean Nostr query — directly query nostr-relay.testnet.unicity.network for kind=1059, #p=<fresh_pubkey> from a clean Node script. Expected: 0 events. Observed during this soak (indirectly): 3–14. If the direct query reproduces, file as a relay-side issue with concrete numbers.
2. Run the M10b discriminator (different-IP §4 test).
3. Independent of Nostr relay degradation across consecutive trader-soak runs — retry-loop flooding hypothesis + amplification of #473 #555, consider raising EARLY_MESSAGE_CAP from 32 to ~128 in sphere-cli/src/trader/acp-transport.ts. Risk is low (in-memory buffer growth), upside is robustness against the (A) anomaly should it ever scale up. Not urgent.
4. PR feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558 (SDK M8 opt-out): still valuable but no longer load-bearing for Nostr relay degradation across consecutive trader-soak runs — retry-loop flooding hypothesis + amplification of #473 #555. Wait for M10b results before deciding to wire the CLI opt-in.

Related

• Nostr relay degradation across consecutive trader-soak runs — retry-loop flooding hypothesis + amplification of #473 #555 — original investigation
• Nostr DM delivery flakiness across CLI process boundaries (intermittent receiver miss) #473 — cross-process DM delivery flakiness (parent)
• PR feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558 — SDK M8 opt-out (the selfWrap: false API surface)

[vrogojin]

Suggested action #1 — relay #p-filter discriminator: (A.1) ruled out

PR #560 lands manual-test-relay-fresh-pubkey-backlog.mjs — a clean Node script that does exactly what this issue's Suggested action #1 calls for: fresh secp256k1 keypair, no SDK state (just the bare NostrClient for NIP-42 AUTH), subscribe kind=1059, #p:[fresh_pubkey], count what arrives.

Result (3 runs against wss://nostr-relay.testnet.unicity.network, 2026-06-15)

Run	Mode	events pre-EOSE	events post-EOSE	time-to-EOSE
1	default (7d since floor)	0	0	25 ms
2	default (7d since floor)	0	0	25 ms
3	--no-since (no time bound at all)	0	0	25 ms

Fresh pubkeys from this run (for trace, in case future leakage shows correlation):

89ecea61bc76f81d36a19eaf360ab77ba9da52a4e5ec869335038aeea1f9f628
7cac87678924b18636a6ed5294a197d53bb00abd98ebb1bc19f19ee4f9aebf7f
a59be61607562e44ff180207bb6f9c7a414e8e79747e24d51565ff571ac71b95

What this changes for the open hypothesis list

• (A.1) Relay filter looseness — ruled out. Direct query returns 0 events. The relay's #p index is clean for never-used pubkeys.
• (A.2) Tenant / escrow / soak side-channel publishes — now the leading hypothesis. The §3 spawn table already shows alice's first ever command (SET_STRATEGY) sees buffered=4 and bob's first sees buffered=3. Within-run self-wrap accumulation cannot explain that — no prior sendDM has fired by then. Something publishes to the controller pubkey before the controller's first ACP sendDM resolves. Most plausible candidates, in order of suspicion:
  1. The trader tenant container emits a hello / ack / heartbeat gift-wrap to the controller after the host finishes provisioning. The controller subscribes ~hundreds of ms later and finds the backlog.
  2. The host's HMCP / control plane publishes to the controller pubkey during spawn (status, ready, provisioning result) via a non-sendDM path.
  3. The soak's wait_for_tenant_running polling itself publishes through a path that bypasses the per-process sendDM flow.
• (A.3) HD-derivation collision — still untested. Cheap to check: log MultiAddressTransportMux.addresses.size at controller startup. If > 1, allPubkeys widens beyond the controller key. For the trader CLI this should be 1; if it's not, that's a bug in its own right.

How to reproduce

cd sphere-sdk
node manual-test-relay-fresh-pubkey-backlog.mjs                     # default
node manual-test-relay-fresh-pubkey-backlog.mjs --no-since --quiet   # strictest
node manual-test-relay-fresh-pubkey-backlog.mjs --relay wss://other-relay  # cross-relay

Help: --help.

Suggested next step

The (A.2) hypothesis can be verified the same way #559 was filed — patch the trader-service spawn path (and/or sphere-cli's controller bootstrap) with a [diag-559] log on every NIP-17 publish that targets the controller pubkey, run a single soak round, and grep the relay's outbound publish stream. If a non-sendDM publisher is emitting gift-wraps to the controller, this surfaces immediately. Happy to draft the patch on the trader-service side as a follow-up.

PR #560 is independent of PR #558 (M8 self-wrap opt-out) — diagnostic tooling only, no SDK behavior changes.

[vrogojin]

Refined (A.2) analysis + (A.3) likely also ruled out

Following the previous comment (PR #560 ruled out (A.1)), the source-code trace surfaces a concrete candidate for what publishes to the controller pubkey before §3's first ACP sendDM, plus a probable reason the events aren't deduped.

Concrete publisher: HM HMCP responses

I had listed three candidates (tenant heartbeat, host control plane, soak harness). Reading the trader-service + agentic_hosting source narrows it to one:

• Tenant heartbeats (trader-service/src/tenant/heartbeat.ts:58) send to managerAddress, not to the controller. Ruled out.
• Tenant ACP responses (trader-service/src/tenant/acp-listener.ts:626,641,673,695,...) send to senderAddress — only fire in response to a controller command. At §3 spawn time the controller has not sent an ACP command yet, so there are no tenant→controller ACP responses to backlog. Ruled out for the §3 baseline of 3–4 events.
• HM HMCP responses (agentic_hosting/src/host-manager/manager.ts, multiple sender.sendDm(senderAddress, ...) call sites — lines 331, 514, 565, 644, 767, 792, 1103, 1141, 1195, 1242, 1267, 1286, 1330, 1344, 1390, 1445, 1489, 1729) do target the controller. Every sphere trader spawn invocation:
  1. publishes tenant.spawn to the HM (1 self-wrap to controller, default M8 path),
  2. receives acp.ack from the HM (1 gift-wrap to controller),
  3. receives tenant.ready (or failed) from the HM (1 gift-wrap to controller),
  4. process exits ~3 s later.

That is 3 controller-targeted events in the relay's index per spawn. The §3 SET_STRATEGY's buffered=4 (alice) / buffered=3 (bob) exactly matches.

(A.3) — single-controller Sphere

MultiAddressTransportMux.updateSubscriptions builds the chat sub's #p filter from this.addresses.values() (one entry per addAddress call). The trader CLI's Sphere.init registers a single address, so addresses.size === 1 and allPubkeys === [controllerKey]. HD-derivation collision in the filter ruled out (modulo a multi-address regression nobody has filed yet).

So why doesn't dedup catch them?

This is where it gets interesting. The SDK already implements persistent cross-process dedup for both layers (Issue #275):

• MultiAddressTransportMux.processedEventIds flushed to STORAGE_KEYS_GLOBAL.MUX_PROCESSED_EVENT_IDS via schedulePersistDedup() (200 ms debounce) + an explicit persistDedupNow() in disconnect().
• NostrTransportProvider.processedEventIds flushed similarly in its own disconnect().

sphere.destroy() → _transportMux.disconnect() → persistDedupNow() is awaited. So in principle, after sphere trader spawn exits cleanly, the next CLI process's hydrateProcessedDedup() should load the 3 spawn-flow event IDs and the relay's replay should be silently dropped at handleEvent.

But §3's buffered=4 shows dedup is NOT catching them. The growing-buffer pattern across the soak (4 → 11 → 12 → 14 → ...) confirms it's a per-process miss, not a within-process race. The leak window is between adding to processedEventIds and the next process reading them back. Two candidate causes:

1. OrbitDB Profile flush doesn't complete before process.exit() — for trader CLI the storage adapter is OrbitDB (Helia + IPFS-backed). kv.set('mux_processed_event_ids', json) returns once the OrbitDB op is in memory; the underlying IPFS / pin durability completes asynchronously. The companion issues Profile/OrbitDB: invoice tokens not durable across CLI process exit — manual-test-full-recovery.sh §C.1b blocker #234, Profile: shutdown must verify remote IPFS + aggregator durability before exit (root cause of #234 manual-test failure) #239, Client-side Helia/libp2p bootstrap is too heavy — clients should HTTP-only to operator Kubo gateway(s) #266, Flush-durability verify gate (#239) too aggressive on testnet — at-least-once loop in §C.2 #268 all track CID-flush-on-shutdown gaps in this same surface. A flush that returns "ok" without the underlying IPLD bytes pinned will lose the dedup payload across process boundaries.
2. Dedup flushes after relay subscribe / before the dedup gate is consulted — long-shot. updateSubscriptions awaits hydrateProcessedDedup before calling subscribe, so this would require the storage .get() to return stale data even after the prior process's .set() resolved.

The cheapest way to discriminate is a single targeted soak run with a [#559-diag] log added in MultiAddressTransportMux.hydrateProcessedDedup (line 1840) — print processedEventIds.size immediately after hydration. If §3's first SET_STRATEGY process logs hydrated: 0, cause (1). If it logs hydrated: 3, cause (2) — the events are arriving via a path that bypasses dedup.

Fix surface

If cause (1) — durable flush of MUX_PROCESSED_EVENT_IDS on Sphere.destroy() for OrbitDB Profile storage. This is genuinely entangled with the issue #234/#239/#266 family; a clean fix likely lives there rather than in transport.

If cause (2) — locate the bypass path. Candidates: fetchPendingEvents (both Mux and outer provider), the outer NostrTransportProvider.handleEvent gift-wrap path, or a comms.onDirectMessage registration that intercepts events upstream of routeGiftWrap.

Either way, this is bigger than #559's symptom and warrants its own issue (proposed title: "persistent transport dedup not surviving short-lived CLI process across OrbitDB Profile flush") if the diag log confirms cause (1). I can file it under the @vrogojin/uxf workflow once the diag-log soak result is in.

Suggested follow-ups (concrete, scoped)

#	What	Where	Effort
F1	Add 6-line [#559-diag] log in hydrateProcessedDedup + handleEvent dedup branch	sphere-sdk uxf	~30 min + 1 soak run
F2	Based on F1's verdict, file the persistent-dedup-cross-process issue	sphere-sdk	~30 min
F3	Wire selfWrap: false for HMCP sendDm in sphere-cli/src/host/host-commands.ts HMCP send sites	sphere-cli	independent of F1/F2 — cuts the controller's own self-wrap pollution in half regardless

F3 is independent and gives a known partial mitigation today using PR #558's API (once #558 lands or with a local rebase).

Recommend tackling F1 first — it's the deterministic single soak that converts the open hypothesis to a concrete bug + bug location.

[vrogojin]

F1 landed as draft PR — ready for one soak run

PR #582 — diag/issue-559-mux-dedup-instrumentation off @vrogojin/uxf.

Adds two [#559-diag] log lines at INFO level (no DEBUG_LOG=1 needed):

1. MultiAddressTransportMux.hydrateProcessedDedup — post-hydration processedEventIds.size
2. MultiAddressTransportMux.handleEvent — dedup-hit branch (event id prefix + kind + set size)

tsc --noEmit clean. npx vitest run tests/unit/transport/MultiAddressTransportMux → 39 / 39 pass.

How to run the discriminator

cd sphere-sdk
git fetch origin diag/issue-559-mux-dedup-instrumentation
git checkout diag/issue-559-mux-dedup-instrumentation
npx tsup  # rebuild dist/

# In sphere-cli:
cd ../sphere-cli
npm link @unicitylabs/sphere-sdk  # or vendor-bump the dist/

# Run the trader soak with INFO-level logging visible:
LOG_LEVEL=info ./bin/trader-soak.sh 2>&1 | tee /tmp/559-diag.log

# Grep the discriminator:
grep '\[#559-diag\]' /tmp/559-diag.log

What to look for

The §3 first SET_STRATEGY (alice's spawn) should print exactly one hydrated: line. The verdict table is in PR #582's description — three patterns, three causes.

I'll move to F3 (sphere-cli selfWrap: false mitigation, independent of F1/F2) while the soak runs — partial mitigation that lands today regardless of F1's verdict.

[vrogojin]

Static analysis update — cause (1) ruled out without needing the F1 soak

While F1 (PR #582) is queued, I traced the persistence chain end-to-end against @vrogojin/uxf head + sphere-cli to see whether cause (1) — "OrbitDB Profile flush doesn't survive process.exit()" — is actually viable. It isn't, for the trader CLI Node.js path. Re-prioritization implications at the bottom.

The persist chain

#	Layer	Code	Awaited?
1	sphere trader spawn finally → safeDestroy(sphere)	sphere-cli/src/trader/spawn.ts:611-617	✓
2	Sphere.destroy() → _transportMux.disconnect()	core/Sphere.ts:6198	✓
3	Mux.disconnect() → persistDedupNow() (after clearing the debounce timer)	transport/MultiAddressTransportMux.ts:454-469	✓
4	persistDedupNow() → storage.set('mux_processed_event_ids', JSON.stringify(ids))	transport/MultiAddressTransportMux.ts:1911	✓
5	ProfileStorageProvider.set() → localCache.set() (always — runs before any OrbitDB write)	profile/profile-storage-provider.ts:1653-1654	✓
6	Node Profile localCache = FileStorageProvider (NOT a no-op cache)	profile/node.ts:99-102	✓
7	FileStorageProvider.set() — atomic temp-file → fsync → rename → parent-dir fsync	impl/nodejs/storage/FileStorageProvider.ts:139 (SPEC §7.1.3)	✓

Every step awaits the next. The localCache layer for Node Profile is FileStorageProvider with fsync — i.e., when storage.set() resolves, the bytes are on disk durably. The OrbitDB write at ProfileStorageProvider.set step 3 happens AFTER the localCache write — even if the OrbitDB layer never flushes (which is what #234/#239/#266/#268 worry about), the next process's storage.get() reads from localCache first (profile-storage-provider.ts:1525-1529) and finds the data.

Important caveat — mux_processed_event_ids is not cache-only

I checked CACHE_ONLY_KEYS in profile/types.ts:967 — it lists token_registry_cache, price_cache, identity material, and current_address_index. mux_processed_event_ids is not there, so it's written to BOTH localCache AND OrbitDB. Either path satisfies persistence; the OrbitDB write is redundant for cross-process dedup (but useful for cross-device replication).

Why this rules out cause (1)

For cause (1) to be the bug, one of the above steps would have to:

• not actually await, or
• have a fsync gap, or
• write to a directory the next process doesn't read.

None of those are visible in the code as of @vrogojin/uxf head (a8081ded). I read each function inline. The async chain is intact and the storage backend is fsync-safe.

Implication for §3 buffered=4

If persistence is sound, the §3 SET_STRATEGY's buffered=4 events have new event IDs the prior spawn process never saw — i.e., not dedup misses but legitimately fresh events. The publisher must be emitting them to the controller's #p filter AFTER sphere trader spawn exits its finally block. Candidates (in suspicion order):

1. HM emits trailing status/heartbeat to controller after tenant.ready — e.g., a "tenant healthy" or "container running" notification that fires periodically while the tenant is alive. The controller's sphere trader spawn process is gone by the time these land; the relay holds them; the next CLI subscribe pulls them via NIP-17 since. Cheap to verify: grep agentic_hosting/src/host-manager/manager.ts for setInterval or status-loop publishes to controller.
2. HM publishes >3 events per spawn but the spawn process unsubscribes after tenant.ready and misses the tail — possible if the HM's spawn lifecycle includes a tenant.bootstrapped or tenant.observed-healthy event after ready.
3. Self-wrap of the controller's own tenant.spawn arrives AFTER the controller unsubscribes — controller's own gift-wrap to itself (M8 path) could race with the relay's processing. Less likely (publish-and-subscribe on the same socket should land before unsubscribe), but worth checking.

(3) is what F3 (PR #558 + sphere-cli wiring) mitigates. (1) and (2) need a publisher-side audit on agentic_hosting.

Re-prioritized next steps

• F1 (PR diag(transport)(sphere-sdk#559): instrument Mux dedup hydration + hit path #582) still runs as planned — its purpose shifts from "discriminate (1) vs (2)" to "confirm (a) by counting dedup-hits vs buffered events per process". The expected pattern in §3 alice SET_STRATEGY:
  • [#559-diag] hydrated: N>0 event IDs (persistence working)
  • K [#559-diag] dedup hit ... lines (relay replays the previous process's events under since-filter — dedup catches them)
  • [acp-m9] resolvedPubkey set ... buffered=M where M is the count of NEW events, not K+M (which would be cause 1)
• F2 is unlikely to be needed — persistence is sound for the Node.js path. Keep the issue draft on standby in case the soak surprises us.
• F3 (sphere-cli selfWrap: false) only helps if (3) above is the cause — it does nothing for HM-originated events. Worth doing as a precision mitigation but won't kill the backlog if (1) or (2) dominates.
• New: audit agentic_hosting/src/host-manager/manager.ts for trailing publishes to controller — this is now the most likely fix surface. Look for: status loops, recurring heartbeats to controller, post-ready notifications, lifecycle observers.

I'll move to the agentic_hosting audit next. F1 PR #582 stays open for the soak run; it'll either confirm or refute this reading.

[vrogojin]

F1 soak runbook ready — your call to run

Per the decision above (run F1 soak first, then decide on #558), I've packaged everything into one driver script on PR #582:

cd ~/uxf
git fetch origin diag/issue-559-mux-dedup-instrumentation
git checkout diag/issue-559-mux-dedup-instrumentation
bash manual-test-559-soak-collector.sh

What the collector does

1. Verifies the SDK is on the F1 commit (PR diag(transport)(sphere-sdk#559): instrument Mux dedup hydration + hit path #582).
2. Verifies sphere-cli/package.json pins sphere-sdk via file: (so the F1 logs are live without a vendor-bump).
3. Rebuilds the SDK (npx tsup).
4. Runs one trader-soak round with SPHERE_DEBUG=Mux=info KEEP=1.
5. Greps [#559-diag] + [acp-m9] from the captured logs and prints a single-block verdict.

The verdict block tells you which of the three rows in PR #582's table the data lands on. The exit code is non-zero if SPHERE_DEBUG didn't propagate.

Heads-up: SPHERE_DEBUG is required

I caught a bug in my own framing — the [#559-diag] log calls use logger.info('Mux', ...), and the SDK's logger defaults the per-namespace min-level to warn (core/logger.ts:389). The lines only print with SPHERE_DEBUG=Mux=info (or wider). The collector script sets this automatically; if you ever run the soak script directly, set it yourself. PR #582's description has been updated to reflect this.

My static-analysis prediction

Based on my persistence-chain trace, I expect:

• [#559-diag] hydrated: N>0 event IDs ... on the §3 first SET_STRATEGY (cause 1 ruled out)
• [#559-diag] dedup hit ... lines for replays of events the prior sphere trader spawn process processed
• [acp-m9] buffered=K with K new event IDs not appearing in the dedup-hit lines — i.e., events the prior process never received because it exited before relay delivery (case 3 confirmed)

If that prediction holds, the next step is to lift PR #558's hold + draft F3 sphere-cli wiring. If the prediction misses (e.g., hydrated=0 or all buffered events are dedup-hits), we've learned something useful and the fix surface shifts.

What I won't do without your nod

• Won't touch PR feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558.
• Won't open the sphere-cli F3 PR.

Both unblock as soon as the verdict lands.

[vrogojin]

F1 soak result — case (3) confirmed empirically + cause (1) ruled out

Ran the F1-instrumented trader-soak twice against testnet. Second run added a [#559-diag] new event log line (every NEW event added to dedup) so we can directly count what [acp-m9] buffered=K would have measured. Both runs use the live SDK in /home/vrogojin/sphere-sdk rebuilt with the F1 + F1-b log pair on top of debug/market-log-body.

Run 2 per-process snapshot (Sections 1 → §4 alice probe)

Section	Process	hydrated	new-event lines	Notes
§1 alice init	proc 1	0	0	wallet create
§1 alice show	proc 2	0	0	identity show
§1 bob init	proc 3	0	0	wallet create
§1 bob show	proc 4	0	0	identity show
§2 (12 procs)	—	0	0 except last=3	local mint / sync / probe — last proc saw 3 new escrow/market-api responses
§3 alice pre-spawn	proc 1	3	0	escrow responses dedup-hit (replays from §2/§2.5)
§3 alice trader spawn	proc 2	3	7	spawn flow new events
§3 bob pre-spawn	proc 3	0	0	bob's dataDir is separate, clean start
§3 bob trader spawn	proc 4	0	7	spawn flow new events
§4 alice probe (looping)	proc 1	10	0 (so far)	waits 180s for ACP probe ready

What the numbers mean

1. Persistence works end-to-end. Hydrated counts grow monotonically across same-peer processes (0 → 3 → 10 for alice, 0 → 7 for bob), exactly matching the new-event additions of prior processes. Cause (1) — "Mux dedup not surviving process.exit()" — is now ruled out empirically, not just by static analysis. Closes that hypothesis.

2. Case (3) reproduces. Each sphere trader spawn process processes 7 NEW events: roughly 1-2 self-wraps from the CLI's own hm.find/hm.spawn publishes + 3-4 HM responses + 1-2 other peer events. Each of those 7 events arriving during the resolve window would have landed in AcpDmTransport.earlyMessages — i.e., contributed to [acp-m9] buffered=K. The order of magnitude (4–14 in the original telemetry, 7 here) matches; difference is run-to-run variation in HM/escrow response counts.

3. The §3 SET_STRATEGY framing in the original telemetry was accurate. The "buffered=4" event was the CLI's own self-wrap + HM ack + tenant-related responses arriving during the publish/resolve window. They reached earlyMessages not because they leaked from a prior process (dedup catches all replays — proven), but because they arrived legitimately during this process's own activity.

4. The §4 ACP probe failure (no tenant ready in 180s) repeated in both runs. Not blocking the verdict — the relevant transport data already landed. The failure is a tenant-startup timing issue, not a dedup issue.

Fix surface — PR #558 is correctly aimed

Of the 7 new events per spawn, the CLI's OWN sendDm self-wraps are the easiest to eliminate at the source:

• sendDm(hm, hm.find) self-wraps to controller — controller process never reads it
• sendDm(hm, hm.spawn) self-wraps to controller — same
• ... etc, per HMCP call site

PR #558 introduces selfWrap: false at the SDK level so callers can opt out. Cutting the CLI's self-wrap publishes halves the per-process new-event count at the relay's #p:controller index. The HM-response half remains because those are inbound from a peer (HM), which the controller actually needs.

The hold reason for #558 ("pending M10b") was a different hypothesis (per-IP rate limit). My static + empirical analysis substantially weakens M10b's relevance: persistence is sound, dedup is sound, the §3 buffered=K events are normal protocol traffic. #558's mechanism IS the right partial mitigation.

Recommended next step

Lift PR #558's hold and land it into @vrogojin/uxf. Then F3 (sphere-cli dm-transport.ts:289 adds { selfWrap: false }) lights up immediately — sphere-cli auto-picks via file: link.

If you give the go-ahead, I'll:

1. Comment on feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558 with this analysis (link to the soak log).
2. Squash-merge feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558 into @vrogojin/uxf.
3. Open the sphere-cli F3 PR.
4. Optionally re-run the soak with both landed to measure the new-event count drop.

Holding for your nod on #558.

[vrogojin]

PR #558 landed → F3 unblocked

PR #558 merged into @vrogojin/uxf as commit 3b255716. The selfWrap: false SDK API is now live on the integration branch.

PR #582 (F1 instrumentation) auto-merged uxf cleanly — no conflicts between #558's publish-side opt-out and #582's handle-side dedup logging. All 44 MultiAddressTransportMux unit tests pass on the merged state, including #558's 5 new selfWrapOptOut tests. PR #582 is now up-to-date with uxf.

Next: F3 — open a sphere-cli PR adding { selfWrap: false } to HMCP comms.sendDM(...) at src/transport/dm-transport.ts:289 (and any analogous ACP send sites in the trader transport). Targets the @vrogojin/uxf-equivalent of sphere-cli. Will report back when the PR is up.

After F3 lands, can re-run the F1 soak to measure the per-spawn-process new-event drop (expected: ~7 → ~3-4, removing the self-wrap half).

[vrogojin]

F3 PR open — sphere-cli#51

sphere-cli PR #51 — fix/issue-559-selfwrap-optout → @vrogojin/uxf.

Wires { selfWrap: false } into:

• src/transport/dm-transport.ts (HMCP — CLI → host manager)
• src/trader/acp-transport.ts (ACP — CLI → trader tenant)

Leaves sphere message send alone (user-initiated, wants own outbound history).

Net diff: 2 files, +24 / -6. npx tsc --noEmit clean; npx vitest run 187 / 187 pass.

Prereq follow-up that landed alongside

PR sphere-sdk#614 (squash-merged into @vrogojin/uxf) re-exports SendMessageOptions from the top-level index.ts. PR #558 added the type to the transport barrel but missed the explicit allow-list in index.ts. Surfaced as a TS2459 when this F3 PR tried to import it. One-line fix.

Remaining tasks (for record)

• Land F3 (sphere-cli#51) — pending your nod
• Re-run F1 soak with PR feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558 + F3 both landed; expect per-spawn new-event count to drop from ~7 → ~3-4 (HM responses remain, CLI self-wraps gone)
• Close Fresh-wallet chat-subscription backlog + sendDM resolve outlier (follow-up to #555) #559 once the soak confirms the drop

[vrogojin]

F3 landed — sphere-cli#51 merged

sphere-cli#51 squash-merged into @vrogojin/uxf as commit 9d06878. { selfWrap: false } is now live on HMCP + ACP RPC paths.

Status summary

PR	Repo	State
#560	sphere-sdk	Merged (8bf05bb7) — relay #p-filter discriminator
#558	sphere-sdk	Merged (3b255716) — selfWrap: false SDK API
#614	sphere-sdk	Merged (33295d72) — re-export SendMessageOptions
#582	sphere-sdk	Open — F1 diag instrumentation
#51	sphere-cli	Merged (9d06878) — F3 HMCP/ACP wiring

Remaining

• Confirm soak — re-run manual-test-trader-roundtrip.sh with F1 instrumentation still in place; expect per-spawn process new-event count to drop from ~7 → ~3-4. The HM responses (acp.ack, spawn_ready, etc.) remain; CLI self-wraps eliminated.
• Close Fresh-wallet chat-subscription backlog + sendDM resolve outlier (follow-up to #555) #559 when the soak confirms the drop.
• Decide PR diag(transport)(sphere-sdk#559): instrument Mux dedup hydration + hit path #582 disposition — keep merged as permanent diag, or revert once Fresh-wallet chat-subscription backlog + sendDM resolve outlier (follow-up to #555) #559 closes.

Ready to drive the confirm soak whenever you give the nod.

[vrogojin]

Confirmation soak — F3 effect measured empirically

Re-ran manual-test-trader-roundtrip.sh with the full fix surface live in the SDK build that sphere-cli consumes:

• F1 + F1-b diag instrumentation in MultiAddressTransportMux.ts (cherry-picked into /home/vrogojin/sphere-sdk for this measurement)
• PR feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558's selfWrap: false SDK API
• PR fix(transport)(sphere-sdk#559): re-export SendMessageOptions from top-level index #614's SendMessageOptions top-level re-export
• sphere-cli PR feat: restore market module integration #51's { selfWrap: false } wiring at HMCP + ACP sendDM sites

⚠️ First attempt of this soak mis-measured the baseline — the sphere-cli dist/ was stale, so the running CLI was still pre-F3. After npm run build in sphere-cli the soak re-measurement showed the true F3 effect.

§3 per-process new-event counts

Process	Run 2 (pre-F3)	Run 3 (F3 live)	Δ
§3 alice sphere trader spawn	7 new events	4 new events	−43%
§3 bob sphere trader spawn	7 new events	4 new events	−43%

Both peers drop by the same fraction, which is the expected shape if the removed events are CLI-side self-wraps. sphere trader spawn makes 2-3 sendDm calls during the spawn flow (hm.find, hm.spawn, plus the streaming reply correlator); pre-F3 each generated a NIP-17 self-wrap targeting the controller's own pubkey. The remaining 4 events per spawn process are the HM responses (hm.find_result, hm.spawn_ack, hm.spawn_ready) plus one ipfs/escrow/market-api side response — all protocol-required.

§4 ACP probe (long-lived alice process, 180s window)

	Run 2	Run 3	Δ
§4 entry hydrated	10	7	smaller hand-off — already reflects §3 reduction
§4 new events accumulated over 180s	48	24	−50%
§4 end dedup-set size	58	31	−47%

The long-lived probe process exercises F3 more aggressively because every acp.probe command goes through comms.sendDM(..., { selfWrap: false }). The reduction grows from ~43% in spawn to ~50% over the probe's lifetime, because spawn carries some non-CLI new events as a hand-off (HM acks) while the probe loop is dominated by CLI publishes.

Persistence + dedup chain still sound

Section	hydrated trajectory (alice)	hydrated trajectory (bob)
§1 (4 procs)	0 throughout	0 throughout
§2 (12 procs)	0 throughout except last (3 new)	0 throughout
§3 spawn	3 → 3 + 4 new = end 7	0 → 0 + 4 new = end 4
§4 ACP probe entry	hydrated=7	hydrated=4
§4 alice teardown process	hydrated=31	—
§4 bob teardown process	—	hydrated=4

Cross-process Mux dedup persistence keeps working — every event added in one process appears in the next process's hydrated set. Same shape as run 2. Cause (1) stays ruled out empirically.

Interpretation

Case (3) self-wrap-race is confirmed AND the fix surface is correctly closed:

• PR feat(transport)(sphere-sdk#555): NIP-17 self-wrap opt-out (M8 mitigation) #558 introduces the SDK API
• PR fix(transport)(sphere-sdk#559): re-export SendMessageOptions from top-level index #614 exposes it at the package surface
• sphere-cli PR feat: restore market module integration #51 wires it into the two short-lived RPC paths

The Section 4 ACP probe timeout still fires (separate harness timing issue unrelated to #559's transport question — the GET_PORTFOLIO response landed in prior runs after the assert).

Closing

I'll mark this issue closed pending your nod. PR #582 (F1 instrumentation) stays open — useful as a permanent diag toggle if the per-spawn new-event count creeps back up later. If the diff is too much noise to keep on @vrogojin/uxf, the revert is a single line per log site.

Logs preserved at /tmp/trader-559b-soak.log (run 2) and /tmp/trader-559d-soak.log (run 3). Workspaces at /tmp/trader-559b-2033358 and /tmp/trader-559d-3378792.

[vrogojin]

Closing — fix surface delivered, confirmation soak measured

The full fix landed across three repos:

PR	Repo	Role
#560	sphere-sdk	Relay #p-filter discriminator — ruled out (A.1)
#558	sphere-sdk	selfWrap: false SDK API
#614	sphere-sdk	Re-export SendMessageOptions
#51	sphere-cli	Wire { selfWrap: false } at HMCP + ACP send sites

Empirical measurements (Run 2 verdict, Run 3 confirmation):

• Cause (1) "persistence not surviving `process.exit()`" — ruled out empirically. Mux dedup roundtrips cleanly across same-peer processes (FileStorage fsync layer + Profile localCache).
• Case (3) self-wrap-race — confirmed and mitigated. Per-spawn process new-event count drops 7 → 4 (−43%); long-lived §4 ACP probe new-event count drops 48 → 24 (−50%).

Residual events per process are protocol-required HM responses + escrow/market-api side responses — no further fix surface inside the CLI.

PR #582 (F1 instrumentation) stays open for now as a standing diagnostic toggle. Easy to revert later if not needed.

Closing.