bluer

bluer copied to clipboard

Hi, I am currently testing the current master of bluer and starting with the "simple" echo example with the following setup:

Desktop-PC - Ubuntu 22.04) - gatt_echo_server:

• bluer (git rev-parse HEAD: e83517fb1704dfcd0ed45fbb796e002c4dad7fce)
• rustc (1.76.0)
• dbus (1.12.20-2ubuntu4.1)
• bluez (5.64-0ubuntu1.1)

vricosti@vricosti-Z490-VISION-D:~/Dev/bluer$ ./target/debug/examples/gatt_echo_server
Advertising on Bluetooth adapter hci0 with address 40:EC:99:0E:C4:7C
Serving GATT echo service on Bluetooth adapter hci0
Echo service ready. Press enter to quit.
Accepting notify request event with MTU 512

Raspberrypi4 8Gb - Debian GNU/Linux 11 (bullseye) - gatt_echo_client:

• bluer (git rev-parse HEAD: e83517fb1704dfcd0ed45fbb796e002c4dad7fce)
• rustc (1.76.0)
• dbus (1.12.28-0+deb11u1)
• bluez (5.55-3.1+rpt2+deb11u1)

pi@raspberrypi:~/Dev/bluer $ ./target/debug/examples/gatt_echo_client
Discovering on Bluetooth adapter hci0 with address DC:A6:32:B8:68:7E
Discovered device 40:EC:99:0E:C4:7C with service UUIDs {0000180a-0000-1000-8000-00805f9b34fb, 00001800-0000-1000-8000-00805f9b34fb, 00001801-0000-1000-8000-00805f9b34fb, 00000000-0000-0000-000f-eedc0de00002}
    Manufacturer data: None
    Device provides our service!
    Already connected
    Enumerating services...
    Service UUID: 00001801-0000-1000-8000-00805f9b34fb
    Service UUID: 0000180a-0000-1000-8000-00805f9b34fb
    Service UUID: 00000000-0000-0000-000f-eedc0de00002
    Found our service!
    Characteristic UUID: 00000000-0000-0000-000f-00dc0de00002
    Found our characteristic!
    Obtained write IO with MTU 512 bytes
    Obtained notification IO with MTU 517 bytes
    Test iteration 0 with data size 512
    Waiting for echo

and then nothing happens.

I have also tried to run server on rpi and client on pc and this time it's a bit better:

pi@raspberrypi:~/Dev/bluer $ ./target/debug/examples/gatt_echo_server
Advertising on Bluetooth adapter hci0 with address DC:A6:32:B8:68:7E
Serving GATT echo service on Bluetooth adapter hci0
Echo service ready. Press enter to quit.
Accepting notify request event with MTU 512
Accepting write request event with MTU 517
Echoing 512 bytes: [c0, 81, 95, 98] ... [5e, f9, f6, 76]
Echoing 20 bytes: [9c, ce, 5c, 45] ... [4d, ec, c9, e7]

Echoing 512 bytes: [eb, 4a, 96, 3d] ... [81, c3, ff, 75]
Echoing 512 bytes: [57, e2, f9, 96] ... [5a, 58, 3d, 6f]
Echoing 512 bytes: [88, e9, fb, 76] ... [e8, 3b, 97, d]
Read stream ended

vricosti@vricosti-Z490-VISION-D:~/Dev/bluer$ export RUST_BACKTRACE=full
vricosti@vricosti-Z490-VISION-D:~/Dev/bluer$ ./target/debug/examples/gatt_echo_client
Discovering on Bluetooth adapter hci0 with address 40:EC:99:0E:C4:7C

Discovered device DC:A6:32:B8:68:7E with service UUIDs {00000000-0000-0000-000f-eedc0de00002}
    Manufacturer data: None
    Device provides our service!
    Connecting...
    Connected
    Enumerating services...
    Service UUID: 0000180a-0000-1000-8000-00805f9b34fb
    Service UUID: 00001801-0000-1000-8000-00805f9b34fb
    Service UUID: 00000000-0000-0000-000f-eedc0de00002
    Found our service!
    Characteristic UUID: 00000000-0000-0000-000f-00dc0de00002
    Found our characteristic!
    Obtained write IO with MTU 512 bytes
    Obtained notification IO with MTU 517 bytes
    Test iteration 0 with data size 512
    Waiting for echo
    Data matches
    Test iteration 1 with data size 20
    Waiting for echo
    Data matches
    Test iteration 2 with data size 10405
    Waiting for echo
thread 'main' panicked at bluer/examples/gatt_echo_client.rs:112:28:
read failed: Custom { kind: UnexpectedEof, error: "early eof" }
stack backtrace:
   0:     0x564593069606 - std::backtrace_rs::backtrace::libunwind::trace::hbee8a7973eeb6c93
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/../../backtrace/src/backtrace/libunwind.rs:104:5
   1:     0x564593069606 - std::backtrace_rs::backtrace::trace_unsynchronized::hc8ac75eea3aa6899
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x564593069606 - std::sys_common::backtrace::_print_fmt::hc7f3e3b5298b1083
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:68:5
   3:     0x564593069606 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hbb235daedd7c6190
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x56459308e190 - core::fmt::rt::Argument::fmt::h76c38a80d925a410
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/fmt/rt.rs:142:9
   5:     0x56459308e190 - core::fmt::write::h3ed6aeaa977c8e45
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/fmt/mod.rs:1120:17
   6:     0x56459306730f - std::io::Write::write_fmt::h78b18af5775fedb5
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/io/mod.rs:1810:15
   7:     0x5645930693e4 - std::sys_common::backtrace::_print::h5d645a07e0fcfdbb
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x5645930693e4 - std::sys_common::backtrace::print::h85035a511aafe7a8
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x56459306aab7 - std::panicking::default_hook::{{closure}}::hcce8cea212785a25
  10:     0x56459306a819 - std::panicking::default_hook::hf5fcb0f213fe709a
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:292:9
  11:     0x56459306af48 - std::panicking::rust_panic_with_hook::h095fccf1dc9379ee
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:779:13
  12:     0x56459306ae22 - std::panicking::begin_panic_handler::{{closure}}::h032ba12139b353db
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:657:13
  13:     0x564593069b06 - std::sys_common::backtrace::__rust_end_short_backtrace::h9259bc2ff8fd0f76
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:171:18
  14:     0x56459306ab80 - rust_begin_unwind
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:645:5
  15:     0x564592882bb5 - core::panicking::panic_fmt::h784f20a50eaab275
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panicking.rs:72:14
  16:     0x5645928831f3 - core::result::unwrap_failed::h03d8a5018196e1cd
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/result.rs:1649:5
  17:     0x56459289d9a4 - core::result::Result<T,E>::expect::ha0723b60de3bec48
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/result.rs:1030:23
  18:     0x5645928f7d56 - gatt_echo_client::exercise_characteristic::{{closure}}::h5ee827172818e4f5
                               at /home/vricosti/Dev/bluer/bluer/examples/gatt_echo_client.rs:112:24
  19:     0x5645928fb790 - gatt_echo_client::main::{{closure}}::hd186ebcb13806ee9
                               at /home/vricosti/Dev/bluer/bluer/examples/gatt_echo_client.rs:166:80
  20:     0x56459294d093 - tokio::runtime::park::CachedParkThread::block_on::{{closure}}::h2c54c4e9ba6c0ccc
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/park.rs:281:63
  21:     0x56459294ce93 - tokio::runtime::coop::with_budget::h997bf4c4bdce996c
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/coop.rs:107:5
  22:     0x56459294ce93 - tokio::runtime::coop::budget::hedbd3146926cec87
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/coop.rs:73:5
  23:     0x56459294ce93 - tokio::runtime::park::CachedParkThread::block_on::hcd1427df85fc73c4
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/park.rs:281:31
  24:     0x5645929128c4 - tokio::runtime::context::blocking::BlockingRegionGuard::block_on::he02839e01adcac55
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/context/blocking.rs:66:9
  25:     0x5645928bbf71 - tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}::h25e551cefe8c689e
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/multi_thread/mod.rs:87:13
  26:     0x564592942950 - tokio::runtime::context::runtime::enter_runtime::hf5eb4e781ca5de03
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/context/runtime.rs:65:16
  27:     0x5645928bbf20 - tokio::runtime::scheduler::multi_thread::MultiThread::block_on::h91a78faaa43b421c
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/scheduler/multi_thread/mod.rs:86:9
  28:     0x5645928a1848 - tokio::runtime::runtime::Runtime::block_on::h918a00c372bb5e30
                               at /home/vricosti/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.36.0/src/runtime/runtime.rs:350:45
  29:     0x5645928f33bb - gatt_echo_client::main::h382b890b8248f5eb
                               at /home/vricosti/Dev/bluer/bluer/examples/gatt_echo_client.rs:200:5
  30:     0x564592903452 - core::ops::function::FnOnce::call_once::hfe57caa1a4c1d2d0
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  31:     0x564592912795 - std::sys_common::backtrace::__rust_begin_short_backtrace::h62c93b257f1cdf85
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:155:18
  32:     0x56459294c5f6 - std::rt::lang_start::{{closure}}::h7dd040905d6fe1dc
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/rt.rs:166:18
  33:     0x564593061f61 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h37600b1e5eea4ecd
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:284:13
  34:     0x564593061f61 - std::panicking::try::do_call::hb4bda49fa13a0c2b
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:552:40
  35:     0x564593061f61 - std::panicking::try::h8bbf75149211aaaa
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:516:19
  36:     0x564593061f61 - std::panic::catch_unwind::h8c78ec68ebea34cb
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panic.rs:142:14
  37:     0x564593061f61 - std::rt::lang_start_internal::{{closure}}::hffdf44a19fd9e220
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/rt.rs:148:48
  38:     0x564593061f61 - std::panicking::try::do_call::hcb3194972c74716d
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:552:40
  39:     0x564593061f61 - std::panicking::try::hcdc6892c5f0dba4c
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:516:19
  40:     0x564593061f61 - std::panic::catch_unwind::h4910beb4573f4776
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panic.rs:142:14
  41:     0x564593061f61 - std::rt::lang_start_internal::h6939038e2873596b
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/rt.rs:148:20
  42:     0x56459294c5ca - std::rt::lang_start::hd5b8d7bf12173c4d
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/rt.rs:165:17
  43:     0x5645928f346e - main
  44:     0x7f8aede29d90 - __libc_start_call_main
                               at ./csu/../sysdeps/nptl/libc_start_call_main.h:58:16
  45:     0x7f8aede29e40 - __libc_start_main_impl
                               at ./csu/../csu/libc-start.c:392:3
  46:     0x5645928834f5 - _start
  47:                0x0 - <unknown>

I can reproduce this using BlueZ 5.68. Older versions of BlueR have exactly the same problem with this version of BlueZ, thus the issue is probably caused by BlueZ.

Could you test with earlier versions of BlueZ and determine the first version that has this issue? I.e. run git bisect on the BlueZ source?

BlueZ version 5.72 seems to run better, but I still get some hangs.

Have there been any learnings on this issue? I'm also getting hangs and would love to know if there's a way around it (?).

(client running on arch pc) bluer: main branch 5e34d3e840 rustc: rustc 1.79.0 (129f3b996 2024-06-10) dbus: 1.14.10-2 bluez: 5.76-1

(server on rpi5) bluer: main branch 5e34d3e840 rustc: rustc 1.79.0 (129f3b996 2024-06-10) dbus: 1.14.10-1~deb12u1 arm64 bluez: 5.66-1+rpt1+deb12u1 arm64

Could you try with Linux 6.9.5?

I too had various problems using GATT because of bluez (was on 5.66), but sticking with the latest available version solved everything (maybe because of the GATT fixes on 67/70/72/74 but didnt had the time to troubleshoot around).

Since it seems to be resolved, I am closing this issue.