Fedora 39: [org.freedesktop.DBus.Error.NoReply] Remote peer disconnected

vovagorodok commented 11 months ago

bleak version: 0.21.1
Python version: 3.12.0
Operating System: Fedora Linux 39
BlueZ version (bluetoothctl -v) in case of Linux: 5.70

Description

When script trying to read from peripheral characteristics, flowing error occurs:

[org.freedesktop.DBus.Error.NoReply] Remote peer disconnected

What I Did

Ble uploader trying to read information about device from characteristics. Folowing script: https://github.com/vovagorodok/ArduinoBleOTA/blob/main/tools/uploader.sh executes uploader.py.

Works correctly when:

Used Ubuntu instead Fedora
Used bluezero instead bleak (by chenging to bluezero_uploader.py in uploader.sh)

Looks that issue is with bleak in Fedora 39 (trying in Lenovo T490 and HP Zbook 14u G6)

Please let me know what logs I should gather. Thanks!

Logs

N/A

dlech commented 11 months ago

Please let me know what logs I should gather.

https://bleak.readthedocs.io/en/latest/troubleshooting.html

Used Ubuntu instead Fedora

Is everything else the same in this case? Same computer? Same Bluetooth adapter? Same BlueZ version?

vovagorodok commented 11 months ago

Is everything else the same in this case? Same computer? Same Bluetooth adapter? Same BlueZ version?

Yes the same device (compuer and ble adapter). Before Fedora 39, Ubuntu 23.04 was installed, perhaps with older BlueZ version. Checked in another computer with Fedora 39 and the issue exist. Looks that issue is with bleak in Fedora 39.

Traceback (most recent call last):
  File "/home/tsiselsk/Projects/private/ArduinoBleOTA/tools/uploader.py", line 241, in try_scan_and_upload
    asyncio.run(scan_and_upload(path))
  File "/usr/lib64/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/asyncio/base_events.py", line 664, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/home/tsiselsk/Projects/private/ArduinoBleOTA/tools/uploader.py", line 236, in scan_and_upload
    await connect_and_upload(devices[device_num], path)
  File "/home/tsiselsk/Projects/private/ArduinoBleOTA/tools/uploader.py", line 191, in connect_and_upload
    res = await connect(dev)
          ^^^^^^^^^^^^^^^^^^
  File "/home/tsiselsk/Projects/private/ArduinoBleOTA/tools/uploader.py", line 115, in connect
    await acquire_mtu(client)
  File "/home/tsiselsk/Projects/private/ArduinoBleOTA/tools/uploader.py", line 83, in acquire_mtu
    await client._backend._acquire_mtu()
  File "/home/tsiselsk/.local/lib/python3.12/site-packages/bleak/backends/bluezdbus/client.py", line 586, in _acquire_mtu
    assert_reply(reply)
  File "/home/tsiselsk/.local/lib/python3.12/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.freedesktop.DBus.Error.NoReply] Remote peer disconnected

As I see issue is in client._backend._acquire_mtu(). Acquire mtu is needed to achieve maximal upload speed. Should I attach logs for export BLEAK_LOGGING=1?

dlech commented 11 months ago

File "/home/tsiselsk/Projects/private/ArduinoBleOTA/tools/uploader.py", line 83, in acquire_mtu await client._backend._acquire_mtu()

I think this could be what is causing the problem. This looks like _acquire_mtu() is from a 3rd-party library. Whatever that function is doing could be triggering the disconnect.

Logging Bluetooth packets is useful too to see what is actually going on over the air.

vovagorodok commented 11 months ago

With export BLEAK_LOGGING=1:

2023-12-03 21:44:22,032 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to device @ 34:AB:95:8F:62:5A
2023-12-03 21:44:22,038 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to BlueZ path /org/bluez/hci0/dev_34_AB_95_8F_62_5A
2023-12-03 21:44:22,279 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_AB_95_8F_62_5A): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2023-12-03 21:44:23,036 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service0006', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 6)>, 'UUID': <dbus_fast.signature.Variant ('s', 00001801-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,037 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service0006/char0007', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 7)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002a05-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service0006)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Notifying': <dbus_fast.signature.Variant ('b', False)>, 'Flags': <dbus_fast.signature.Variant ('as', ['indicate'])>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,039 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service0006/char0007/desc0009', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 17938)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service0006/char0007)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,040 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 10)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c155ca-36c5-11ed-adc0-9741d6a72f04)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,040 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char000b', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 11)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c1564c-36c5-11ed-adc1-a3d6cf5cc2a4)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['write-without-response'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,040 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char000d', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 13)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c156e2-36c5-11ed-adc2-7396d4fd413a)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Notifying': <dbus_fast.signature.Variant ('b', False)>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'notify'])>, 'NotifyAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,040 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char000d/desc000f', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 17938)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char000d)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,041 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char0010', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 16)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c1576e-36c5-11ed-adc3-8799895de51e)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,041 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char0012', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 18)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c15886-36c5-11ed-adc5-1bc0d0a6069d)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,041 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char0014', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 20)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c157fa-36c5-11ed-adc4-579c60267b47)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,041 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a/char0016', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 22)>, 'UUID': <dbus_fast.signature.Variant ('s', 15c1591c-36c5-11ed-adc6-dbe9603dbf19)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_AB_95_8F_62_5A/service000a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 242)>}, 'org.freedesktop.DBus.Properties': {}}]
2023-12-03 21:44:23,041 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_AB_95_8F_62_5A): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
[org.freedesktop.DBus.Error.NoReply] Remote peer disconnected

Logging Bluetooth packets is useful too to see what is actually going on over the air.

Or do You mean wireshark logs?

dlech commented 11 months ago

Yes, I meant Wireshark.

vovagorodok commented 11 months ago

Captured wireshark logs: bluetooth.zip

dlech commented 11 months ago

In the wireshark logs, it looks like it is starting to do some Bluetooth classic stuff after the Bluetooth low energy stuff. Is this a dual-mode device?

I'm not as familiar with those commands, so I don't know what it is supposed to look like, but I'm guessing BlueZ isn't getting an expected response or is getting a wrong response and disconnects.

dlech commented 11 months ago

If it works with one BlueZ version but not in another, I would report the bug to BlueZ.

vovagorodok commented 11 months ago

I also think it's probably a problem with BlueZ. Where issues with BlueZ should be reported?

dlech commented 11 months ago

Where issues with BlueZ should be reported?

https://github.com/bluez/bluez/ (or the Linux Bluetooth mailing list)

vovagorodok commented 9 months ago

https://github.com/bluez/bluez/issues/670#issuecomment-1936526131 Looks that issue is somewhere between bleak and BlueZ just in latest Fedora 39 (in test Ubuntu 24.04 and same BlueZ ver works ok). Only dbus is between I gues?

vovagorodok commented 7 months ago

@dlech have You idea how to workaround issue for this moment? Because I'm without working solution in Fedora. Trying: and have logs like (exception that we already connected):

Connecting to ArduinoBleOTA
[org.freedesktop.DBus.Error.NoReply] Remote peer disconnected
Client is already connected

After removing reconnection I have exception:

[org.freedesktop.DBus.Error.UnknownObject] Method "ReadValue" with signature "a{sv}" on interface "org.bluez.GattCharacteristic1" doesn't exist

dlech commented 7 months ago

Issues with dual mode devices were discussed recently in #1521. I'm not sure what we can do about it besides fix it in BlueZ.

vovagorodok commented 7 months ago

In Ubuntu it works with the same BlueZ version. Created issue on Fedora side: https://bugzilla.redhat.com/show_bug.cgi?id=2269464

hbldh / bleak