QBluetoothSocketPrivate::_q_readNotify() error

Hello folks,

I am developing an application to control BLE gadget cars:

I have an issue with multiple type of cars (equipped with different electronics): both dropping the connection after a certain amount of time (varied 10-30 sec) with the following error on my XA2:

[W] unknown:0 - void QBluetoothSocketPrivate::_q_readNotify() 48 error: -1 "Software caused connection abort"
[W] BleRcCar::errorReceived:64 - QLowEnergyController::Error(UnknownError) 35306

The application is pretty simple: it publishing some data to a characteristics, and subscribes to a battery notification characteristics.

Both characteristics operation working as intended.

I have tried to do the following, but neither helped:

  • Reduced the write interval
  • Tried with both Random and Public remote address types
  • Disabling the battery notification subscribtion

The connection drops randomly after a certain period on my XA2, while it works just fine on a Jolla Cified Aqua fish, both running 4.3.0.12.

Any idea is welcome!

1 Like

It looks my suspicion about the fact that it works with the Jolla C was a bit too early, the connection breaks on that as well but here with:

[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[W] unknown:0 - void QBluetoothSocketPrivate::_q_readNotify() 52 error: -1 "Timeout in connection"
[D] unknown:0 - Unknown l2cp socket error:  QBluetoothSocket::UnknownSocketError "Timeout in connection"

I have increased the logging level of the Qt Bluetooth module with:

QLoggingCategory::setFilterRules(QStringLiteral("qt.bluetooth* = true"));

however nothing suspicious shows up before the connection break as it shown above.
(The ’ Writing characteristic 9 (size: b with response: false ) lines are the periodic characteristic writes what I perform periodically to send commands to the car.

I have created a trace with btmon from the disconnect and I found it very interesting:

The 27 byte ATT write commands are the commands what I send out periodically (with 50 ms interval).
And then at once (for some unknown reason) the hosts asks the controller for disconnect specifying the remote side as a reason for disconnection.

I did an experiment with gattool: I connected to the device and manually sent commands with
char-write-req 0x0012 025e695a48ff2a438ca680f83e04e45d

However this way I did not get disconnected at all, and the battery notifications are kept received periodically.

The difference between the gattool and my app approach is the fact that I do a service discovery in my app.
Maybe it could be related to the issue?

It just popped at me … 50ms interval? That may be a bit too short? Just a guess. Maybe worth a test.

It just popped at me … 50ms interval? That may be a bit too short? Just a guess. Maybe worth a test.

As I written in the first post I tried it and it does not help.
On the another hand the Android app uses this interval as well.

It disconnect even if I do not do anything. It disconnect with the Qt’s lowenergyscanner example as well.

Ah, missed it. I actually have an XA2 coming (next week), but I’m not sure I can help debug without the correct kind of client?

Ah, missed it. I actually have an XA2 coming (next week), but I’m not sure I can help debug without the correct kind of client?

I will find some other BLE devices to see if the disconnect happens with them as well (but I assume it won’t)

The difference between the gatttool and the Qt based control mode is the discovery:
With gatttool I do not perform any discovery: the characteristics is written by a handle, while the Qt API mandates the discovery of the services and their characteristics. During the service an characteristics discovery I see a lot of suspicious messages:

[D] unknown:0 - Sending read_by_group_type request, startHandle: 8 endHandle: ffff 2800
[D] unknown:0 - Received size: 14 data: "110608000e00f0ff0f0012000f18"
[D] unknown:0 - Found uuid: "{0000fff0-0000-1000-8000-00805f9b34fb}" start handle: 8 end handle: e
[W] BburagoRcCar::serviceDiscovered:59 - service discovered "{0000fff0-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Sending read_by_type request, startHandle: 8 endHandle: e type: 2802 packet: "0808000e000228"
[D] unknown:0 - Found uuid: "{0000180f-0000-1000-8000-00805f9b34fb}" start handle: f end handle: 12
[W] BburagoRcCar::serviceDiscovered:59 - service discovered "{0000180f-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Sending read_by_type request, startHandle: f endHandle: 12 type: 2802 packet: "080f0012000228"
[D] unknown:0 - Sending read_by_group_type request, startHandle: 13 endHandle: ffff 2800
[D] unknown:0 - Received size: 5 data: "010808000a"
[D] unknown:0 - Error1: "no attribute in given range found" last command: 8 handle: 8
[D] unknown:0 - Sending read_by_type request, startHandle: 8 endHandle: e type: 2803 packet: "0808000e000328"
[D] unknown:0 - Received size: 5 data: "01080f000a"
[D] unknown:0 - Error1: "no attribute in given range found" last command: 8 handle: f
[D] unknown:0 - Sending read_by_type request, startHandle: f endHandle: 12 type: 2803 packet: "080f0012000328"
[D] unknown:0 - Received size: 5 data: "011013000a"
[D] unknown:0 - Error1: "no attribute in given range found" last command: 10 handle: 13
[D] unknown:0 - Sending read_by_group_type request, startHandle: 1 endHandle: ffff 2801
[D] unknown:0 - Received size: 16 data: "090709001c0a00f1ff0c00100d00f2ff"
[D] unknown:0 - Found handle: 9 properties: QFlags(0x4|0x8|0x10) value handle: a uuid: "{0000fff1-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Found handle: c properties: QFlags(0x10) value handle: d uuid: "{0000fff2-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Sending read_by_type request, startHandle: d endHandle: e type: 2803 packet: "080d000e000328"
[D] unknown:0 - Received size: 9 data: "09071000121100192a"
[D] unknown:0 - Found handle: 10 properties: QFlags(0x2|0x10) value handle: 11 uuid: "{00002a19-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Sending read_by_type request, startHandle: 11 endHandle: 12 type: 2803 packet: "08110012000328"
[D] unknown:0 - Received size: 5 data: "011001000a"
[D] unknown:0 - Error1: "no attribute in given range found" last command: 10 handle: 1
[D] unknown:0 - Received size: 5 data: "01080d000a"
[D] unknown:0 - Error1: "no attribute in given range found" last command: 8 handle: d
[D] unknown:0 - Reading all characteristic values for "{0000fff0-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Discovering descriptor values for "{0000fff0-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Sending find_info request (9, c) 9
[D] unknown:0 - Received size: 5 data: "010811000a"
[D] unknown:0 - Error1: "no attribute in given range found" last command: 8 handle: 11
[D] unknown:0 - Reading all characteristic values for "{0000180f-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Received size: 14 data: "0501090003280a00f1ff0b000229"
[D] unknown:0 - Suppressing primary/characteristic 2803
[D] unknown:0 - Suppressing char handle a
[D] unknown:0 - Descriptor found, uuid: "{00002902-0000-1000-8000-00805f9b34fb}" descriptor handle: b
[D] unknown:0 - Sending find_info request (c) c
[D] unknown:0 - Received size: 2 data: "0b38"
[D] unknown:0 - Discovering descriptor values for "{0000180f-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Sending find_info request (10) 10
[D] unknown:0 - Received size: 14 data: "05010c0003280d00f2ff0e000229"
[D] unknown:0 - Suppressing primary/characteristic 2803
[D] unknown:0 - Suppressing char handle d
[D] unknown:0 - Descriptor found, uuid: "{00002902-0000-1000-8000-00805f9b34fb}" descriptor handle: e
[D] unknown:0 - Reading all descriptor values for "{0000fff0-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Received size: 14 data: "0501100003281100192a12000229"
[D] unknown:0 - Suppressing primary/characteristic 2803
[D] unknown:0 - Suppressing char handle 11
[D] unknown:0 - Descriptor found, uuid: "{00002902-0000-1000-8000-00805f9b34fb}" descriptor handle: 12
[D] unknown:0 - Reading all descriptor values for "{0000180f-0000-1000-8000-00805f9b34fb}"
[D] unknown:0 - Received size: 3 data: "0b0000"
[D] unknown:0 - Received size: 3 data: "0b0000"
[W] ShellRcCar::controlServiceDetailsDiscovered:108 - Control service discovered QLowEnergyService::ServiceState(ServiceDiscovered)
[W] ShellRcCar::controlServiceDetailsDiscovered:111 - Connected!
[W] AvailableDevicesModel::currentDeviceConnectionStateChangedSlot:142 - AbstractRcCar::ConnectionState(Connecting) AbstractRcCar::ConnectionState(Connected)
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Writing characteristic 9 (size: b with response: false )
[D] unknown:0 - Received size: 3 data: "0b0000"

I am unsure if the Android app does discovery or not, or even if on Android is it possible to write to characteristics by handles.

Some further info about my investigation:

The disconnects’ Reason: Remote User Terminated Connection (0x13) seems to be a bit misleading.
If I call QLowEnergyController::disconnectFromDevice() the same reasoncode will be in the btmon logs.
The same get generated on Android if I disconnect from the car, and on SFOS too if I disconnect from the car with gattool.

I tried to examine the LE Create connection differences between the Android and my application:

Some parameters looks to be different, but for e.g. over time the connection interval got updated several times:

Also these parameters are identical between my app and gattool (gattool works fine, and no further LE Connection Updates are present in the traces):

What I want to say with this: it looks that not these parameters causing the issues.

I noticed that the Rx MTU size is different between the Android and Qt, and in the gattool log I have not found Exchange MTU requests:

If we look into the discovery differences (gattool does not do discovery at all, however Android does), I found that the Qt implementation does a secondary service declaration:

For which the device answers with attribute not found:
kép

I have enabled the bluetooth systemd service versbosity by adding a -d to the bluetoothd in the /usr/lib/systemd/system/bluetooth.service.

Relevant part of the journalctrl -x bluetooth.service output when disconnect happens (0A:C0:31:44:FF:BA is the gadget’s MAC I working with):

jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_0A_C0_31_44_FF_BA
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_0A_C0_31_44_FF_BA
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_0A_C0_31_44_FF_BA
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:device_free() 0x354800
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_0A_C0_31_44_FF_BA
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:device_free() 0x354800
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_A4_C1_38_E8_F5_37
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_A4_C1_38_E8_F5_37
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_A4_C1_38_E8_F5_37
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:device_free() 0x33a9a0
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_A4_C1_38_E8_F5_37
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:device_free() 0x33a9a0
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_5D_ED_2C_6A_B6_0E
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:device_remove() Removing device /org/bluez/hci0/dev_5D_ED_2C_6A_B6_0E
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_5D_ED_2C_6A_B6_0E
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_5D_ED_2C_6A_B6_0E
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/device.c:device_free() 0x354338
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/device.c:device_free() 0x354338
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/adapter.c:dev_disconnected() Device 0A:C0:31:44:FF:BA disconnected, reason 2
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr **0A:C0:31:44:FF:BA** type 1 status 0xe
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/adapter.c:resume_discovery()
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/adapter.c:dev_disconnected() Device 0A:C0:31:44:FF:BA disconnected, reason 2
jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr **0A:C0:31:44:FF:BA** type 1 status 0xe

What is especially strange for me is this line:

jan 26 22:03:27 XperiaXA2 bluetoothd[23661]: bluetoothd[23661]: src/adapter.c:dev_disconnected() Device 0A:C0:31:44:FF:BA disconnected, reason 2

This output should come from this line:

Where reason==2 should be MGMT_DEV_DISCONN_LOCAL_HOST

Daah. There is no proper headbang emoji here…

The solution was simple and straightforward: I needed to shut down the BLE discovery (call QBluetoothDeviceDiscoveryAgent::stop() and wait for the cancelled signal) before I start to connect to the device…

2 Likes

Man, oh, man. This is one of those Iconic deep dives only to discover … Thanks for your hard headed and thorough investigation. It’s shed some light on the bluetooth stack for me!