Panic reported on disconnect

[andrewdavidmackenzie]

Describe the bug
When I do a disconnect from a device (see code further down).

I get a panic at the write() in this code in ble_handler.rs:246:47

    pub async fn write_to_radio(&self, buffer: &[u8]) -> Result<(), Error> {
        self.radio
            // TODO: remove the skipping of the first 4 bytes
            .write(&self.toradio_char, &buffer[4..], WriteType::WithResponse)
            .await
            .map_err(|e: btleplug::Error| {
                Error::InternalStreamError(InternalStreamError::StreamWriteError {
                    source: Box::new(e),
                })
            })
    }

with this backtrace:

thread 'tokio-runtime-worker' panicked at /Users/amackenz/.cargo/git/checkouts/rust-a1709e8f8e020629/bd5fe19/src/connections/ble_handler.rs:246:47:
range start index 4 out of range for slice of length 0
stack backtrace:
   0: __rustc::rust_begin_unwind
             at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:697:5
   1: core::panicking::panic_fmt
             at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/panicking.rs:75:14
   2: core::slice::index::slice_start_index_len_fail::do_panic::runtime
             at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/panic.rs:218:21
   3: core::slice::index::slice_start_index_len_fail::do_panic
             at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/intrinsics/mod.rs:2367:9
   4: core::slice::index::slice_start_index_len_fail
             at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/panic.rs:223:9
   5: <core::ops::range::RangeFrom<usize> as core::slice::index::SliceIndex<[T]>>::index
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/slice/index.rs:570:13
   6: core::slice::index::<impl core::ops::index::Index<I> for [T]>::index
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/slice/index.rs:18:15
   7: meshtastic::connections::ble_handler::BleHandler::write_to_radio::{{closure}}
             at /Users/amackenz/.cargo/git/checkouts/rust-a1709e8f8e020629/bd5fe19/src/connections/ble_handler.rs:246:47
   8: meshtastic::utils_internal::build_ble_stream::{{closure}}::{{closure}}
             at /Users/amackenz/.cargo/git/checkouts/rust-a1709e8f8e020629/bd5fe19/src/utils_internal.rs:334:61
   9: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/core.rs:365:24
  10: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/loom/std/unsafe_cell.rs:16:9
  11: tokio::runtime::task::core::Core<T,S>::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/core.rs:354:30
  12: tokio::runtime::task::harness::poll_future::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:535:30
  13: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/panic/unwind_safe.rs:272:9
  14: std::panicking::catch_unwind::do_call
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/panicking.rs:589:40
  15: ___rust_try
  16: std::panicking::catch_unwind
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/panicking.rs:552:19
  17: std::panic::catch_unwind
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/panic.rs:359:14
  18: tokio::runtime::task::harness::poll_future
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:523:18
  19: tokio::runtime::task::harness::Harness<T,S>::poll_inner
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:210:27
  20: tokio::runtime::task::harness::Harness<T,S>::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:155:20
  21: tokio::runtime::task::raw::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/raw.rs:325:13
  22: tokio::runtime::task::raw::RawTask::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/raw.rs:255:18
  23: tokio::runtime::task::LocalNotified<S>::run
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/mod.rs:509:13
  24: tokio::runtime::scheduler::multi_thread::worker::Context::run_task::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:600:18
  25: tokio::task::coop::with_budget
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/task/coop/mod.rs:167:5
  26: tokio::task::coop::budget
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/task/coop/mod.rs:133:5
  27: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:591:9
  28: tokio::runtime::scheduler::multi_thread::worker::Context::run
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:551:29
  29: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:504:24
  30: tokio::runtime::context::scoped::Scoped<T>::set
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/context/scoped.rs:40:9
  31: tokio::runtime::context::set_scheduler::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/context.rs:176:38
  32: std::thread::local::LocalKey<T>::try_with
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/thread/local.rs:315:12
  33: std::thread::local::LocalKey<T>::with
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/thread/local.rs:279:20
  34: tokio::runtime::context::set_scheduler
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/context.rs:176:17
  35: tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:499:9
  36: tokio::runtime::context::runtime::enter_runtime
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/context/runtime.rs:65:16
  37: tokio::runtime::scheduler::multi_thread::worker::run
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:491:5
  38: tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/scheduler/multi_thread/worker.rs:457:45
  39: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/blocking/task.rs:42:21
  40: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/core.rs:365:24
  41: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/loom/std/unsafe_cell.rs:16:9
  42: tokio::runtime::task::core::Core<T,S>::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/core.rs:354:30
  43: tokio::runtime::task::harness::poll_future::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:535:30
  44: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/panic/unwind_safe.rs:272:9
  45: std::panicking::catch_unwind::do_call
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/panicking.rs:589:40
  46: ___rust_try
  47: std::panicking::catch_unwind
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/panicking.rs:552:19
  48: std::panic::catch_unwind
             at /Users/amackenz/.rustup/toolchains/stable-aarch64-apple-darwin/lib/rustlib/src/rust/library/std/src/panic.rs:359:14
  49: tokio::runtime::task::harness::poll_future
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:523:18
  50: tokio::runtime::task::harness::Harness<T,S>::poll_inner
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:210:27
  51: tokio::runtime::task::harness::Harness<T,S>::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/harness.rs:155:20
  52: tokio::runtime::task::raw::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/raw.rs:325:13
  53: tokio::runtime::task::raw::RawTask::poll
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/raw.rs:255:18
  54: tokio::runtime::task::UnownedTask<S>::run
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/mod.rs:546:13
  55: tokio::runtime::blocking::pool::Task::run
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/blocking/pool.rs:161:19
  56: tokio::runtime::blocking::pool::Inner::run
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/blocking/pool.rs:516:22
  57: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}
             at /Users/amackenz/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/blocking/pool.rs:474:47

I see there is a TODO there, that might be related.

To Reproduce
This is the code I use to disconnect from a device, when a UI button to do so is clicked:

async fn do_disconnect(stream_api: ConnectedStreamApi) -> Result<(), anyhow::Error> {
    stream_api
        .disconnect()
        .await
        .context("Failed to disconnect")?;
    Ok(())
}

Expected behavior
Call to disconnect either works or returns an error.

[lukipuki]

I think the buffer is too small, see core::slice::index::slice_start_index_len_fail mentioned towards the beginning of the stack trace. Can you bump the buffer size in utils_internal.rs at line 297 and check if the problem persists?

[lukipuki]

OK, this is not related to buffer length, we're getting len == 0 at line 333:

rust/src/utils_internal.rs

Line 333 in bd5fe19

let len = from_server.map_err(duplex_write_error_fn)?;

len equal to zero probably means the device is disconnecting, we should handle the case gracefully. Interesting that it sometimes works, maybe it depends on the shutdown order of the async tasks, i.e. the tasks gets shutdown even before reaching line 333.

[andrewdavidmackenzie]

I see calls to write_to_radio (from line 334), AFTER disconnect has been called.
Maybe the tokio select is returning on that branch when the connection to the device is closed?

Skip the write_to_radio() if the len == 0 ??

[andrewdavidmackenzie]

That certainly avoids the panic, whether the correct thing to be happening or not depends on the semantics of tokio::io::duplex I guess.

I'll read up on it when I get a chance to see.

[andrewdavidmackenzie]

From https://docs.rs/tokio/latest/tokio/io/struct.DuplexStream.html

"Closing a DuplexStream
If one end of the DuplexStream channel is dropped, any pending reads on the other side will continue to read data until the buffer is drained, then they will signal EOF by returning 0 bytes. Any writes to the other side, including pending ones (that are waiting for free space in the buffer) will return Err(BrokenPipe) immediately."

Looks like 0 bytes as EOF is what is expected, and we should just handle it.

I'll send that 1-line PR for you to consider.