Skip to content

observability(events-ws): log per-PP event delivery + drop reasons on the listener#116

Merged
AquiGorka merged 1 commit into
mainfrom
observability/per-pp-ws-listener-emit-log
Jun 9, 2026
Merged

observability(events-ws): log per-PP event delivery + drop reasons on the listener#116
AquiGorka merged 1 commit into
mainfrom
observability/per-pp-ws-listener-emit-log

Conversation

@AquiGorka

Copy link
Copy Markdown
Contributor

Working from: /Users/theahaco/repos/pm-theahaco/prompts/force-evidence-based-testnet-validation-1-prompt.md

What this addresses

Per-PP events emitted by verifier.process.handleVerificationSuccess (verifier.bundle_completed, bundle.deposit_completed, bundle.withdraw_completed) inconsistently fail to reach the harness on deployed testnet. Failure window log slice for the most recent sweep:

$ jq -cs --arg start "2026-06-09T16:33:25Z" --arg end "2026-06-09T16:37:43Z" \
    'map(select(.timestamp >= $start and .timestamp <= $end)) | length' \
    provider-platform-logs.json
0

Zero log lines. The handler's existing events WS opened / events WS closed / events WS error (ws-handler.ts:156, 161, 165) also did not fire — so the per-PP WS lifecycle for the failing PP cannot be reconstructed from logs at all.

The listener gap

ws-handler.ts:140-149 (pre-fix):

const listener = (event: ProviderEvent) => {
  if (event.scope.ppPublicKey !== boundPpPublicKey) return;
  if (socket.readyState !== WebSocket.OPEN) return;
  try {
    socket.send(JSON.stringify(event));
  } catch (error) {
    log.debug("kind", event.kind);
    log.error(error, "failed to send event over WS");
  }
};

The listener has no log for the happy path (event matched + sent) and no log for the early-return on readyState !== OPEN. The only listener log fires on socket.send throwing.

Change

Add .event() + .debug() calls for both branches inside the listener. No behavioral change. No new dependencies. No config touched.

     const listener = (event: ProviderEvent) => {
       if (event.scope.ppPublicKey !== boundPpPublicKey) return;
-      if (socket.readyState !== WebSocket.OPEN) return;
+      if (socket.readyState !== WebSocket.OPEN) {
+        log.debug("kind", event.kind);
+        log.debug("readyState", socket.readyState);
+        log.event("event dropped: WS not OPEN");
+        return;
+      }
       try {
         socket.send(JSON.stringify(event));
+        log.debug("kind", event.kind);
+        log.event("event sent to WS");
       } catch (error) {
         log.debug("kind", event.kind);
         log.error(error, "failed to send event over WS");
       }
     };

Failure output that motivates this (verbatim, sweep.log)

[events-capture] FAIL — script testnet-main — run testnet-main-2026-06-09T16-37-42-906Z
[events-capture]   perPp:GAFBCHCG5TOPHUPT6DY3S26BJ5X5DYHCA2OVFPDSU7VSDE3ZOMO2ZUGW: FAIL — expected 12, captured 9
[events-capture]   network: PASS (5/5)
    [0] OK   kind="channel.provider_added"
    [1] OK   kind="mempool.bundle_added"
    [2] OK   kind="executor.transaction_submitted"
    [3] OK   kind="verifier.bundle_completed"
    [4] OK   kind="bundle.deposit_completed"
    [5] OK   kind="mempool.bundle_added"
    [6] OK   kind="executor.transaction_submitted"
    [7] DIFF kind mismatch: expected "verifier.bundle_completed" got "mempool.bundle_added"
    [8] DIFF kind mismatch: expected "mempool.bundle_added" got "executor.transaction_submitted"
    [9] MISS expected "executor.transaction_submitted" not received
    [10] MISS expected "verifier.bundle_completed" not received
    [11] MISS expected "bundle.withdraw_completed" not received

Test plan

  • deno fmt, deno lint, deno check src/http/v1/events/ws-handler.ts clean
  • deno test src/http/v1/events/ — 1/1 (existing WS-stays-OPEN test unchanged and still passing)
  • deno.json: 0.7.6 → 0.7.7 (auto-tag precondition)
  • After merge + testnet deploy: re-run a sweep; quote the new listener log lines from flyctl logs for the failure window to confirm whether missing per-PP events are dropped at the listener-OPEN gate or never reach the listener.

… the listener

The per-PP WS listener at `src/http/v1/events/ws-handler.ts:140-149`
silently dropped events when `socket.readyState !== WebSocket.OPEN` and
silently delivered them when OPEN. Neither path emitted a log line, so
the failure window of a sweep that shows missing per-PP events on the
harness side is invisible in `flyctl logs`.

Concrete failure that motivates this: sweep
`testnet-main-2026-06-09T16-37-42-906Z`, window 16:33:25Z–16:37:43Z,
expected `perPp 12/12`, captured 9. Missing: 2× `verifier.bundle_completed`
+ 1× `bundle.withdraw_completed`. Provider-platform `flyctl logs` slice
for the window: 0 lines. The handler's existing `events WS opened` /
`events WS closed` / `events WS error` logs at lines 156/161/165 also
did not fire, so the WS lifecycle for the failing PP cannot be
reconstructed from logs at all.

Change: inside the listener (no behavioral change), add `.event()` +
`.debug()` calls for both branches:
  - `event sent to WS` on the happy path (with kind)
  - `event dropped: WS not OPEN` on the early-return (with kind + readyState)

Existing error log on send failure (line 147) is unchanged.

Next sweep's failure window will show whether the missing events were
emitted to the bus and dropped at the listener gate, or never reached
the listener at all.
@AquiGorka AquiGorka merged commit cae4b76 into main Jun 9, 2026
7 checks passed
@AquiGorka AquiGorka deleted the observability/per-pp-ws-listener-emit-log branch June 9, 2026 17:37
AquiGorka added a commit that referenced this pull request Jun 10, 2026
## Why

Provider-platform runs multi-machine on Fly. The previous in-process
`EventBus` only delivered events to subscribers on the same machine as
the emitter. Fly proxy load-balances HTTP requests across machines, so a
bundle POST lands on machine A while the WS subscriber for that PP is
held on machine B — A's local emit goes to A's bus only, B's WS
subscriber never sees it.

Diagnosed in the `add-events-capture-framework-1` thread (2026-06-09)
with verbatim Fly logs from PRs #115 + #116:

> For a withdraw bundle, events 1–8 (deposit + send, processed on the
same machine as the WS) all delivered with `event sent to WS` log lines.
Events 9–12 (withdraw, processed on the other machine) had
`EventBus.emit` log lines on the other machine but ZERO matching `event
sent` or `event dropped` lines anywhere — the listener literally doesn't
exist on the emitter's process.

Workaround currently in place: testnet's second machine has autostart
disabled (`flyctl machine update --autostart=false`), forcing
single-machine. Mainnet is also single-machine today. This PR makes that
workaround unnecessary so capacity scaling can land later.

## Design

Replace the in-process bus with a Postgres NOTIFY/LISTEN-backed
implementation:

- **Single channel** `provider_events` for the entire `ProviderEvent`
taxonomy. Receivers deserialize and dispatch by `kind`. No
per-event-type channels, no event persistence table.
- **Single-path delivery**: `emit()` ONLY fires `NOTIFY provider_events
<payload>` via the existing drizzle Postgres pool. Even local emitters
round-trip through Postgres — adds ~5–20 ms latency but means there is
one delivery path to debug. No dedup needed, no "did this fire twice"
question.
- **Dedicated listener task per machine**: `startPgListener(deps)` boots
a separate `postgres()` client (NOT the drizzle pool — `LISTEN` reserves
its connection for the subscription's lifetime), calls
`sql.listen('provider_events', onNotify, onListen)`, and on every
notification parses the JSON and calls into the bus's internal
`publishLocal()` — driving local subscribers without re-triggering
NOTIFY.
- **Payload-size guard**: defensive `payload.length < 7900` bytes check
at emit time (Postgres NOTIFY cap is 8000). Oversize events are logged +
dropped rather than thrown back into the caller's already-committed
transaction. Worst-case audited payload (verifier.bundle_completed with
100 sha256-hex bundle IDs) is ~7,060 bytes — under the guard with ~12%
headroom. Defensive guard captures whatever future bundle-ID format
pay-platform may send.
- **Reconnect**: `postgres@^3.4.7`'s `sql.listen` ships its own
reserved-connection reconnect logic. The `onlisten` callback fires on
every (re-)subscribe so we log each recovery. Start-from-now semantics
during disconnect windows — subscribers backfill themselves if needed
(out of scope for the transport).
- **Boot order**: `pgListener` subscribes first, `setNotifier()` wires
the NOTIFY transport on the bus second, then mempool / event-watcher /
HTTP server start. Until `setNotifier()` is called, the bus falls back
to in-process loopback — used in tests and during boot before transport
is up.
- **No call-site changes**: the bus's public `emit` + `subscribe`
surface is preserved byte-for-byte. `emit-helpers.ts`, `ws-handler.ts`,
and the integration test only update their import paths.

## Files

**Added:**
- `src/core/service/events/pg-notify-event-bus.ts` — new bus impl with
`emit` + `subscribe` + internal `publishLocal` + `setNotifier`.
- `src/core/service/events/pg-listener.ts` — long-lived LISTEN task with
shutdown hook.
- `src/core/service/events/pg-notify-event-bus.test.ts` — 9 unit tests
covering subscribe/publishLocal, loopback fallback, single-path-delivery
invariant, oversize-drop, NOTIFY-rejection swallow, and the simulated
cross-machine round-trip.
- `tests/integration/events/cross-machine-events.test.ts` — 3
integration tests using PGlite's native LISTEN/NOTIFY API to exercise
the same wire path (serialize → NOTIFY → LISTEN → parse → publishLocal →
subscriber) across separate connections to a shared backend.

**Removed:**
- `src/core/service/events/event-bus.ts` — direct replacement, no
feature flag, no parallel old + new.

**Modified:**
- `src/core/service/events/index.ts` — re-export `PgNotifyEventBus`,
`startPgListener`, `PROVIDER_EVENTS_CHANNEL`.
- `src/core/service/events/emit-helpers.ts`,
`src/http/v1/events/ws-handler.ts`,
`tests/integration/http/events-ws.test.ts` — import path only.
- `src/main.ts` — boot order: `startPgListener` →
`setNotifier(pgClient.notify)` → mempool/event-watcher/HTTP. Shutdown
handler awaits listener teardown.
- `src/persistence/drizzle/config.ts` — export the raw `postgres-js`
client so the bus's NOTIFY uses the existing pool.

## Local multi-machine smoke

Ran a narrowed smoke against an isolated Postgres (port 5443, not
touching any other local stack) with two `provider-platform` processes
from this branch HEAD (ports 3110 + 3111, same `DATABASE_URL`).

**Boot order on each instance:**
```
EVT -starting pgListener
EVT -LISTEN provider_events subscribed
EVT -pgListener started
EVT -NOTIFY transport wired
EVT -server running on http://localhost:31XX
```

**Cross-machine delivery via psql `pg_notify`:**
- Fired from a third connection: `SELECT pg_notify('provider_events',
'<mempool.bundle_added JSON>');`
- Instance A receipt: `13:14:59.600 DBG kind: mempool.bundle_added
(main.PgNotifyEventBus)`
- Instance B receipt: `13:14:59.600 DBG kind: mempool.bundle_added
(main.PgNotifyEventBus)`
- Same timestamp, 1 ms processing on each instance.

**Production transport via `postgres@3.4.7 sql.notify`:**
- Standalone script: `await sql.notify('provider_events',
JSON.stringify(event))` against the same DB.
- Instance A: `13:16:08.085 DBG  kind: executor.transaction_submitted`
- Instance B: `13:16:08.084 DBG  kind: executor.transaction_submitted`
- 1 ms cross-instance delivery via the exact wire format production
uses.

**Clean shutdown via SIGTERM:**
```
EVT -shutting down server
EVT -stopping pgListener
EVT -pgListener stopped       (3 ms after stop)
```

Two-machine `local-dev/testnet/run-local.sh all` was NOT run against the
full local-dev stack — PM-acked, deferred to post-merge verification.

## Out of scope

- network-dashboard-platform — uses the same pattern but its `bus.ts`
docstring explicitly calls itself "single-instance per env by design".
Separate future thread.
- council-platform, pay-platform — audited, no EventBus / WS handler.
- Re-enabling provider-platform's second-machine autostart on
testnet/mainnet — follow-up PM action once this lands.

## Test plan

- [x] `deno fmt --check`
- [x] `deno lint`
- [x] `deno check src/main.ts`
- [x] `deno task test:unit` — 74 passed (9 new on PgNotifyEventBus)
- [x] `deno task test:integration` — 99 passed (3 new on cross-machine
delivery)
- [x] `deno task test` (full) — 116 passed
- [x] Local two-instance smoke: psql NOTIFY + postgres-js `sql.notify`
both deliver to both instances within 1 ms; SIGTERM shuts pgListener
cleanly.
- [ ] Two-machine `local-dev/testnet/run-local.sh all` against the full
local-dev stack — PM-deferred to post-merge.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant