aiolabs/events

Fork 0

Nostr publish failures are silently swallowed — inventory counters drift with no retry and no operator signal #35

New issue

Closed

opened 2026-09-06 11:44:20 +00:00 by padreug · 1 comment

padreug commented

2026-09-06 11:44:20 +00:00

Owner

Incident

On 2026-09-05 an nsecbunkerd signing outage caused every NIP-52
republish on aio-demo to fail for roughly 25 minutes:

Sep 05 18:13:09 | WARNING | [EVENTS] Failed to publish to Nostr:
                             no NIP-46 response for 'sign_event' within 15.0s
Sep 05 18:22:35 | WARNING | [EVENTS] Failed to publish to Nostr: ...
Sep 05 18:26:29 | WARNING | [EVENTS] Failed to publish to Nostr: ...
Sep 05 18:27:15 | WARNING | [EVENTS] Failed to publish to Nostr: ...
Sep 05 18:30:09 | WARNING | [EVENTS] Failed to publish to Nostr: ...
Sep 05 18:38:53 | WARNING | [EVENTS] Failed to publish to Nostr: ...

Three tickets sold for event hyhNjddtsZ7JNbezwX8ERB during that
window (18:11:21, 18:21:28, 18:29:25). All three republishes were
dropped. The relay kept serving a copy of the calendar event published
2026-08-09, with month-old inventory:

created_at: 1786297786          # 2026-08-09T17:49:46Z
['tickets_available', '7']
['tickets_sold', '4']

Meanwhile the DB read amount_tickets=9, sold=7. Every client showed a
stale "tickets left" badge, and nothing anywhere indicated a problem.
The drift was only discovered because a human noticed a number that
looked wrong on an event card.

nsecbunkerd has since been fixed and publishing recovered on its own,
but the swallow-and-forget path remains.

Mechanism

Two nested catch-alls, neither of which propagates.

nostr_publisher.py:202-204 — swallows and returns None:

except Exception as e:
    logger.warning(f"[EVENTS] Failed to publish to Nostr: {e}")
    return None

nostr_hooks.py:39-46 — swallows whatever the first one missed, and
treats a None return as an ordinary no-op:

nostr_event = await publish_event_to_nostr(nostr_client, event, signer, delete=delete)
if nostr_event and not delete:
    event.nostr_event_id = nostr_event.id
    event.nostr_event_created_at = nostr_event.created_at
    await update_event(event)
except Exception as exc:
    logger.warning(f"[EVENTS] Nostr publish failed: {exc}")

publish_or_delete_nostr_event returns None on both success and
failure, so none of its 11 call sites can tell the difference —
services.py:68 (the sale path) plus ten in views_api.py.

Swallowing here is deliberate and partly correct: a Nostr outage must
not fail the payment flow that triggered the publish. The bug is that
the failure then leaves no trace anywhere except a WARNING line, and
nothing ever tries again.

Impact

Inventory silently diverges from reality for an unbounded period
— until the next sale that happens to land while the signer is
healthy. Buyers see wrong availability; a sold-out event can keep
advertising tickets.
nostr_event_created_at stays pinned to the last success, so the
monotonic-timestamp logic anchors on a stale value.
No operator signal. WARNING is indistinguishable from routine
noise in the journal, and there is no metric, alert, or persisted
failure state.

Existing partial mitigation

views_api.py:136 /republish-all (admin) and views_api.py:160
/republish-mine (owner) force-republish approved events. So recovery
is possible — but only by a human who already knows the drift happened,
which is exactly what the current logging fails to tell them.

Proposed fix

Raise the log level to ERROR for publish failures. These are not
routine.
Make failure observable in the data: persist a nostr_publish_failed
/ nostr_publish_pending marker on the event row so drift is
queryable rather than buried in the journal.
Retry with backoff so counters self-heal when the signer recovers.
A periodic sweep republishing rows whose marker is set is probably
simpler and more robust than an in-request retry loop, and it reuses
the logic already behind /republish-all.
Consider returning a success boolean from
publish_or_delete_nostr_event so callers can branch, while keeping
the default non-fatal.

Signing is NostrSigner-backend agnostic, so the same failure mode
applies to LocalSigner — a bunker outage is just the most likely
trigger, not the only one.

Split out of #34, which covers the amount_tickets capacity-semantics
bug found during the same investigation. The two are independent: #34
makes the published numbers wrong by construction, this one stops
correct numbers from reaching the relay at all.

## Incident On 2026-09-05 an nsecbunkerd signing outage caused every NIP-52 republish on aio-demo to fail for roughly 25 minutes: ``` Sep 05 18:13:09 | WARNING | [EVENTS] Failed to publish to Nostr: no NIP-46 response for 'sign_event' within 15.0s Sep 05 18:22:35 | WARNING | [EVENTS] Failed to publish to Nostr: ... Sep 05 18:26:29 | WARNING | [EVENTS] Failed to publish to Nostr: ... Sep 05 18:27:15 | WARNING | [EVENTS] Failed to publish to Nostr: ... Sep 05 18:30:09 | WARNING | [EVENTS] Failed to publish to Nostr: ... Sep 05 18:38:53 | WARNING | [EVENTS] Failed to publish to Nostr: ... ``` Three tickets sold for event `hyhNjddtsZ7JNbezwX8ERB` during that window (18:11:21, 18:21:28, 18:29:25). All three republishes were dropped. The relay kept serving a copy of the calendar event published **2026-08-09**, with month-old inventory: ``` created_at: 1786297786 # 2026-08-09T17:49:46Z ['tickets_available', '7'] ['tickets_sold', '4'] ``` Meanwhile the DB read `amount_tickets=9, sold=7`. Every client showed a stale "tickets left" badge, and nothing anywhere indicated a problem. The drift was only discovered because a human noticed a number that looked wrong on an event card. nsecbunkerd has since been fixed and publishing recovered on its own, but the swallow-and-forget path remains. ## Mechanism Two nested catch-alls, neither of which propagates. `nostr_publisher.py:202-204` — swallows and returns `None`: ```python except Exception as e: logger.warning(f"[EVENTS] Failed to publish to Nostr: {e}") return None ``` `nostr_hooks.py:39-46` — swallows whatever the first one missed, and treats a `None` return as an ordinary no-op: ```python nostr_event = await publish_event_to_nostr(nostr_client, event, signer, delete=delete) if nostr_event and not delete: event.nostr_event_id = nostr_event.id event.nostr_event_created_at = nostr_event.created_at await update_event(event) except Exception as exc: logger.warning(f"[EVENTS] Nostr publish failed: {exc}") ``` `publish_or_delete_nostr_event` returns `None` on both success and failure, so **none of its 11 call sites can tell the difference** — `services.py:68` (the sale path) plus ten in `views_api.py`. Swallowing here is deliberate and partly correct: a Nostr outage must not fail the payment flow that triggered the publish. The bug is that the failure then leaves no trace anywhere except a `WARNING` line, and nothing ever tries again. ## Impact 1. **Inventory silently diverges from reality** for an unbounded period — until the next sale that happens to land while the signer is healthy. Buyers see wrong availability; a sold-out event can keep advertising tickets. 2. **`nostr_event_created_at` stays pinned** to the last success, so the monotonic-timestamp logic anchors on a stale value. 3. **No operator signal.** `WARNING` is indistinguishable from routine noise in the journal, and there is no metric, alert, or persisted failure state. ## Existing partial mitigation `views_api.py:136` `/republish-all` (admin) and `views_api.py:160` `/republish-mine` (owner) force-republish approved events. So recovery is possible — but only by a human who already knows the drift happened, which is exactly what the current logging fails to tell them. ## Proposed fix - Raise the log level to `ERROR` for publish failures. These are not routine. - Make failure observable in the data: persist a `nostr_publish_failed` / `nostr_publish_pending` marker on the event row so drift is queryable rather than buried in the journal. - Retry with backoff so counters self-heal when the signer recovers. A periodic sweep republishing rows whose marker is set is probably simpler and more robust than an in-request retry loop, and it reuses the logic already behind `/republish-all`. - Consider returning a success boolean from `publish_or_delete_nostr_event` so callers *can* branch, while keeping the default non-fatal. Signing is `NostrSigner`-backend agnostic, so the same failure mode applies to `LocalSigner` — a bunker outage is just the most likely trigger, not the only one. ## Related Split out of #34, which covers the `amount_tickets` capacity-semantics bug found during the same investigation. The two are independent: #34 makes the published numbers wrong by construction, this one stops correct numbers from reaching the relay at all.

padreug commented

2026-09-26 21:31:44 +00:00

Author

Owner

Second occurrence on cfaun — and a mechanism this issue doesn't cover

Same symptom, different path in. Worth recording because the fix proposed here wouldn't have caught it.

Event Q6mhQQzQPSXqkQuFndzXnf (URU ECSTATIC DANCE), oyez.ariege.io. DB read amount_tickets=45, sold=5; the relay served a copy published 2026-09-12 with tickets_available=48 tickets_sold=2 — 14 days stale. Found the same way as last time: a human noticed a wrong number on a public page.

Sep 12 11:05:40  tickets 1+2 paid
Sep 12 11:07:47  Published NIP-52 calendar event: 81709fa3... / 756fed21...   <- last success
Sep 20 13:00:50  lnbits restart; NostrClient connected 13:01:00, subscribed 13:01:05
Sep 21 13:39:01  tickets 3+4 paid   -> nothing in the journal
Sep 23 14:19:58  ticket 5 paid      -> nothing in the journal

events.nostr_event_created_at is still 1789211268 and nostr_event_id still 756fed21…, matching the relay exactly — so no publish succeeded after Sep 12.

The difference from the Sep 5 incident: that one produced six Failed to publish to Nostr WARNINGs — the swallow-and-forget path this issue describes. This one produced no log line at all, success or failure. sold reached 5 and only set_ticket_paid writes it, so the hook definitely ran three more times; it returned through one of the two paths that log nothing at INFO:

nostr_hooks.py:34 — if signer is None: return, a bare return with no log at any level
nostr_publisher.py:175 — if not nostr_client: logger.debug(...), invisible at INFO

Neither is an exception, so neither reaches the except blocks quoted above, and raising those to ERROR wouldn't have surfaced this. Filed as #51 for the logging half.

Implication for the fix proposed here: a nostr_publish_pending marker set on failure would also have missed this, because from the code's point of view nothing failed — it declined to publish. The marker wants to be set before attempting and cleared on confirmed success, so "never attempted" and "attempt failed" both leave drift queryable. The periodic sweep then covers both without caring why.

That strengthens the case for the sweep over in-request retry: it's the only part of the proposal that catches a cause nobody predicted.

(I filed #52 against this before spotting this issue — closed as a duplicate, nothing in it that isn't here or in #51.)

## Second occurrence on cfaun — and a mechanism this issue doesn't cover Same symptom, different path in. Worth recording because the fix proposed here wouldn't have caught it. Event `Q6mhQQzQPSXqkQuFndzXnf` (URU ECSTATIC DANCE), oyez.ariege.io. DB read `amount_tickets=45, sold=5`; the relay served a copy published 2026-09-12 with `tickets_available=48 tickets_sold=2` — 14 days stale. Found the same way as last time: a human noticed a wrong number on a public page. ``` Sep 12 11:05:40 tickets 1+2 paid Sep 12 11:07:47 Published NIP-52 calendar event: 81709fa3... / 756fed21... <- last success Sep 20 13:00:50 lnbits restart; NostrClient connected 13:01:00, subscribed 13:01:05 Sep 21 13:39:01 tickets 3+4 paid -> nothing in the journal Sep 23 14:19:58 ticket 5 paid -> nothing in the journal ``` `events.nostr_event_created_at` is still `1789211268` and `nostr_event_id` still `756fed21…`, matching the relay exactly — so no publish succeeded after Sep 12. **The difference from the Sep 5 incident:** that one produced six `Failed to publish to Nostr` WARNINGs — the swallow-and-forget path this issue describes. This one produced **no log line at all**, success or failure. `sold` reached 5 and only `set_ticket_paid` writes it, so the hook definitely ran three more times; it returned through one of the two paths that log nothing at INFO: - `nostr_hooks.py:34` — `if signer is None: return`, a bare return with no log at any level - `nostr_publisher.py:175` — `if not nostr_client: logger.debug(...)`, invisible at INFO Neither is an exception, so neither reaches the `except` blocks quoted above, and raising those to ERROR wouldn't have surfaced this. Filed as #51 for the logging half. **Implication for the fix proposed here:** a `nostr_publish_pending` marker set on failure would also have missed this, because from the code's point of view nothing failed — it declined to publish. The marker wants to be set *before* attempting and cleared on confirmed success, so "never attempted" and "attempt failed" both leave drift queryable. The periodic sweep then covers both without caring why. That strengthens the case for the sweep over in-request retry: it's the only part of the proposal that catches a cause nobody predicted. (I filed #52 against this before spotting this issue — closed as a duplicate, nothing in it that isn't here or in #51.)

padreug referenced this issue

2026-09-26 21:32:19 +00:00

A lost NIP-52 republish is permanent — nothing reconciles the relay copy #52

padreug referenced this issue

2026-09-26 21:32:43 +00:00

Rebase fork onto upstream v1.6.8 (waves / on-chain / approval reconciliation) #33

padreug referenced this issue from a commit

2026-09-26 21:34:54 +00:00

fix(nostr): log publish skips at WARNING instead of silently

padreug referenced this issue

2026-09-26 21:35:09 +00:00

fix(nostr): log publish skips at WARNING instead of silently #54