Underflow computing growth in stream data flow control credit

[fl0rek]

We've encountered a panic in quinn-proto-0.10.4. We're using quinn-0.10.2 with libp2p-0.53.1.

thread 'main' panicked at HOME/.cargo/registry/src/index.crates.io-6f17d22bba15001f/quinn-proto-0.10.4/src/connection/streams/recv.rs:108:20:
attempt to subtract with overflow
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/quinn-0.10.2/src/mutex.rs:138:42:
called `Result::unwrap()` on an `Err` value: PoisonError { .. }

Full Backtrace

    Finished dev [unoptimized + debuginfo] target(s) in 1.89s
     Running `target/debug/celestia node`
thread 'main' panicked at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/quinn-proto-0.10.4/src/connection/streams/recv.rs:108:20:
attempt to subtract with overflow
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/quinn-0.10.2/src/mutex.rs:138:42:
called `Result::unwrap()` on an `Err` value: PoisonError { .. }
stack backtrace:
   0:        0x102468cb4 - std::backtrace_rs::backtrace::libunwind::trace::hdc7d2d82dacc83e6
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/../../backtrace/src/backtrace/libunwind.rs:104:5
   1:        0x102468cb4 - std::backtrace_rs::backtrace::trace_unsynchronized::h11fcbf27db856d40
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x102468cb4 - std::sys_common::backtrace::_print_fmt::h117e5fb45bd92414
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/sys_common/backtrace.rs:68:5
   3:        0x102468cb4 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hd4e6df6dd376d525
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x102487b68 - core::fmt::rt::Argument::fmt::h4f724c1ed2e34985
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/fmt/rt.rs:142:9
   5:        0x102487b68 - core::fmt::write::h5a442bf928ef18fb
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/fmt/mod.rs:1120:17
   6:        0x102465e18 - std::io::Write::write_fmt::h01fe6f9cc882fac7
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/io/mod.rs:1846:15
   7:        0x102468ae8 - std::sys_common::backtrace::_print::h15d065176d59d5e1
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/sys_common/backtrace.rs:47:5
   8:        0x102468ae8 - std::sys_common::backtrace::print::h249c7fd853efd630
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/sys_common/backtrace.rs:34:9
   9:        0x10246a074 - std::panicking::default_hook::{{closure}}::h539bfee0454d0951
  10:        0x102469dbc - std::panicking::default_hook::he5a7d244fe90fc13
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:292:9
  11:        0x10246a4b0 - std::panicking::rust_panic_with_hook::h9b82bdc13ccb171b
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:781:13
  12:        0x10246a3a4 - std::panicking::begin_panic_handler::{{closure}}::hf609a05c98725eb7
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:659:13
  13:        0x102469138 - std::sys_common::backtrace::__rust_end_short_backtrace::hea0399d584786a2b
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/sys_common/backtrace.rs:171:18
  14:        0x10246a12c - rust_begin_unwind
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:647:5
  15:        0x1024e7478 - core::panicking::panic_fmt::hb4d79f470bcac176
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/panicking.rs:72:14
  16:        0x1024e78b8 - core::result::unwrap_failed::h66d43c215ff45232
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/result.rs:1649:5
  17:        0x1019e25f0 - core::result::Result<T,E>::unwrap::h7c99f05345093b69
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/result.rs:1073:23
  18:        0x1019e25f0 - quinn::mutex::non_tracking::Mutex<T>::lock::h561694b9d8685ade
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/quinn-0.10.2/src/mutex.rs:138:24
  19:        0x1019c5090 - <quinn::connection::ConnectionRef as core::ops::drop::Drop>::drop::hc4a7e038cd0e4a1c
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/quinn-0.10.2/src/connection.rs:792:26
  20:        0x1019ebe3c - core::ptr::drop_in_place<quinn::connection::ConnectionRef>::h078d0937bddd5271
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ptr/mod.rs:507:1
  21:        0x1019ebfcc - core::ptr::drop_in_place<quinn::connection::ConnectionDriver>::h8c199c7e65a2ffdb
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ptr/mod.rs:507:1
  22:        0x1019e9e20 - core::ptr::drop_in_place<alloc::boxed::Box<dyn core::future::future::Future+Output = ()+core::marker::Send>>::h981a232cae97d7a4
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ptr/mod.rs:507:1
  23:        0x1019ea118 - core::ptr::drop_in_place<core::pin::Pin<alloc::boxed::Box<dyn core::future::future::Future+Output = ()+core::marker::Send>>>::h4ed35e31bf719d81
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ptr/mod.rs:507:1
  24:        0x1019ea61c - core::ptr::drop_in_place<tokio::runtime::task::core::Stage<core::pin::Pin<alloc::boxed::Box<dyn core::future::future::Future+Output = ()+core::marker::Send>>>>::h7c87f6174096defa
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ptr/mod.rs:507:1
  25:        0x1019f2630 - tokio::runtime::task::core::Core<T,S>::set_stage::{{closure}}::hf1f1c753047e8705
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/core.rs:382:41
  26:        0x1019f223c - tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut::had358646553d09b9
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/loom/std/unsafe_cell.rs:16:9
  27:        0x1019f223c - tokio::runtime::task::core::Core<T,S>::set_stage::hbc51f07db78f1672
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/core.rs:382:9
  28:        0x1019f1588 - tokio::runtime::task::core::Core<T,S>::drop_future_or_output::h68367009df92d723
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/core.rs:347:13
  29:        0x1019c7310 - <tokio::runtime::task::harness::poll_future::{{closure}}::Guard<T,S> as core::ops::drop::Drop>::drop::hca90dad35f2db1bb
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/harness.rs:481:17
  30:        0x1019eab80 - core::ptr::drop_in_place<tokio::runtime::task::harness::poll_future::{{closure}}::Guard<core::pin::Pin<alloc::boxed::Box<dyn core::future::future::Future+Output = ()+core::marker::Send>>,alloc::sync::Arc<tokio::runtime::scheduler::current_thread::Handle>>>::h17eebe9864db8332
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ptr/mod.rs:507:1
  31:        0x1019c8d54 - tokio::runtime::task::harness::poll_future::{{closure}}::hdad0a83362d2bb01
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/harness.rs:488:5
  32:        0x1019e4308 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::he8f0cedda7243058
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/panic/unwind_safe.rs:272:9
  33:        0x1019cc714 - std::panicking::try::do_call::h4c002eecde49991f
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:554:40
  34:        0x1019ce0a4 - ___rust_try
  35:        0x1019cb8d4 - std::panicking::try::h476c6815dabdc207
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:518:19
  36:        0x1019cb67c - std::panic::catch_unwind::h8ee26191249a4854
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panic.rs:142:14
  37:        0x1019c82b0 - tokio::runtime::task::harness::poll_future::h3269162229e905a7
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/harness.rs:473:18
  38:        0x1019c8f84 - tokio::runtime::task::harness::Harness<T,S>::poll_inner::h49862e2a0312ee22
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/harness.rs:208:27
  39:        0x1019c9dc8 - tokio::runtime::task::harness::Harness<T,S>::poll::h6b2a4e76de7a7a30
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/harness.rs:153:15
  40:        0x1019d5cfc - tokio::runtime::task::raw::poll::h767bbff8caccf35a
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/raw.rs:276:5
  41:        0x1023c5ca0 - tokio::runtime::task::raw::RawTask::poll::ha0d737babbea93ea
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/raw.rs:200:18
  42:        0x1020e3fd8 - tokio::runtime::task::LocalNotified<S>::run::he64183064a74982b
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/task/mod.rs:408:9
  43:        0x100d0006c - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}::h4f54fd7046d30818
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:706:25
  44:        0x100cff5c4 - tokio::runtime::coop::with_budget::hd1df283faa20597e
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/coop.rs:107:5
  45:        0x100cff5c4 - tokio::runtime::coop::budget::hdbc87cf7abae73a3
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/coop.rs:73:5
  46:        0x100cff5c4 - tokio::runtime::scheduler::current_thread::Context::run_task::{{closure}}::h4b04702e2166dc0f
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:343:43
  47:        0x100cff2c8 - tokio::runtime::scheduler::current_thread::Context::enter::h5b01fcd5f4339216
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:410:19
  48:        0x100cff468 - tokio::runtime::scheduler::current_thread::Context::run_task::h5b8e74259132849e
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:343:23
  49:        0x100cfffe0 - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::ha0c20fcef49684df
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:705:34
  50:        0x100cff970 - tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}::h9701170602fd9494
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:743:68
  51:        0x100c418ac - tokio::runtime::context::scoped::Scoped<T>::set::h66e055fe3d61cb8f
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/context/scoped.rs:40:9
  52:        0x10106dd48 - tokio::runtime::context::set_scheduler::{{closure}}::h363ffc220f660c3b
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/context.rs:176:26
  53:        0x100b73b78 - std::thread::local::LocalKey<T>::try_with::hb1ef866639d0dc22
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/thread/local.rs:286:16
  54:        0x100b6eab8 - std::thread::local::LocalKey<T>::with::ha8b2f4275ead3c72
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/thread/local.rs:262:9
  55:        0x10106dd08 - tokio::runtime::context::set_scheduler::h92feef536709b8dd
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/context.rs:176:9
  56:        0x100cff798 - tokio::runtime::scheduler::current_thread::CoreGuard::enter::h6d792852750080b8
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:743:27
  57:        0x100cff9a0 - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::hc5b2a62620625faa
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:652:19
  58:        0x100cf67d4 - tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}::h7b3eb93862647b6c
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:175:28
  59:        0x100c0e464 - tokio::runtime::context::runtime::enter_runtime::hb5570fc4746770ed
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/context/runtime.rs:65:16
  60:        0x100cf66f4 - tokio::runtime::scheduler::current_thread::CurrentThread::block_on::h3910abd9a4b6dd10
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/scheduler/current_thread/mod.rs:167:9
  61:        0x100c98d94 - tokio::runtime::runtime::Runtime::block_on::h476c80be26a5a58d
                               at /Users/mikolaj.florkiewicz/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.33.0/src/runtime/runtime.rs:348:47
  62:        0x100f3a2a4 - celestia::main::h5794a3ede700ae30
                               at /Users/mikolaj.florkiewicz/dev/lumina-header_sync_repro/celestia/src/main.rs:4:5
  63:        0x1010e50b4 - core::ops::function::FnOnce::call_once::hc4b6dc09ac572737
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ops/function.rs:250:5
  64:        0x1010720a4 - std::sys_common::backtrace::__rust_begin_short_backtrace::h93a345640907338a
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/sys_common/backtrace.rs:155:18
  65:        0x100d7509c - std::rt::lang_start::{{closure}}::h6c6905c3eeb8cbbc
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/rt.rs:166:18
  66:        0x102460254 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hc7fa490c25ff5c7e
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ops/function.rs:284:13
  67:        0x102460254 - std::panicking::try::do_call::h357310772e5ed201
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:554:40
  68:        0x102460254 - std::panicking::try::h7be07bf7667211c0
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:518:19
  69:        0x102460254 - std::panic::catch_unwind::h3ab45e592d6c9793
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panic.rs:142:14
  70:        0x102460254 - std::rt::lang_start_internal::{{closure}}::h522f1a8ded7e5ad3
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/rt.rs:148:48
  71:        0x102460254 - std::panicking::try::do_call::h403386826d59f38d
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:554:40
  72:        0x102460254 - std::panicking::try::h5e255b7a06373cce
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:518:19
  73:        0x102460254 - std::panic::catch_unwind::h462489ab339aac24
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panic.rs:142:14
  74:        0x102460254 - std::rt::lang_start_internal::h7f00bef3cf1b3caa
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/rt.rs:148:20
  75:        0x100d75068 - std::rt::lang_start::h7323fd224ebf8c76
                               at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/rt.rs:165:17
  76:        0x100f3a340 - _main
thread 'main' panicked at library/core/src/panicking.rs:163:5:
panic in a destructor during cleanup
thread caused non-unwinding panic. aborting.
[1]    96704 abort      cargo run node

I don't think I can provide much details on reproduction. Code was running on the network for ~5h while I was trying to reproduce another bug when I saw this panic.

let diff = max_stream_data - self.sent_max_stream_data; seems to be the offending substraction, but I don't know quinn well enought to tell whether that's a cause (to be fixed with e.g. saturating substraction) or a symptom of a deeper issue.

[Ralith]

Thanks for the report!

Full Backtrace

This is the backtrace for the poisoned mutex panic, not the original underflow panic that caused it. You'll want to look just above in the logs.

let diff = max_stream_data - self.sent_max_stream_data; seems to be the offending substraction

That's surprising. self.sent_max_stream_data is only ever populated with a max_stream_data returned from an immediately preceding call to fn max_stream_data. That value is a sum of self.assembler.bytes_read(), which grows monotonically, and stream_receive_window, which never changes within the lifetime of a connection. An accounting error in bytes_read isn't impossible, but I'm not seeing one.

[fl0rek]

Hey @Ralith, thanks for the response!

At the time I wasn't capturing quinn logs to save space and all I have there is occasional
WARN quinn_proto::connection: discarding possible duplicate packet.
I am trying to reproduce the panic again with more logging enabled, but so far it seems like a very rare occurance and I did not manage to yet.

[Ralith]

Panic backtraces aren't Quinn logs; they're produced by the panic handler, which by default looks for RUST_BACKTRACE=1 in your environment per your paste. Be sure to set that.

Might be worth investigating hooking a smart fuzzer up to the stream bookkeeping directly, if you've got no idea at all what triggered this.

[Rexagon]

I caught an 'attempt to substract with overflow' panic here

quinn/quinn-proto/src/connection/streams/recv.rs

Line 109 in db2df61

let diff = max_stream_data - self.sent_max_stream_data;

while doing some ridiculous tests with 30 local endpoints communicating with each other in debug build.

Unfortunately there are too many logs to attach, but apparently a lot of packets are lost and something goes beyond the window.

[Ralith]

Did you get a backtrace?

[Ralith]

Spent some hours staring at this and I think I found the issue: #1869.

This could only arise with specific patterns of packet loss on a stream that's already been stopped (e.g. dropped) by the application, which explains the rarity.