Skip to content

IBD stuck #421

Closed
Closed

Description

@dpc
◆ **Found it: rbitcoin stopped advancing immediately after persistent `io_uring` store failures.** The sustained `eta=?` appeared about 34 minutes later.

### Timeline — September 10, Pacific time

| Time             | Event                                                          |
| ---------------- | -------------------------------------------------------------- |
| **14:29:05 PDT** | Persistent `io_uring undrained` and batch-queue warnings begin |
| **14:29:14 PDT** | Last height advance: **904002**                                |
| **14:30:04 PDT** | Same height, already reporting **0.0 blocks/s**                |
| **15:03:17 PDT** | ETA finally becomes `?` and stays there                        |

At **09:58 PDT on September 11**, it was still at height 904002—roughly **19½ hours without progress**, despite remaining active with **16 peers**.

These are the useful developer-facing lines, with UTC timestamps:

```text
2026-09-10T21:29:05Z WARN store: io_uring invariant undrained pending=73 epoch=12617 thread=ibd-confirm-write (Corrupt; not a TipOnly miss)
2026-09-10T21:29:05Z WARN ibd: bq resolve wave: store: corrupt record: invariant: io_uring undrained
```

The batch-queue warning repeated **3,499 times** through our observation. An earlier lookup-thread failure also reported `io_uring session poisoned`, although progress continu
ed for a while afterward.

**This strongly points to the undrained/poisoned store I/O path. It does not establish actual on-disk corruption**, despite the error wording, or distinguish an application bu
g from a kernel/storage problem.

I’d preserve the process and datadir until the developer has this evidence and can suggest targeted diagnostics or recovery. **Nothing was restarted or changed.**

Full report:

# rbitcoin stall investigation — ren (read-only)

**Finding:** the current rbitcoin invocation is genuinely stalled. `eta=?` became sustained at **2026-09-10 15:03:17 PDT** (**22:03:17Z**), but the actual last observed tip advance was earlier: **14:29:14 PDT** (**21:29:14Z**), at height `904002`. The primary correlated evidence is a recurring rbitcoin `io_uring` store invariant failure that began nine seconds before that final height advance.

## Current observation

Observed **2026-09-11 09:58:59 PDT** (**16:58:59Z**):

- `rbitcoin.service` was active/running, current invocation since **2026-09-10 14:05:51 PDT**; main PID `2594022`.
- Latest progress at **09:58:55 PDT** remained: `progress 93% tip=904002 (0.0/s) ... peers=16 ... eta=?`.
- Thus, at the observation point, the `eta=?` state had persisted **18h55m42s**, and no observed height advance for **19h29m45s**.
- The running package identifies itself as `rbitcoin-0.6.99`; the Nix lock pins rbitcoin revision `f3705ab6dde773796278472f57cac6c5e09e1c34`.

## Timeline (PDT; UTC is PDT + 7h)

- **14:05:51** — current service invocation started.
- **14:06:20** — first `eta=?`, but this was a startup placeholder only: it returned to a finite ETA (`24h`) at **14:06:35** while the tip advanced.
- **14:18:33** — first `store: io_uring invariant undrained pending=47 ... thread=ibd-confirm-lookup`; **14:18:38** followed with `io_uring session poisoned`. IBD continued making height progress afterward.
- **14:29:05** — `store: io_uring invariant undrained pending=73 ... thread=ibd-confirm-write`; at the same second the first recurring warning appeared: `ibd: bq resolve wave: store: corrupt record: invariant: io_uring undrained`.
- **14:29:14** — last observed tip advance: `tip=904002 (2.2/s) ... eta=2.8h`.
- **14:30:04** — still `tip=904002`, already reporting `0.0/s`; ETA was finite but rising (`4.1h`). It rose continuously through days/years as the denominator decayed.
- **15:03:17** — first sustained `eta=?`: still `tip=904002 (0.0/s)`. It has never returned to finite ETA in this invocation.
- **09:58:52, Sep 11** — recurrent `bq resolve wave ... io_uring undrained` warning still emitted; summary scan counted **3,499** occurrences from 14:29:05 through that point, roughly every 20 seconds.

No rbitcoin `ERROR` or `FATAL` records appeared after this invocation began (based on journal level text). The service remains live and reports 16 peers, so this does not look like a process exit or simple peer-loss stall.

## Interpretation and limits

The temporal correlation is strong: persistent zero progress begins immediately after the second `io_uring` invariant failure, while the later `eta=?` marker is the estimator finally giving up after about 34 minutes of no progress. The developer's `eta=?` heuristic correctly identifies the sustained stall, but the more useful boundary for diagnosis is **14:29:05 PDT / 21:29:05Z**.

Read-only inspection of the *pinned* source confirms that `io_uring undrained` is emitted when pending requests remain after a drain, and that this IBD batch-queue path warns on non-backpressure store errors. This establishes the log's software meaning, but **does not prove on-disk data corruption** or establish whether the triggering fault was rbitcoin, io_uring/kernel, filesystem, or hardware.

A bounded `host-monitor ren kernel-warnings 200 1200` query returned only a TCP/GRO warning at **19:13:49 PDT**, after the stall. It returned no storage warning, but it is not a complete disk/filesystem health check. I did not inspect the datadir, bypass privileges, make network/RPC probes, or change/restart anything.

## Safe next step

Preserve the current process and datadir; do **not** restart or delete/reindex state before the rbitcoin developer advises. Send the developer this compact boundary and the two exact recurring messages:

```text
2026-09-10T21:29:05Z WARN store: io_uring invariant undrained pending=73 epoch=12617 thread=ibd-confirm-write (Corrupt; not a TipOnly miss)
2026-09-10T21:29:05Z WARN ibd: bq resolve wave: store: corrupt record: invariant: io_uring undrained
last height advance: 2026-09-10T21:29:14Z, tip=904002
sustained eta=?: 2026-09-10T22:03:17Z
package/revision: rbitcoin-0.6.99 / f3705ab6dde773796278472f57cac6c5e09e1c34
```

Ask for a version-specific, data-preserving diagnostic/recovery procedure for a poisoned/undrained io_uring session. Any substantive fix belongs in the rbitcoin project, not this Nix configuration checkout.

Activity

  1. reardencode commented on Sep 11, 2026

    @reardencode
    Owner

    Tyvm, we'll investigate

  2. rearden-grok commented on Sep 11, 2026

    @rearden-grok
    Contributor

    Working theory from the logs (not a confirmed root cause).

    f3705ab is 14 commits after v0.6.0. None of those touch the confirm/io_uring drain path, so this is not a post-0.6 product delta.

    The repeating ibd: bq resolve wave: … io_uring undrained is a lookup-thread store error. That path only warns and retries the same body-queue wave; it does not reject the block or halt IBD. Drain is capped (~5s), so a failed TipOnly wave can sit on a ~20s cadence indefinitely while P2P stays up — which matches ~3,499 warnings and 19h at height 904002 with 16 peers.

    The stall boundary is the earlier write-thread line:

    store: io_uring invariant undrained pending=73 epoch=12617 thread=ibd-confirm-write
    

    That is leftover SQEs after drain_all on a large confirm pwrite/RMW wave (ring depth 128). The session is poisoned and dropped. Lookup then flipping from a one-off poison (14:18, IBD still advanced) to persistent undrained is consistent with completions no longer arriving after that write drain, not with on-disk record corruption.

    Please keep the process and datadir as they are until we have a recovery/diagnostic step. A restart may well resume; it would also throw away the wedged kernel/ring state we would want to inspect.

  3. reardencode commented on Sep 11, 2026

    @reardencode
    Owner

    Can you tell us what kind of drive your datadir is on?

  4. dpc commented on Sep 11, 2026

    @dpc
    Author

    bcachefs accross two identical nvme drives

    ⦸> lsblk -N
    NAME    TYPE MODEL                                    SERIAL                REV TRAN   RQ-SIZE  MQ
    nvme0n1 disk Lexar SSD NM790 4TB                      QB134263W94201279        nvme       256  16
    nvme1n1 disk Lexar SSD NM790 4TB                      PMP34263W942P2202        nvme       256  16
    

    Quite possibly it has something to do with bcachefs, wouldn't be a first. Such is a life of leading on the edge.

  5. reardencode commented on Sep 11, 2026

    @reardencode
    Owner

    Ahhh, good to know. Probably there was a write stall relating to the underlying FS which delayed the CQE completion and triggered the bug. Still a bug in rbitcoin though.

  6. dpc commented on Sep 11, 2026

    @dpc
    Author

    Worth considering that I'm running it with absolutely lowest IO&CPU priority, as explained in #408

  7. reardencode commented on Sep 11, 2026

    @reardencode
    Owner

    grok and I will make rbitcoin handle slow write IO more gracefully. In the meantime, a restart may well recover without corruption, but there's a chance it's all effed up :-\

  8. dpc commented on Sep 11, 2026

    @dpc
    Author

    I'm happy to be a guinea pig and IBD multiple times, no worries.

    But yeah - IIUC I'm torture testing I guess with batch CPU scheduling and IDLE IO scheduling which will effectively delay stuff nearly indefinitely.

  9. reardencode commented on Sep 11, 2026

    @reardencode
    Owner

    Ok. We've got a good fix PR in progress.

    Short version of the issue that we had a global per-batch timeout of 5s on both reads and writes. Reards exceeding that was harmless and retried safely. Writes hadn't exceeded it on my machine, so we hadn't dealt with what happens when writes are left in a mixed state as a result.

    Two fixes happening: 1) we'll now timeout on progress stalling not a total of 5s for a whole batch of reads/writes. That reduced the incidence of a slow write causing an abort and 2) if we do abort, we'll recover gracefully as long as it's only occasional. If it becomes frequent, we'll abort the process and advise the operator of the issue.

  10. added a commit that references this issue on Sep 11, 2026
  11. dpc commented on Sep 11, 2026

    @dpc
    Author
    ◆ **Recommend changes: two P1 correctness issues** in PR #425 at `6b52dac20024`.
    
    ### 1. Post-commit recovery can report success without completing the failed operation
    
    **Locations:** `crates/rbitcoin-net/src/chain.rs:2042–2055`; `crates/rbitcoin-net/src/i
    bd/confirm/mod.rs:1497–1530`
    
    Class C commits **before** spend annotation and the final `tx.head` drain. If either su
    bsequently returns a session fault, the new tip-connect recovery loop retries—but the e
    xisting “already connected” shortcut immediately returns success without repeating the
    failed operation.
    
    With the spend index enabled, this can leave missing annotations and produce **false-un
    spent query results**. Tip entry does not automatically repair those annotations.
    
    The IBD path has a related gap: its existing `has_block` shortcut runs before the new r
    ecovery handler, so post-commit faults bypass recovery-credit accounting.
    
    **Fix:** Resume or idempotently repeat incomplete post-commit work rather than treating
     tip presence as completion. Add a regression injecting a session fault after Class C a
    dvances.
    
    ### 2. Load recovery retains the abandoned plan’s FK reservations and pins
    
    **Locations:** `crates/rbitcoin-net/src/ibd/confirm/mod.rs:1847–1860, 1952–1962`
    
    Before materialization, `note_lookup_ok` advances `LoadAheadState::next_tx_start` and i
    nserts the plan’s creates into `in_flight`. If materialization returns a session fault,
     the new recovery branch only requeues the hashes and continues.
    
    Nothing resets that speculative state: `requeue_hashes` only updates the feed, and the
    skipped HWM synchronization would not roll reservations back anyway. Retried plans can
    therefore receive FKs beyond the durable append position, causing **planned/actual FK m
    ismatches**; later waves can also resolve parents through an abandoned pack.
    
    **Fix:** Invalidate dependent queued work and rebuild load-ahead state from durable Cla
    ss A state before retrying. Test a fault after `note_lookup_ok`, asserting that retry u
    ses the correct contiguous FK range.
    
    ---
    
    **Scope:** Read-only store/drain and recovery-integration review; no tests or CI rerun.
     No GitHub review posted. The preliminary buffer-lifetime concern was withdrawn because
     it predates this PR; it is not included above.
    

    Out of curiosity I asked a clanker to review and it said this. Not sure if this is helpful, so feel free to tell me not to do that. @reardencode

  12. reardencode commented on Sep 11, 2026

    @reardencode
    Owner

    Thanks - what model, out of curiosity? I'll go over these with my clanker as well. I had a slight feeling there might be regressions hiding in the retry logic.

  13. dpc commented on Sep 12, 2026

    @dpc
    Author

    Thanks - what model, out of curiosity? I'll go over these with my clanker as well. I had a slight feeling there might be regressions hiding in the retry logic.

    Sol, medium effort, using https://radicle.network/nodes/radicle.dpc.pw/rad:z2HR882B4c4mTdAgdt4SozpdeTuMf#multipart-review

    @reardencode

  14. dpc commented on Sep 13, 2026

    @dpc
    Author

    I updated to 0.6.1 and it synced to the tip without any other intervention. 👍

  15. reardencode commented on Sep 13, 2026

    @reardencode
    Owner

    Good news! Thanks so much for testing!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions