tokio current-thread runtime deadlock on arm 2025.09.18

[frostyplanet]

A continue issue after #35
tokio is patched with frostyplanet/tokio@6eb7cfa

https://github.com/frostyplanet/crossfire-rs/actions/runs/17809618502
commit 633b950
tokio current_thread
test_pressure_bounded_mixed_async_blocking_conversion::case_1

[2025-09-17 21:26:12.205654][DEBUG][ThreadId(6)] rx: recv
[2025-09-17 21:26:12.205655][DEBUG][ThreadId(2)] drop tx 1
[2025-09-17 21:26:12.205658][DEBUG][ThreadId(5)] tx: send Some(waker(8198 state=5))
[2025-09-17 21:26:12.205661][DEBUG][ThreadId(5)] tx: reg waker(8228 state=0)
[2025-09-17 21:26:12.205662][DEBUG][ThreadId(5)] tx: sender_reg_and_try Some(waker(8228 state=1)) 1
[2025-09-17 21:26:12.205672][DEBUG][ThreadId(5)] tx: send Some(waker(8228 state=3))
[2025-09-17 21:26:12.205675][DEBUG][ThreadId(2)] wake tx waker(8228 state=3) Waked
[2025-09-17 21:26:12.205676][DEBUG][ThreadId(2)] rx: recv Some(waker(7874 state=3))
[2025-09-17 21:26:12.205677][DEBUG][ThreadId(2)] rx: recv
[2025-09-17 21:26:12.205677][DEBUG][ThreadId(2)] rx: reg waker(7875 state=0)
[2025-09-17 21:26:12.205678][DEBUG][ThreadId(2)] rx: commit_waiting Some(waker(7875 state=1)) 1
[2025-09-17 21:26:12.205697][DEBUG][ThreadId(6)] rx: reg waker(7876 state=0)
[2025-09-17 21:26:12.205698][DEBUG][ThreadId(6)] rx: waker(7876 state=1) commit_waiting 1
[2025-09-17 21:26:12.205701][DEBUG][ThreadId(5)] wake rx waker(7875 state=3) Waked
[2025-09-17 21:26:12.205704][DEBUG][ThreadId(5)] tx: reg waker(8229 state=0)
[2025-09-17 21:26:12.205706][DEBUG][ThreadId(5)] tx: sender_reg_and_try Some(waker(8229 state=1)) 1

It's not obvious to tell async from threaded context, should change the log format add file and line
information extract from the current log format:

rx1 (async): ThreadId(2) is tokio runtime,

trace_log!("rx: commit_waiting {:?} {}", o_waker, state);

[2025-09-17 21:26:12.205677][DEBUG][ThreadId(2)] rx: recv
[2025-09-17 21:26:12.205677][DEBUG][ThreadId(2)] rx: reg waker(7875 state=0)
[2025-09-17 21:26:12.205678][DEBUG][ThreadId(2)] rx: commit_waiting Some(waker(7875 state=1)) 1

rx2 (thread): ThreadId(6)

trace_log!("rx: {:?} commit_waiting {}", waker, state);
[2025-09-17 21:26:12.205697][DEBUG][ThreadId(6)] rx: reg waker(7876 state=0)
[2025-09-17 21:26:12.205698][DEBUG][ThreadId(6)] rx: waker(7876 state=1) commit_waiting 1

only 1 tx left
tx: blocking context, ThreadId(5)

trace_log!("tx: sender_reg_and_try {:?} {}", o_waker, state);

[2025-09-17 21:26:12.205704][DEBUG][ThreadId(5)] tx: reg waker(8229 state=0)
[2025-09-17 21:26:12.205706][DEBUG][ThreadId(5)] tx: sender_reg_and_try Some(waker(8229 state=1)) 1
[2025-09-17 21:26:12.205701][DEBUG][ThreadId(5)] wake rx waker(7875 state=3) Waked

rx async waker(7875) is dead

[frostyplanet]

A strange behavior with shadow variable, created an issue rust-lang/rust#146719.

run 25: https://github.com/frostyplanet/crossfire-rs/actions/runs/17823475038
tokio multi-thread

previous commit 62fda2b

test_pressure_bounded_async_multi_1

There should be waker 3775, but the log has strange duplicated log of "waker 3776"

[2025-09-18 09:00:00.870625][DEBUG][ThreadId(5)][waker_registry.rs:50] tx: reg waker(3775)
[2025-09-18 09:00:00.870627][DEBUG][ThreadId(5)][async_tx.rs:274] tx: sender_reg_and_try Some(waker(3775)) state=1
[2025-09-18 09:00:00.870642][DEBUG][ThreadId(5)][waker_registry.rs:50] tx: reg waker(3776)
[2025-09-18 09:00:00.870645][DEBUG][ThreadId(2)][waker_registry.rs:392] wake tx waker(3776) Waked
[2025-09-18 09:00:00.870712][DEBUG][ThreadId(2)][async_rx.rs:235] rx: recv
[2025-09-18 09:00:00.870723][DEBUG][ThreadId(2)][waker_registry.rs:385] wake tx waker(3776) Waked

attempt to replace the shadow variable with commit 70ceb3f

It look like

    [2025-09-18 09:00:00.870645][DEBUG][ThreadId(2)][waker_registry.rs:392] wake tx waker(3776) Waked

and

    [2025-09-18 09:00:00.870723][DEBUG][ThreadId(2)][waker_registry.rs:385] wake tx waker(3776) Waked

is different call of poll(), but I have no idea how it get duplicated 3776.

attempt fix with de2189d

[frostyplanet]

run 29
https://github.com/frostyplanet/crossfire-rs/actions/runs/17825537694
test_pressure_bounded_async_1_1
tokio multi-thread
I have 667adaa
It looks like a spurious wake, and wake_by_ref() get notified state.
I was expecting wake_by_ref would wake again, but it's not. Should get to know more about state transfer.

[2025-09-18 10:20:45.388776][DEBUG][ThreadId(6)][async_tx.rs:274] txSome(Id(4)): sender_reg_and_try Some(waker(15)) state=1
[2025-09-18 10:20:45.388778][DEBUG][ThreadId(6)][async_tx.rs:214] txSome(Id(4)): will_wake waker(15)
[2025-09-18 10:20:45.388778][DEBUG][ThreadId(2)][state.rs:259] waker.wake_by_ref already notified
[2025-09-18 10:20:45.388780][DEBUG][ThreadId(2)][waker_registry.rs:392] wake tx waker(15) Waked

[frostyplanet]

NOTE: how to find out which sender is hang

grep -E 'spawn|exit' crossfire_ring.log.34 | cut -d" " -f 3- | sort -n
grep -E 'spawn|exit' crossfire_ring.log.34 | cut -d" " -f 4- | sort -n

[frostyplanet]

tokio frostyplanet/tokio@d990b8c
tokio: currrent thread
test_pressure_bounded_mixed_async_blocking_conversion

[2025-09-19 04:34:45.512896][DEBUG][ThreadId(5)][blocking_tx.rs:184] tx: send Some(waker(4984))
[2025-09-19 04:34:45.512899][DEBUG][ThreadId(2)][harness.rs:198] task 2 transition_to_running Snapshot { is_running: true, is_complete: false, is_notified: false, is_cancelled: false, is_join_interested: true, is_join_waker_set: false, ref_count: 4 
} suc
[2025-09-19 04:34:45.512900][DEBUG][ThreadId(2)][async_rx.rs:230] rxSome(Id(2)): recv waker(792)
[2025-09-19 04:34:45.512901][DEBUG][ThreadId(2)][waker_registry.rs:209] rxSome(Id(2)): reg waker(794)
[2025-09-19 04:34:45.512902][DEBUG][ThreadId(2)][async_rx.rs:265] rxSome(Id(2)): commit_waiting waker(794) 1
[2025-09-19 04:34:45.512903][DEBUG][ThreadId(2)][harness.rs:219] task 2 transition_to_idle Ok
[2025-09-19 04:34:45.512908][DEBUG][ThreadId(6)][waker_registry.rs:209] rxNone: reg waker(795)
[2025-09-19 04:34:45.512909][DEBUG][ThreadId(6)][blocking_rx.rs:133] rx: waker(795) commit_waiting state=1
[2025-09-19 04:34:45.512911][DEBUG][ThreadId(5)][waker_registry.rs:392] wake rx waker(794) Waked
[2025-09-19 04:34:45.512913][DEBUG][ThreadId(5)][waker_registry.rs:52] txNone: reg waker(5159)
[2025-09-19 04:34:45.512914][DEBUG][ThreadId(5)][blocking_tx.rs:149] tx: sender_reg_and_try Some(waker(5159)) state=1

https://github.com/frostyplanet/crossfire-rs/actions/runs/17848230761/job/50751786420
I can see task2 transite to idle, and waker 794 is dead.
For thread 5, before 04:34:45.512896 and 2025-09-19 04:34:45.512911 there no covering wake_by_ref() debug log

[2025-09-19 04:34:45.512911][DEBUG][ThreadId(5)][waker_registry.rs:392] wake rx waker(794) Waked

So it should be in the Submit branch of transition_to_notified_by_ref()

[frostyplanet]

Added more log for tokio scheduler.

https://github.com/frostyplanet/crossfire-rs/actions/runs/17850277588/job/50757354826
tokio: currrent thread frostyplanet/tokio@6a96ec9
test_pressure_bounded_mixed_async_blocking_conversion

[2025-09-19 06:45:00.469416][DEBUG][ThreadId(2)][async_rx.rs:230] rxSome(Id(2)): recv waker(8227)
[2025-09-19 06:45:00.469418][DEBUG][ThreadId(2)][waker_registry.rs:209] rxSome(Id(2)): reg waker(8228)
[2025-09-19 06:45:00.469419][DEBUG][ThreadId(2)][async_rx.rs:265] rxSome(Id(2)): commit_waiting waker(8228) 1
[2025-09-19 06:45:00.469419][DEBUG][ThreadId(2)][harness.rs:219] task 2 transition_to_idle Ok
[2025-09-19 06:45:00.469448][DEBUG][ThreadId(6)][waker_registry.rs:209] rxNone: reg waker(8229)
[2025-09-19 06:45:00.469450][DEBUG][ThreadId(6)][blocking_rx.rs:133] rx: waker(8229) commit_waiting state=1
[2025-09-19 06:45:00.469454][DEBUG][ThreadId(5)][state.rs:271] waker.wake_by_ref (idle)
[2025-09-19 06:45:00.469456][DEBUG][ThreadId(5)][mod.rs:661] task Id(2) outside push
[2025-09-19 06:45:00.469457][DEBUG][ThreadId(5)][waker_registry.rs:392] wake rx waker(8228) Waked
[2025-09-19 06:45:00.469460][DEBUG][ThreadId(5)][waker_registry.rs:52] txNone: reg waker(9253)
[2025-09-19 06:45:00.469460][DEBUG][ThreadId(5)][blocking_tx.rs:149] tx: sender_reg_and_try Some(waker(9253)) state=1

waker 8228 is dead, task 2 is not scheduled.
Next we should debug in Inject or park.

[frostyplanet]

passed, https://github.com/frostyplanet/crossfire-rs/actions/runs/17851772944
with frostyplanet/tokio@a1fec5f
test code: ae7a430

Created issue for tokio :
tokio-rs/tokio#7632

[frostyplanet]

run 55
https://github.com/frostyplanet/crossfire-rs/actions/runs/17876513415/job/50838599306
tokio frostyplanet/tokio@b9bfb74
dev 910b76e

tests::test_blocking_async::test_pressure_tx_multi_blocking_multi_rx_async::case_02

---

task 18 and task 20 hang

 [2025-09-20 07:04:45.511949][DEBUG][ThreadId(2)][test_blocking_async.rs:309] rxSome(Id(18)) 17 spawn
[2025-09-20 07:04:45.511961][DEBUG][ThreadId(2)][test_blocking_async.rs:309] rxSome(Id(20)) 19 spawn

task 18

[2025-09-20 07:04:45.788487][DEBUG][ThreadId(2)][waker_registry.rs:209] rxSome(Id(18)): reg waker(112594)
[2025-09-20 07:04:45.788487][DEBUG][ThreadId(14)][waker_registry.rs:392] wake rx waker(112593) Next
[2025-09-20 07:04:45.788488][DEBUG][ThreadId(2)][async_rx.rs:265] rxSome(Id(18)): commit_waiting waker(112594) 1
[2025-09-20 07:04:45.788489][DEBUG][ThreadId(2)][async_rx.rs:220] rxSome(Id(18)): will_wake waker(112594)
[2025-09-20 07:04:45.788489][DEBUG][ThreadId(14)][state.rs:258] waker.wake_by_ref (notified)
[2025-09-20 07:04:45.788491][DEBUG][ThreadId(14)][waker_registry.rs:399] wake rx waker(112594) Waked

task 20

[2025-09-20 07:04:45.780586][DEBUG][ThreadId(2)][waker_registry.rs:209] rxSome(Id(20)): reg waker(111275)
[2025-09-20 07:04:45.780585][DEBUG][ThreadId(99)][waker_registry.rs:392] wake rx waker(111271) Next
[2025-09-20 07:04:45.780587][DEBUG][ThreadId(2)][async_rx.rs:265] rxSome(Id(20)): commit_waiting waker(111275) 1
[2025-09-20 07:04:45.780588][DEBUG][ThreadId(2)][async_rx.rs:220] rxSome(Id(20)): will_wake waker(111275)
[2025-09-20 07:04:45.780589][DEBUG][ThreadId(2)][waker_registry.rs:209] rxSome(Id(3)): reg waker(111276)
[2025-09-20 07:04:45.780589][DEBUG][ThreadId(99)][state.rs:258] waker.wake_by_ref (notified)
[2025-09-20 07:04:45.780590][DEBUG][ThreadId(2)][async_rx.rs:260] rxSome(Id(3)): recv waker(111276)
[2025-09-20 07:04:45.780591][DEBUG][ThreadId(2)][waker_registry.rs:209] rxSome(Id(3)): reg waker(111277)
[2025-09-20 07:04:45.780592][DEBUG][ThreadId(2)][async_rx.rs:265] rxSome(Id(3)): commit_waiting waker(111277) 1
[2025-09-20 07:04:45.780591][DEBUG][ThreadId(99)][waker_registry.rs:399] wake rx waker(111275) Waked

both task when into the "waker.wake_by_ref (notified)", so I would just apply the last two patches to see if it's stable.