Skip to content

feat(event-loop): log block stream gap closures from alloy-internal reconnects (COW-1086) - #65

Closed
brunota20 wants to merge 1 commit into
feat/m5-docker-image-and-cifrom
bruno/cow-1086-ws-reconnect-info-log
Closed

feat(event-loop): log block stream gap closures from alloy-internal reconnects (COW-1086)#65
brunota20 wants to merge 1 commit into
feat/m5-docker-image-and-cifrom
bruno/cow-1086-ws-reconnect-info-log

Conversation

@brunota20

Copy link
Copy Markdown

What this PR does

Adds a positive-recovery Info log when the block subscription resumes after a silence ≥ 60 s. Closes the observability gap surfaced in the 2026-06-23 Sepolia soak: an alloy_transport_ws::native ERROR followed by silence looked identical to a hung engine on the dashboard, because alloy's internal reconnect path bypasses the engine's own reconnecting_block_task and never emits the existing block subscription reopened log line (COW-1071).

Live evidence (2026-06-23 soak)

09:05:43  ERROR  WS connection error: WebSocket protocol error:
                 Connection reset without closing handshake
                 target=alloy_transport_ws::native
(no further WS-related lines for ~1 h)
10:02:24  INFO   indexed watch:...     ← twap-monitor activity resumes
10:05:24  INFO   ethflow observed ...  ← ethflow-watcher activity resumes

docker ps shows 0 restarts and the container stayed healthy throughout. Grep on the engine's own reconnect markers returns zero hits:

$ docker logs shepherd 2>&1 | grep -iE 'reopen|reconnect|healthy|stream ended'
(only the boot-time `subscription open` lines)

So alloy's transport layer reconnected internally without inner.next().await ever returning None — the engine never entered the stream ended → backoff → subscription reopened arm and the existing positive-recovery log never fired.

Change

In reconnecting_block_task, on every yielded item, compare now.duration_since(last_event) against BLOCK_GAP_LOG_THRESHOLD (60 s, 5× Sepolia block time). When the gap meets or exceeds the threshold, emit:

INFO  chain_id=... gap_s=... kind=\"block\"
      \"stream gap closed - first event after silence
       (likely an alloy-internal transport reconnect)\"

The decision logic is factored into a small synchronous helper:

fn block_stream_gap_to_log(
    now: Instant,
    last_event: Option<Instant>,
    threshold: Duration,
) -> Option<Duration>

so it can be unit-tested without an async runtime or a real provider.

Why blocks only

Block subscriptions have predictable cadence (Sepolia and mainnet both produce ~12 s blocks). A 60 s silence is anomalous and worth surfacing. Log subscriptions are inherently sparse (driven by on-chain user activity), so the same threshold would fire false positives during quiet windows — the engine-detectable reconnect path already covers them via the existing log subscription reopened line.

Tests (90 total, all green)

4 new unit tests on the helper:

  • block_stream_gap_to_log_returns_none_when_no_prior_event
  • block_stream_gap_to_log_returns_none_when_under_threshold
  • block_stream_gap_to_log_returns_some_at_threshold_boundary (60 s = 60 s counts as a gap)
  • block_stream_gap_to_log_returns_some_when_well_over_threshold (pinned at the 3600 s of the actual soak gap)
running 90 tests
test result: ok. 90 passed; 0 failed; 0 ignored

cargo clippy -p nexum-engine --all-targets -- -D warnings clean. cargo fmt --check clean.

Out of scope

  • End-to-end test of reconnecting_block_task against a mock provider — no existing scaffolding for that path. The gap helper covers the decision logic deterministically.
  • Suppressing the alloy_transport_ws::native ERROR itself — it is a legitimate transport-layer event, just one whose recovery wasn't previously observable. The new Info line closes that loop without losing the original signal.

Live validation plan

Deploy to the soak VM after review. Next time alloy auto-reconnects internally, the new line surfaces as a structured JSON event with gap_s=<seconds> so the soak dashboard can correlate it with the preceding transport ERROR.

Linear

Resolves COW-1086.

AI assistance disclosure: drafted by Claude (Opus 4.7, 1M context) following the 2026-06-23 soak inspection.

…econnects (COW-1086)

Adds a positive-recovery Info log when the block subscription
resumes after a silence ≥ 60 s, covering the observability gap
identified in the 2026-06-23 Sepolia soak.

## Background

The 2026-06-23 soak surfaced this sequence:

    09:05:43  ERROR  WS connection error: WebSocket protocol error:
                     Connection reset without closing handshake
                     target=alloy_transport_ws::native
    (no further WS-related lines for ~1 h)
    10:02:24  INFO   indexed watch:...     ← twap-monitor activity resumes
    10:05:24  INFO   ethflow observed ...  ← ethflow-watcher activity resumes

`docker ps` showed 0 restarts and the container stayed healthy
throughout — alloy's transport layer reconnected internally without
the engine's `reconnecting_block_task` ever observing
`inner.next().await -> None`. So the engine never entered its
"stream ended → backoff → subscription reopened" path, and the
existing `block subscription reopened` Info log (COW-1071) never
fired. The transport-layer ERROR followed by silence is
indistinguishable from a hung engine on a soak dashboard.

## What changes

In `reconnecting_block_task`, on every yielded item compare
`now.duration_since(last_event)` against `BLOCK_GAP_LOG_THRESHOLD`
(60 s, 5× Sepolia block time). When the gap meets or exceeds the
threshold, emit:

    INFO  chain_id=... gap_s=... kind="block"
          "stream gap closed - first event after silence
           (likely an alloy-internal transport reconnect)"

The gap-detection logic is factored into a small synchronous helper
`block_stream_gap_to_log(now, last_event, threshold) -> Option<Duration>`
so it can be unit-tested without spinning up an async runtime or a
real provider.

## Why blocks only (not logs)

Block subscriptions have predictable cadence — Sepolia produces a
new block every ~12 s, mainnet every ~12 s. A 60 s silence is
therefore anomalous and worth surfacing. Log subscriptions, by
contrast, are inherently sparse (driven by on-chain user activity),
so the same threshold would fire false positives on quiet windows.
The existing `log subscription reopened` log already handles the
engine-detectable reconnect for log streams.

## Tests

4 new unit tests on the gap-detection helper:

  * `block_stream_gap_to_log_returns_none_when_no_prior_event`
  * `block_stream_gap_to_log_returns_none_when_under_threshold`
  * `block_stream_gap_to_log_returns_some_at_threshold_boundary`
  * `block_stream_gap_to_log_returns_some_when_well_over_threshold`

All 90 nexum-engine tests pass (86 existing + 4 new). Clippy strict
clean, fmt clean. Wasm build untouched.

## Out of scope

* End-to-end test of `reconnecting_block_task` against a mock
  provider — no existing scaffolding for that path, and the gap
  helper covers the decision logic deterministically.
* Suppressing or downgrading the `alloy_transport_ws::native` ERROR
  itself — it is a legitimate transport-layer event, just one whose
  recovery wasn't previously observable. The new Info line closes
  that loop without losing the original signal.

## Live validation

The next time alloy auto-reconnects internally on the soak VM, the
new line will surface as a structured JSON event with
`gap_s=<seconds>` so the soak dashboard can correlate it with the
preceding transport ERROR.
@linear-code

linear-code Bot commented Jun 23, 2026

Copy link
Copy Markdown

COW-1086

@brunota20

Copy link
Copy Markdown
Author

Live validation note (2026-06-23 14:00 UTC)

Combined with the rest of the redesign + fix bundle on deploy/cow-1076-observe-on-m5 and deployed to the Sepolia soak VM. Container Up healthy with the new image since 13:56:50 UTC. Will accumulate live evidence in the next observation window.

Companion PRs (same redesign / soak deploy bundle)

PR Concern Layer
#62 ethflow-watcher: observe + verify (replaces submit) M2 (BLEU-833 alternative)
#63 ethflow-watcher: same redesign with BLEU-855 split M3/M4 (COW-1074 base)
#64 twap-monitor: skip submit on already-submitted UID M5 (COW-1085)
#65 nexum-engine: gap-closed log on alloy-internal reconnect M5 (COW-1086)

Each is single-concern; the deploy branch is the cumulative integration point and will fold into latest once the stack lands.

@brunota20

Copy link
Copy Markdown
Author

Superseded by deploy branch commit 59d09eb feat(event-loop): log block stream gap closures from alloy-internal reconnects (COW-1086) (now in dev/m5-base). Closing as merged via different commit.

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