Confirm publishes against the relay's OK, not the send queue #56

New issue

Closed

opened 2026-09-26 21:46:29 +00:00 by padreug · 1 comment

padreug commented

2026-09-26 21:46:29 +00:00

Owner

Split out of #55 rather than bolted onto it. (Checked the tracker first — #35 raises "consider returning a success boolean", which #55 did, but nothing covers the OK frame itself.)

NostrClient.publish_nostr_event returns as soon as the req is on the queue:

async def publish_nostr_event(self, e: NostrEvent):
    await self.send_req_queue.put(["EVENT", e.dict()])

publish_event_to_nostr logs Published NIP-52 calendar event on the next line, and after #55 that's also where nostr_publish_pending gets cleared. So "published" means "queued", and a relay that never receives the event — or receives it and rejects it — looks identical to success.

is_websocket_connected reads self.ws.keep_running, which stays True on a socket that's dead but not yet noticed, so bytes can be accepted and dropped with nothing raised. #55's hold-and-retry only covers the case where ws.send actually raises.

What it needs

Read ["OK", <event_id>, <true|false>, <message>] frames off the receive side and correlate them to in-flight publishes by event id.
publish_nostr_event awaits that correlation with a timeout, returning success/failure.
Clear nostr_publish_pending only on an OK true; a false or a timeout leaves the row flagged, and the #55 sweep retries it.
A rejection message from the relay is worth logging verbatim — it's the only place we'd learn about e.g. a rejected created_at or a size limit.

The receive loop already exists (get_event / receive_event_queue), so this is mostly correlation bookkeeping rather than new plumbing.

Priority

Low-ish. Neither production incident (#35 on aio-demo, #51 on cfaun) went through this gap — both failed or were skipped before anything reached the queue, and #55 covers those. This closes the last silent path rather than a known-live one.

Worth noting the same gap exists in every extension using this NostrClient pattern (it came from nostrmarket), so a fix here is a candidate to carry over.

Split out of #55 rather than bolted onto it. (Checked the tracker first — #35 raises "consider returning a success boolean", which #55 did, but nothing covers the OK frame itself.) `NostrClient.publish_nostr_event` returns as soon as the req is on the queue: ```python async def publish_nostr_event(self, e: NostrEvent): await self.send_req_queue.put(["EVENT", e.dict()]) ``` `publish_event_to_nostr` logs `Published NIP-52 calendar event` on the next line, and after #55 that's also where `nostr_publish_pending` gets cleared. So "published" means "queued", and a relay that never receives the event — or receives it and rejects it — looks identical to success. `is_websocket_connected` reads `self.ws.keep_running`, which stays True on a socket that's dead but not yet noticed, so bytes can be accepted and dropped with nothing raised. #55's hold-and-retry only covers the case where `ws.send` actually raises. ## What it needs - Read `["OK", <event_id>, <true|false>, <message>]` frames off the receive side and correlate them to in-flight publishes by event id. - `publish_nostr_event` awaits that correlation with a timeout, returning success/failure. - Clear `nostr_publish_pending` only on an OK true; a false or a timeout leaves the row flagged, and the #55 sweep retries it. - A rejection message from the relay is worth logging verbatim — it's the only place we'd learn about e.g. a rejected `created_at` or a size limit. The receive loop already exists (`get_event` / `receive_event_queue`), so this is mostly correlation bookkeeping rather than new plumbing. ## Priority Low-ish. Neither production incident (#35 on aio-demo, #51 on cfaun) went through this gap — both failed or were skipped before anything reached the queue, and #55 covers those. This closes the last silent path rather than a known-live one. Worth noting the same gap exists in every extension using this NostrClient pattern (it came from nostrmarket), so a fix here is a candidate to carry over.

padreug commented

2026-09-27 09:53:09 +00:00

Author

Owner

This gap hit production today — correcting the priority note

I closed this issue saying "neither production incident went through this gap… this closes the last silent path rather than a known-live one." That's now wrong. It bit within an hour of #55 deploying, and it silently reverted a completed repair.

What happened

Context: the cfaun signer for Q6mhQQzQPSXqkQuFndzXnf had just been restored (see aiolabs/lnbits#73), so the #55 sweep should have republished the event and corrected a 14-day-stale ticket count. Journal times are CEST:

09:35:39  lnbits restart (pid 411227)
09:36:39  [EVENTS] Republish sweep: 1 event(s) pending
09:36:39  [EVENTS] Published NIP-52 calendar event: 51fee6d0423ba662... (kind 31923)
09:36:39  [EVENTS] Republish sweep: 1/1 recovered
09:36:59  Restarting connection to relay 'wss://lnbits.ariege.io/nostrrelay/castle'
09:37:00  [Relay: wss://lnbits.ariege.io/nostrrelay/castle] Connected.

51fee6d0… never reached the relay. Querying the relay for everything that author ever published returned five events, newest still the Sep 12 one:

1789211268 kind=31923 756fed216056 d=Q6mhQQzQPSXqkQuFndzXnf avail=48 sold=2
1788959727 kind=5     e7f5185a24a7
1788959691 kind=5     93703a5e9a5b
1788959576 kind=5     2fe553d6072c
1788959247 kind=0     8697c12c3296

The publish landed 21 seconds before nostrclient had a connected upstream relay, so NostrRouter._handle_client_event took its short-circuit:

connected = [r for r in nostr_client.relay_manager.relays.values() if r.connected]
if not connected:
    await self._send_ok(event_id, False, "error: no relays connected")
    return

The router said OK false and told us exactly what was wrong. We threw it away, logged Published, cleared nostr_publish_pending, and counted 1/1 recovered.

Why that's worse than the original bug

Before #55, drift was invisible. After #55, drift is visible and self-healing — except here, where the sweep marked the row clean on a delivery that never happened. The row would never be retried; the count stayed stale; and the log positively asserted success. A manual

UPDATE events SET nostr_publish_pending = TRUE WHERE id = 'Q6mhQQzQPSXqkQuFndzXnf';

was needed, after which the next sweep published for real (created_at 1790502680, avail=45 sold=5).

So the flag's contract — "cleared only on a confirmed success" — isn't actually honoured today. It's cleared on a confirmed enqueue. Reading the OK is what makes the contract true, which makes this a correctness dependency of #55 rather than a nice-to-have after it.

The good news for implementing it

nostrclient already does the hard part. NostrRouter._handle_command_results aggregates per-relay results into exactly one NIP-01 OK per published event id — true as soon as any relay accepts, false once all reject or after PUBLISH_TIMEOUT_SECONDS (10s), and it carries the relay's message. So this is correlation bookkeeping in our client, not new protocol work, and the failure messages are already meaningful ("error: no relays connected" would have named this instantly).

REPUBLISH_SWEEP_FIRST_DELAY = 60 races nostrclient's relay connection — boot to relay-connected was 81s here, and check_relays only retries every 20s so the window varies. Raising the delay would have hidden today's failure rather than fixed it: a relay can drop at any time, not only at boot. Worth a small bump anyway for the common case, but it isn't the fix.

## This gap hit production today — correcting the priority note I closed this issue saying "neither production incident went through this gap… this closes the last silent path rather than a known-live one." That's now wrong. It bit within an hour of #55 deploying, and it **silently reverted a completed repair**. ### What happened Context: the cfaun signer for `Q6mhQQzQPSXqkQuFndzXnf` had just been restored (see aiolabs/lnbits#73), so the #55 sweep should have republished the event and corrected a 14-day-stale ticket count. Journal times are CEST: ``` 09:35:39 lnbits restart (pid 411227) 09:36:39 [EVENTS] Republish sweep: 1 event(s) pending 09:36:39 [EVENTS] Published NIP-52 calendar event: 51fee6d0423ba662... (kind 31923) 09:36:39 [EVENTS] Republish sweep: 1/1 recovered 09:36:59 Restarting connection to relay 'wss://lnbits.ariege.io/nostrrelay/castle' 09:37:00 [Relay: wss://lnbits.ariege.io/nostrrelay/castle] Connected. ``` `51fee6d0…` never reached the relay. Querying the relay for everything that author ever published returned five events, newest still the Sep 12 one: ``` 1789211268 kind=31923 756fed216056 d=Q6mhQQzQPSXqkQuFndzXnf avail=48 sold=2 1788959727 kind=5 e7f5185a24a7 1788959691 kind=5 93703a5e9a5b 1788959576 kind=5 2fe553d6072c 1788959247 kind=0 8697c12c3296 ``` The publish landed **21 seconds before nostrclient had a connected upstream relay**, so `NostrRouter._handle_client_event` took its short-circuit: ```python connected = [r for r in nostr_client.relay_manager.relays.values() if r.connected] if not connected: await self._send_ok(event_id, False, "error: no relays connected") return ``` The router said `OK false` and told us exactly what was wrong. We threw it away, logged `Published`, **cleared `nostr_publish_pending`**, and counted `1/1 recovered`. ### Why that's worse than the original bug Before #55, drift was invisible. After #55, drift is visible *and self-healing* — except here, where the sweep marked the row clean on a delivery that never happened. The row would never be retried; the count stayed stale; and the log positively asserted success. A manual ```sql UPDATE events SET nostr_publish_pending = TRUE WHERE id = 'Q6mhQQzQPSXqkQuFndzXnf'; ``` was needed, after which the next sweep published for real (`created_at 1790502680`, `avail=45 sold=5`). So the flag's contract — "cleared only on a confirmed success" — isn't actually honoured today. It's cleared on a confirmed *enqueue*. Reading the OK is what makes the contract true, which makes this a correctness dependency of #55 rather than a nice-to-have after it. ### The good news for implementing it nostrclient already does the hard part. `NostrRouter._handle_command_results` aggregates per-relay results into exactly one NIP-01 `OK` per published event id — `true` as soon as any relay accepts, `false` once all reject or after `PUBLISH_TIMEOUT_SECONDS` (10s), and it carries the relay's message. So this is correlation bookkeeping in our client, not new protocol work, and the failure messages are already meaningful (`"error: no relays connected"` would have named this instantly). ### Related but secondary `REPUBLISH_SWEEP_FIRST_DELAY = 60` races nostrclient's relay connection — boot to relay-connected was 81s here, and `check_relays` only retries every 20s so the window varies. Raising the delay would have hidden today's failure rather than fixed it: a relay can drop at any time, not only at boot. Worth a small bump anyway for the common case, but it isn't the fix.

padreug referenced this issue from a commit

2026-09-27 20:11:25 +00:00

feat(nostr): confirm publishes against the relay's OK

padreug referenced this issue from a pull request that will close it,

2026-09-27 20:11:46 +00:00

feat(nostr): confirm publishes against the relay's OK #58

padreug closed this issue

2026-09-27 20:26:58 +00:00

padreug referenced this issue from a commit

2026-09-28 22:02:56 +00:00

fix: use satspay for onchain payments (#56)

padreug referenced this issue from a commit