Bluer causes bluetoothd to crash on armv7 #48
Comments
|
A couple of additional notes.
|
|
Please open a bug with BlueZ, i.e. bluetoothd, since it should not crash under any circumstances. |
|
I believe the upstream issue is bluez/bluez#196. I agree that the root problem should be fixed there, but there doesn't seem to have been much movement on that issue since it was opened a year ago. And other clients seem to work fine on armv7, so I thought it might be worth investigating what it is about bluer's messages that cause the daemon to crash. If not, it might be worth documenting that armv7 targets are not supported by bluer until the upstream issue is resolved. |
|
I would suggest running bluetoothd under Memcheck and try to track down the bug that way. It should be easy to find that way. Working around the symptoms is usually not a good idea, especially in open source projects when the underlying cause can be fixed by submitting a patch. |
|
It is crashing inside libdbus though and I don't see how we could avoid that since it appears to be something internal when dealing with a DBusMessage. |
# This is the 1st commit message: BLE Passive Scanning # This is the commit message #2: monitor # This is the commit message bluez#3: monitor # This is the commit message bluez#4: monitor # This is the commit message bluez#5: monitor # This is the commit message bluez#6: monitor # This is the commit message bluez#7: monitor # This is the commit message bluez#8: monitor # This is the commit message bluez#9: monitor # This is the commit message bluez#10: monitor # This is the commit message bluez#11: monitor # This is the commit message bluez#12: monitor # This is the commit message bluez#13: monitor # This is the commit message bluez#14: monitor # This is the commit message bluez#15: monitor # This is the commit message bluez#16: monitor # This is the commit message bluez#17: monitor # This is the commit message bluez#18: monitor # This is the commit message bluez#19: monitor # This is the commit message bluez#20: monitor # This is the commit message bluez#21: monitor # This is the commit message bluez#22: monitor # This is the commit message bluez#23: monitor # This is the commit message bluez#24: monitor # This is the commit message bluez#25: monitor # This is the commit message bluez#26: monitor # This is the commit message bluez#27: monitor # This is the commit message bluez#28: monitor # This is the commit message bluez#29: monitor # This is the commit message bluez#30: monitor # This is the commit message bluez#31: monitor # This is the commit message bluez#32: monitor # This is the commit message bluez#33: monitor # This is the commit message bluez#34: monitor # This is the commit message bluez#35: monitor # This is the commit message bluez#36: monitor # This is the commit message bluez#37: monitor # This is the commit message bluez#38: monitor # This is the commit message bluez#39: monitor # This is the commit message bluez#40: monitor # This is the commit message bluez#41: monitor # This is the commit message bluez#42: monitor # This is the commit message bluez#43: monitor # This is the commit message bluez#44: monitor # This is the commit message bluez#45: monitor # This is the commit message bluez#46: monitor # This is the commit message bluez#47: monitor # This is the commit message bluez#48: monitor # This is the commit message bluez#49: monitor # This is the commit message bluez#50: monitor # This is the commit message bluez#51: monitor # This is the commit message bluez#52: monitor # This is the commit message bluez#53: monitor # This is the commit message bluez#54: monitor # This is the commit message bluez#55: monitor # This is the commit message bluez#56: monitor # This is the commit message bluez#57: monitor # This is the commit message bluez#58: monitor # This is the commit message bluez#59: monitor # This is the commit message bluez#60: monitor # This is the commit message bluez#61: monitor # This is the commit message bluez#62: monitor
|
I can confirm that this is still an issue. After some digging, it seems like blueR does not exit cleanly in any circumstances. fn main() {
simple_logger::SimpleLogger::new()
.with_level(log::LevelFilter::Trace)
.init()
.unwrap();
let rt = tokio::runtime::Builder::new_current_thread()
.enable_time()
.enable_io()
.build()
.expect("failed to build tokio runtime");
log::info!("Starting async tokio task...");
let _ = rt.block_on(async {
let session = bluer::Session::new().await?;
let adapter = session.default_adapter().await?;
adapter.set_powered(true).await?;
log::info!("Starting discovery");
let event_stream = adapter.discover_devices().await?;
tokio::time::sleep(tokio::time::Duration::from_secs(1)).await;
log::info!("Stopping discovery");
bluer::Result::Ok(())
});
//explicit drop and flush to make sure messages are not stuck somewhere
drop(rt);
log::logger().flush();
std::io::stdout().flush().unwrap();
std::io::stderr().flush().unwrap();
}For me, this procudes the following log output:
When setting the log level to trace, one would expect at least a "StopDiscovery" message on the dbus, which doesnt happen. I tried to dig even deeper into it, and it seems like the whole cleanup routine of "SessionInner" is never executed. From my understanding, at least this code should be executed on program exit: tokio::spawn(async move {
let _ = term_rx.await;
log::trace!("Terminating single session for {}", &path);
stop_fn.await;
let _ = termed_tx.send(());
log::trace!("Terminated single session for {}", &path);
});However, the drop trait of "SessionInner" only calls ".abort" on the tokio Task. I also noticed that by not assigning the event stream, the cleanup DOES happen. Most likely because in this case the compiler removes the "start_discovery" call alltogether. Maybe this calls causes some circular referencing issue, or the event stream uses a reference for too long. I also tried dropping the event stream manually via "drop" before destroying the adapter/session, without effect. This seems like quite an important issue. It could also explain other posts, e.g. the "busy" issue in BlueZ after termination. Edit: When dropping the "event_stream" and waiting for some time (e.g. 1 second) before leaving the scope, the cleanup does happen. Seems like it needs some time to send those messages. Seems weird. What would be the proper way of handling the wait time? Hardcoding a certain time period is not a good solution. However, even with successfull clean up, the crash on armv7 still happens. This is strange, because the bluetoothctl tool works without issues. For me it still seems like maybe something isnt cleaned up properly by blueR. |
|
On my Raspi, bluetoothd started crashing in the last few days, probably some os package updates introduced that, don't know. After updating all dependencies, the issue was still there. I've now added a let filter = DiscoveryFilter {
transport: DiscoveryTransport::Le,
..Default::default()
};
adapter.set_discovery_filter(filter).await?; |
From the Tokio docs:
Dropping the Tokio runtime does not guarantee that all background tasks are run to completion, thus Nevertheless, |
|
Hey everyone and @surban , I have an update on the issue. I spend some days investigating further and found the cause of the problem. In blueZ, the scan filter gets parsed when receiving the dbus message. During deserialization, blueZ has to deserialize two booleans (the flags for discoverable and duplicate data in the scan filter). The error here was that dbus always requires booleans to be 4 bytes, but blueZ uses stdbool which on many platforms only has one byte. This leads to a heap corruption of the blueZ service, causing a random crash shortly later. I have submitted a patch for blueZ here: https://patchwork.kernel.org/project/bluetooth/patch/20231107103507.505581-1-lukas.funke-oss@weidmueller.com/ So why does this only happen on ARM? My best guess here is that on x86 the filter struct has more padding bytes after the two boolean flags (which come last in the C struct), so its actually pure luck that it doesnt crash on x86. The code is still wrong on x86, too. Here is another interesting find: The crash does not happen when using bluetoothctl. So why is that? After some more digging it turns out that bluetoothctl behaves different from blueR when it comes to setting the scan filter. It does NOT set the two boolean flags in the scan filter if they are set to false, which is the default. The behavior of bluetoothctl seems to be that, if a flag has its default value, its not send at all. However, blueR sends the two flags with a "false" value, causing the deserialization and heap corruption in blueZ. @surban Even though this issue is theoretically fixed now, I think it might still be worth investigating a "hack fix" for blueR here. Almost all users of blueZ will experience this crash otherwise and I can not tell when the fix will be live. Maybe it would be a possibility to not send the discoverable and duplicate flags at all when they are set to false (just like bluetoothctl does)? Even though this is not blueRs fault, it would at least improve compatbility with blueZ vastly for allmost all users (think e.g. Raspberry Pi projects). |
|
Thanks for figuring that out @Mille2525! Could you try with version 0.16.2-pre1 and check if it fixes the issue with an unpatched bluetoothd? |
|
@surban I can check, but currently I only see changes to the release notes and cargo.toml file in that branch. Or am I mistaken? What changed in the code specifically? |
|
Hi @surban , thanks for the clarification! How did you determine the default values? I see that you assume true and false as defaults for duplicateData and discoverable, respectively. However, to me it seems like both are "false" by default, at least if I interpret the source code of bluetoothctl correctly (See: https://github.com/bluez/bluez/blob/8b035b70f379e45a32c94579ec8d00e48070c21e/client/main.c#L1251 ) Also: I just noticed that the bluez heap crash patch was accepted into the master! :) So this issue should hopefully be gone in newer bluez versions. |
|
I have taken the default values from the D-Bus API documentation. However, from the code it seems that you are right and both default to false. |
|
I've changed the default assumption in version 0.17.0-pre1. Please test. |
|
Fixed in version 0.17.0. |
On a Raspberry Pi 4 running 32-bit Pi OS, the following program will cause
bluetoothdto crash when the program exits:Running this program causes
bluetoothdto crash with an error similar to the following:I believe this is the same issue that was previously reported in #9. However, the
bluetoothctlprogram does not causebluetoothdwhen performing scans, so there must be something different with bluer's interactions. It is also interesting to note that the crash does not occur until the program exits, even though the bluer objects are already dropped. Also, unlike #9, this crash is occurring on normal program exit, not Ctrl+C.One thing I note in the DBus logs is that on initialization, a number of DBus matches are added:
However, when the objects are dropped, only one of those matches is removed:
I don't know enough about DBus or bluez to know if that could cause the problem or if it's just a red herring, but it's the only unusual thing in the DBus logs that jumped out to me.
Versions:
The text was updated successfully, but these errors were encountered: