Skip to content

send_durable_inline_text intermittent hang on postgres backend — race in sync path before runtime.block_on (CIRISPersist#139 closure) #58

Closed

Description

@emooreatx

Tracking the edge-side fix for CIRISPersist#139

Persist closed their side of #139 with a thorough investigation that pointed at edge: the postgres durable-send 'no reactor running' panic — and the related silent hang — is in edge's runtime entry, not in persist's enqueue_outbound. Confirmed via local repro at edge 1.1.5 against postgres:

  • 25-30% hang rate on a single `send_durable_inline_text` against postgres
  • Hang shows up at the send call; `init_edge_runtime` always completes
  • Tokio runtime is idle during the hang (32 workers parked, 1 in ep_poll, no trace events after the call enters Rust)
  • The future never gets polled — the hang is in the sync portion of `PyEdge::send_durable_inline_text` before `runtime.block_on(fut)` reaches first poll
  • Same race on persist v3.9.0 AND v3.11.0; not a persist regression

Full diagnostic + thread dump: CIRISPersist#139 comment.

Candidate fix paths

Path A — `run_async` `Handle::try_current` reachability audit (src/ffi/pyo3.rs:1231)

The function takes the `block_in_place` branch when `try_current` returns Ok. The Python main thread isn't a tokio worker, so this branch should never be taken from the conformance subprocess script. If something is installing a runtime context on the main thread before the send (verify v4.7.1's lazy `ciris_verify_init` from the .init_array fix is a candidate), `try_current` returns Ok inappropriately and `block_in_place` deadlocks or misroutes the future polling.

Verify by: log RUST_LOG=ciris_edge=trace on every `run_async` entry, count which branch is taken for the failing call. If the if-branch fires, defend against it (replace `block_in_place` with the else-branch logic when `try_current().handle().id()` doesn't match `runtime.id()`).

Path B — tokio::sync::Mutex contention with init_edge_runtime's spawned tasks

`init_edge_runtime` starts background tasks (the Reticulum listener, the inbound dispatcher loop). If any of edge's internal state (`queue`, `metrics`, `events`, `reachability`) is wrapped in a `tokio::sync::Mutex` held across an `.await` by one of those tasks AND that mutex is acquired by `send_durable_inline_text`'s sync path or its early await, you'd see exactly this hang.

Verify by: audit `tokio::sync::Mutex` / `RwLock` uses across Edge's fields; check whether any are held across awaits by the dispatch loop.

Repro

```bash
docker run -d --name conformance-pg -e POSTGRES_USER=postgres -e POSTGRES_PASSWORD=postgres \
-e POSTGRES_DB=conformance -p 5433:5432 postgres:16
python3 -m venv /tmp/v && source /tmp/v/bin/activate
pip install ciris-edge==1.1.5 ciris-persist==3.11.0 ciris-verify==4.8.0

(or use v1.1.6 once published)

loop 30x; each subprocess does Engine + init_edge_runtime + send_durable_inline_text

expect ~25% hang rate

```

Phase-instrumented harness: `/tmp/edge139/repro_instrumented.py` on the box that filed this.

Closure

When fixed: CIRISConformance `test_050_send_receive.py::test_durable_send_enqueues_to_outbound_queue` postgres-side xfail flips back to a real both-backends gate. Currently strict=False on postgres (sometimes passes, often hangs to xfail).

Cross-links

  • CIRISPersist#139 — the upstream report + persist's diagnosis hand-off
  • CIRISConformance test_050_send_receive — the gate that catches the regression

Activity

  1. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    Leviculum-side root-cause fix is merged — Edge can proceed

    The panic this issue traces to (spawn_traffic_counter building tokio::time::interval inside a tokio::spawn at reticulum-std/src/interfaces/mod.rs:134, which panics with "timers are disabled" when the embedding wheel's runtime is built without enable_time()) is fixed and merged to leviculum main.

    Action: bump the leviculum pin d3238e4 → fea04c161cb3473e31743cfb68b72153e2953f14 (CIRISAI/Leviculum PR #3).

    The #58 fix (commit e3f4a6e)

    spawn_traffic_counter now runs on a dedicated OS thread (std::thread::sleep, no time-driver dependency) holding a Weak to the stats map, so it self-terminates when the node drops. A regression test builds exactly the embedder runtime (current-thread, no enable_time) and asserts no panic. This removes the dependency on how the host wired its runtime — no Edge-side enable_time() workaround needed.

    Also bundled in this bump (validated, not just the #58 fix)

    • RNS shared-instance RPC now speaks msgpack as well as pickle (RNS ≥1.3.x migrated codec) — auto-detected by leading byte. rnstatus/rnpath/rnprobe interop again.
    • Dependency trim 198 → 189 crates (tokio feature-narrow, clap/cbindgen default-features off). no_std reticulum-core unchanged at 35 — i.e. Edge's carried surface is leaner.
    • GitHub Actions CI now gates leviculum — including a cross-check pre-flight that cargo checks reticulum-core on Edge's targets (android arm64/x86_64/armv7 + aarch64-apple-ios), so a leviculum change that breaks an Edge target fails in leviculum CI, not Edge's heavier pipeline.

    Validation

    Interop 258/258 on Python 3.10 and 3.12 (RNS 1.3.5); core 1107 + std 218 unit tests green; full GitHub Actions matrix green on the merge commit.

    One unrelated known gap (does not affect Edge): an intermittent Tier-2 Docker-suite discovery-timing flake, tracked as leviculum #4.

  2. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    Second root-cause fix merged — pin this for v1.1.8 (no xfail needed)

    The residual hang after fea04c1 (which took the durable-send hang 100% → ~45%) was a second tokio-timer panic site: the node's event loop (driver/mod.rs, sleep_until) and interface timers were spawned onto the embedder's runtime, so a PyO3 host that built its runtime without enable_time() panicked the event-loop task on first poll → hang. The #58 OS-thread trick couldn't cover this because an async select! event loop fundamentally needs real timers.

    Fixed in CIRISAI/Leviculum PR #7 — bump the pin fea04c1 → e8baf4d24cc377314a8c4acf149224e068eb9d68.

    What changed

    ReticulumNode::start() now builds and owns a time-enabled multi_thread runtime, and enters it before spawning — so the event loop, every interface, and all child tasks run on a runtime independent of how the host configured its own. Restart-safe; torn down via shutdown_background() in stop()/Drop (no blocking Runtime drop in a host async context, including on start() error paths — caught in review).

    This means no Edge-side enable_time() workaround and no xfail mask — the durable-send race is fixed at the root in Leviculum.

    Validation

    • Regression test: a host runtime built without enable_time() → node start/run/stop is clean (pre-fix: event-loop JoinError).
    • core 1107 + std lib tests, interop 258/258 (Python 3.10 + RNS 1.3.5), full GitHub Actions matrix green on the merge commit (incl. macOS + android/iOS cross-checks).

    Expectation: combined with fea04c1, this should take the durable_send_postgres hang to 0%. Please re-run your 20× harness against e8baf4d before cutting v1.1.8; if any residual remains, post the panic/backtrace and I'll chase it.

  3. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    Validation against e8baf4d: 75 → 80% pass; residual deadlock (not a panic)

    Re-ran the 20× harness against `leviculum e8baf4d24cc377314a8c4acf149224e068eb9d68` + persist 3.12.1 + edge 1.1.8-code (the v1.1.7 codebase with the diagnostic harness, persist pin bumped to 3.12.1, leviculum at this PR's HEAD). Three consecutive runs:

    ```
    20 rounds, timeout=4s, panic-log armed
    fast: 16 (80%)
    hung: 4 (20%)
    panic: 0
    other: 0
    ```

    Repeated against 30 rounds; same ~20% ± rate.

    What changed vs the earlier 45% (fea04c1)

    • 0 panics captured — fully fixed. The panic log file (the in-process std::panic::set_hook capture, raw IPs via backtrace::trace, dladdr → <basename>+<offset>) is 0 bytes across every subprocess. The two panic sites that fea04c1 + e8baf4d closed (spawn_traffic_counter and the event-loop sleep_until) are confirmed gone end-to-end.
    • Hang rate halved (45% → 20%). Meaningful improvement but not the predicted 0%.

    Residual shape — deadlock or missed wakeup, not a panic

    Every hang reaches post_init_edge_runtime (the phase marker right after init_edge_runtime(...) returns) and never reaches post_send_durable (the marker right after send_durable_inline_text(...) returns). Identical localization to the pre-fix hang, but without any thread dying.

    ```
    PHASE python_start
    PHASE import_persist
    PHASE import_edge
    PHASE pre_engine
    PHASE post_engine
    PHASE post_register_key
    PHASE post_init_edge_runtime ← last phase emitted
    [ no panic in /tmp/edge-panic.log., no stderr, no stdout ]
    ```

    Plausibility note (no proof yet)

    The e8baf4d fix gave the Reticulum node its own multi_thread runtime (per the PR description: "ReticulumNode::start() now builds and owns a time-enabled multi_thread runtime"). Edge has its OWN runtime (handed in via persist's runtime_handle_capsule). So we now have two cohabiting runtimes in the process: persist+edge's runtime, and Reticulum's runtime.

    If anything in edge's send_durable_inline_text path awaits a wakeup that depends on a Reticulum-runtime-side task (e.g. through Arc<dyn Transport> channels, the event_bus, or metrics) — the wakeup might be queued on the wrong runtime's notify, and the awaiter blocks forever on a wakeup that's coming from a runtime it isn't watching.

    This is consistent with the 20% rate (race: did the await register on the right side of the runtime boundary?) and the no-panic signature (nothing's panicking — it's just blocked on a Notify whose owner is on the other side).

    gdb dump pending

    The harness's --gdb-on-hang attaches rust-gdb -batch -ex 't a a bt' to the hung subprocess. Failed on the first try because kernel.yama.ptrace_scope=1 blocks non-sudo attach even from direct parent (harness-side issue; needs a prctl(PR_SET_PTRACER_ANY) in the scenario preamble). I'll patch that and post the thread dump in a follow-up.

    For Edge#58 closure

    If you can confirm the two-runtime hypothesis (or point at a different residual cause), I'll cut v1.1.8 against this pin. The harness data is reproducible — happy to ship the panic-debug wheel artifact if useful for your-side gdb attach.

    Current Cargo.toml pin in edge 1.1.8-WIP:
    ```toml
    reticulum-core = { git = "...", rev = "e8baf4d24cc377314a8c4acf149224e068eb9d68", ... }
    reticulum-std = { git = "...", rev = "e8baf4d24cc377314a8c4acf149224e068eb9d68", ... }
    ```

    Diagnostics live in tools/race_repro.py; reproducible via:

    ```bash
    maturin build --profile panic-debug --features "pyo3 extension-module transport-http debug-tools" --skip-auditwheel --strip false --include-debuginfo
    pip install target/wheels/ciris_edge-*-linux_x86_64.whl ciris-persist==3.12.1 ciris-verify==4.8.0
    python3 tools/race_repro.py --scenario tools/scenarios/durable_send_postgres.py --rounds 30 --timeout 4 --panic-log /tmp/edge-panic.log
    ```

    (Note: scenario doesn't actually touch postgres in the failing path — the hang is in send_durable's outbound enqueue, which goes to persist's queue regardless of backend. Renamed for historical reasons.)

  4. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    Analysis + a runtime fix incoming (CIRISAI/Leviculum PR #8)

    Great diagnosis — 0 panics across every subprocess confirms both timer panic sites (spawn_traffic_counter + the event-loop sleep_until) are dead. Thank you for the phase-marker localization and the reproducible harness.

    One correction, then the real mechanism

    The "wakeup queued on the wrong runtime's notify" framing isn't quite how tokio works: a Notify/channel waker is bound to the task (and its runtime), not to the runtime that calls notify_one() — so a Leviculum-rt task waking an edge-rt awaiter does schedule it correctly across the boundary. Cross-runtime notify is fine.

    What the e8baf4d fix actually changed is thread count and parallelism. It gave the node a num_cpus-worker multi_thread runtime. In your process that means three runtimes (edge+persist's, plus the node's num_cpus workers) → ~2× core oversubscription, and real parallelism between the node's event loop and its public API where your single-host-runtime model previously had cooperative scheduling. That combination is exactly what turns a latent ordering race into an intermittent (~20%, no-panic) deadlock — and it's consistent with "blocked, nothing died."

    The change (PR #8)

    The node now runs its owned runtime on a single worker thread (worker_threads(1)). It keeps the time-enabled runtime (so the panic fix stands), but removes the added parallelism and drops the node's thread footprint from num_cpus to 1 — eliminating the oversubscription against persist's queue. The node's work is async-I/O bound (network + light per-packet crypto), so one cooperative worker is sufficient; interop 258/258 still passes with it.

    I'll post the merged main SHA here the moment PR #8's CI is green and it's merged — please re-run your 30× harness against it.

    Honest framing: this is a strongly-reasoned mitigation, not a proven fix, because I can't reproduce your edge+persist cohabitation locally. If 30× still shows residual hangs, the t a a bt dump will pin the exact await, and I'll chase that specific one.

    Your gdb ptrace blocker

    kernel.yama.ptrace_scope=1 blocks attach even from the parent unless the child opts in. In the scenario preamble (before the hang), have the child allow it:

    import ctypes
    libc = ctypes.CDLL("libc.so.6", use_errno=True)
    PR_SET_PTRACER = 0x59616d61
    PR_SET_PTRACER_ANY = -1
    libc.prctl(PR_SET_PTRACER, ctypes.c_int(PR_SET_PTRACER_ANY), 0, 0, 0)

    (Or system-wide for the run: sudo sysctl -w kernel.yama.ptrace_scope=0.) Then rust-gdb -p <pid> -batch -ex 't a a bt' attaches. The thread dump showing which Notify/channel the hung task is parked on would let me confirm or refute the parallelism theory definitively.

  5. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    PR #8 merged — re-test against this pin

    Bump the leviculum pin e8baf4d → 4c1b68f72ee3655035cc57667ae167ee4dbc951b (CIRISAI/Leviculum PR #8 on main).

    This is the single-worker node-runtime change: the node keeps its own time-enabled runtime (panic fix intact) but now runs it on one worker thread instead of a num_cpus pool — removing the thread oversubscription and the event-loop↔API parallelism that the e8baf4d fix introduced into your cohabitation. Full GitHub Actions matrix green on the merge commit; interop 258/258.

    Please re-run the 30× harness against 4c1b68f. Two outcomes:

    • 0% hang → the parallelism/oversubscription theory holds; cut v1.1.8 against this pin.
    • Still hanging → please grab the rust-gdb -p <pid> -batch -ex 't a a bt' dump (with the PR_SET_PTRACER_ANY preamble from the previous comment). The thread parked in send_durable's await + which Notify/channel it's on will pin the exact site, and I'll fix that specific one rather than guessing again.

    (Also in this pin, unrelated to the deadlock: reticulum-core now builds for Cortex-M0/thumbv6m — Leviculum #6.)

  6. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    gdb dump captured against 4c1b68f — the spawned future is never polled

    rust-gdb -batch -ex 't a a bt 50' against a hung subprocess (panic-debug wheel with full DWARF) gave us full symbol resolution. The shape is unusual: it's not a wait-on-Notify deadlock — the future was queued and no worker picked it up.

    Thread 1 (Python main) — parked in my run_async's sync_channel.recv

    ```
    #0 syscall ()
    #1 std::sys::pal::unix::futex::futex_wait
    #2 std::sys::sync::thread_parking::futex::Parker::park_timeout
    #3 std::thread::Thread::park_timeout
    #4 std::sync::mpmc::context::Context::wait_until
    ... [mpmc::Channel::recv internals] ...
    #13 std::sync::mpsc::Receiver::recv_timeout
    #14 ciris_edge::ffi::pyo3::run_async at src/ffi/pyo3.rs:1282
    #15 ciris_edge::ffi::pyo3::send_durable_inline_text::closure at src/ffi/pyo3.rs:411
    #16 pyo3::marker::Python::detach
    #17 PyEdge::send_durable_inline_text at src/ffi/pyo3.rs:410
    ```

    run_async in v1.1.7+ is runtime.spawn(fut); rx.recv_timeout(...). So Thread 1 is waiting on the spawned future to call tx.send(result). The future never does.

    Every other thread is idle

    37 threads total in the process:

    No thread anywhere is mid-poll of an application future. Searched the dump for any frame in ciris_edge::edge::, ciris_persist::store::, sqlx::, send_durable, enqueue_outbound, sign_envelope, build_signed_envelope — zero hits. The spawned future never started polling.

    Failure shape — spawn accepted, wake signal lost (or runtime mismatch)

    runtime.spawn(async move { let _ = tx.send(fut.await); }) accepted the task into the queue, but none of the 32 workers in that runtime woke up to poll it. Three plausible mechanisms:

    1. Wrong runtime: self.runtime (the RuntimeHandle edge captured at init_edge_runtime time via persist's runtime_handle_capsule) points at a runtime whose workers are NOT the 34 we see — i.e., a separate, unparked-into-non-existence runtime. Maybe the new owned-runtime in ReticulumNode::start() is being held twice, or there's an extra runtime construction we're missing.

    2. Cross-tokio-crate-version aliasing: edge's static cargo persist 3.12.1 and the python-installed persist 3.12.1 wheel could be pulling different patch versions of tokio. If two distinct tokio crates are linked into the process (e.g., from different transitive paths), spawn on one and poll on the other won't wake.

    3. Worker thread-pool starvation: the spawn queue was woken but all workers were past their park-check window. Less likely given the steady-state idle.

    Suggestion

    A rust-gdb -p <pid> -batch -ex 'print *(self as *const RuntimeHandle)' against the run_async frame would tell us which runtime handle is being spawned onto. I can rebuild + capture if you have a specific expression to evaluate; the panic-debug wheel has full DWARF so print on Rust values works.

    Cargo.toml current pins:
    ```toml
    ciris-persist = { tag = "v3.12.1", features = ["sqlite"] }
    reticulum-core = { rev = "4c1b68f72ee3655035cc57667ae167ee4dbc951b" }
    reticulum-std = { rev = "4c1b68f72ee3655035cc57667ae167ee4dbc951b" }
    ```

    Rate against 4c1b68f: 8/30 hangs (27%). Down from 100% (d3238e4) → 45% (fea04c1) → 27% (4c1b68f). Each fix takes another bite.

    Full gdb dump (74k chars, debug symbols throughout, all 37 threads): happy to paste inline or attach as a gist if useful.

  7. emooreatx commented on Jun 4, 2026

    @emooreatx
    ContributorAuthor

    Diagnosis: two tokios in the process — the capsule'd Handle crosses a tokio-instance boundary

    The dump is conclusive and it points away from Leviculum: the spawned future is never polled (zero frames in ciris_edge::/reticulum/sqlx/send_durable), all 34 workers idle, and Leviculum's own threads are present and correctly idle (reticulum-node in epoll_wait, reticulum-traff in clock_nanosleep). runtime.spawn() enqueued the task into a runtime whose workers are not the 34 that are parked. That's candidate #2, and your pins show exactly how it happens.

    The mechanism (candidate #2, made concrete)

    You link persist twice in one process:

    • statically into ciris_edge's cdylib: ciris-persist = { tag = "v3.12.1", features = ["sqlite"] }
    • as a separate wheel: pip install ciris-persist==3.12.1 → its own .so

    Two .sos ⇒ two tokio crates ⇒ two independent sets of runtime thread-locals, worker pools, and Handle vtables. run_async captures the runtime via persist's runtime_handle_capsule. If the capsule carries a Handle created by one persist's tokio and run_async spawns through the other persist/edge's tokio, the task lands in a runtime view whose workers nobody is parking into → never polled → recv_timeout waits forever. The ~20–27% rate is the race over which tokio "wins" Handle::current() / the capsule round-trip per process start.

    This is a tokio-runtime aliasing bug across the static-vs-wheel persist boundary, not a logic bug in any single crate.

    Confirm it (fast)

    1. cargo tree -i tokio --target x86_64-unknown-linux-gnu in the edge wheel build — if more than one tokio resolves (or persist appears both as a path/git dep and is also wheel-installed), that's it.
    2. In the process: grep -c 'tokio.*Runtime::new\|tokio.*worker' is hand-wavy — better, gdb -p <pid> -batch -ex 'info functions tokio.*runtime.*spawn' will show two distinct tokio::runtime symbol sets if two tokios are linked.
    3. gdb confirm the handle: at run_async (frame 14), print &self.runtime (or whatever field holds the Handle) and print self.runtime — then compare the inner Arc pointer to the runtime the 34 workers belong to (pick a worker thread, print its scheduler context). Different Arc inner ptr ⇒ wrong runtime confirmed.

    The fix (edge/persist side)

    One tokio per process. Pick one:

    • Don't static-link persist in edge and wheel-install it — use a single source so cargo unifies to one tokio; or
    • Don't pass a tokio::Handle across the .so boundary at all — let each .so own its runtime and bridge via a plain channel / pyo3-async-runtimes; or
    • Make run_async spawn onto the same runtime that owns the 34 workers (capture Handle::current() inside that runtime, not a capsule from the other persist).

    Leviculum side

    Nothing to fix here for this hang — single tokio 1.49, no handle passing, runtime healthy in the dump. My three changes addressed the panic sites (100→45%) and removed thread oversubscription (45→27%); the residual is this cross-.so tokio aliasing.

    One thing I can offer to simplify your runtime topology: a builder opt-out so ReticulumNode uses the ambient runtime instead of creating its own — viable once your host runtime is built with enable_time() (it currently isn't, which is why the owned runtime exists). That removes one runtime from the process. Say the word and I'll add ReticulumNodeBuilder::use_ambient_runtime().

  8. emooreatx commented on Jun 5, 2026

    @emooreatx
    ContributorAuthor

    Closed end-to-end by the executor_capsule consumption in edge v1.1.10 (depends on CIRISPersist#157, shipped in persist v3.13.0) + the sqlite inline-sync rewrite in CIRISPersist#158 (shipped in v3.14.0). Race rate trajectory per #60:

    100% (baseline)
     45% (leviculum PR #3)
     27% (leviculum PR #8)
      0% (executor_capsule consumption)
    

    tools/race_repro.py × 100 rounds at edge 1.1.11: 0 hangs / 0 panics on both postgres and sqlite. p50=46ms postgres / 83ms sqlite.

    Agent-side: CIRISAgent release/2.9.5 runs against the canonical triple (edge 1.1.11 + persist 3.14.3 + verify 4.8.0) per CIRISConformance/matrices/current.yaml. Full audit + setup + verify-adapter + runtime test sweep 563/563 green on the new triple.

  9. emooreatx commented on Jun 5, 2026

    @emooreatx
    ContributorAuthor

    Thanks for the deep diagnostic work — the cross-tokio aliasing identification + the gdb thread dump with 34 idle workers in futex_wait was the smoking gun that made the executor_capsule the obvious cure. Following the race-rate trajectory (100% → 45% → 27% → 0%) across the leviculum PRs + the executor_capsule consumption was the clearest possible story for the cohort bump.

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

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions