Discovering services and characteristics callback never called

[curioussavage]

Hi,

issue

I am connecting to a device and then calling discoverSomeServicesAndCharacteristics and discoverAllServicesAndCharacteristics I passed a callback to both methods and it was never fired.

I did try the discoverServices method and using the 'servicesDiscover' listener. The callback was fired but the services argument was an empty array.

Steps taken to debug

I have been able to connect and listen to the particular service I want to with the lightBlue ios app.

Version

v1.6.0
v1.7.0

What do I need to do to debug this further?

[sandeepmistry]

@curioussavage are you using Linux? If so, an HCI dump capture would help debugging: sudo hcidump -t -x

[curioussavage]

yes. I will try to do that tomorrow and post it here.

[curioussavage]

HCI sniffer - Bluetooth packet analyzer ver 5.23
device: hci0 snap_len: 1500 filter: 0xffffffff
2017-02-14 05:10:34.409064 < HCI Command: Set Event Mask (0x03|0x0001) plen 8
Mask: 0xfffffbff07f8bf3d
2017-02-14 05:10:34.409571 > HCI Event: Command Complete (0x0e) plen 4
Set Event Mask (0x03|0x0001) ncmd 1
status 0x00
2017-02-14 05:10:34.409880 < HCI Command: LE Set Event Mask (0x08|0x0001) plen 8
mask 0x1f00000000000000 (Reserved)
2017-02-14 05:10:34.410386 > HCI Event: Command Complete (0x0e) plen 4
LE Set Event Mask (0x08|0x0001) ncmd 1
status 0x00
2017-02-14 05:10:34.410411 < HCI Command: Read Local Version Information (0x04|0x0001) plen 0
2017-02-14 05:10:34.410853 > HCI Event: Command Complete (0x0e) plen 12
Read Local Version Information (0x04|0x0001) ncmd 1
status 0x00
HCI Version: 4.1 (0x7) HCI Revision: 0xb6
LMP Version: 4.1 (0x7) LMP Subversion: 0x2209
Manufacturer: Broadcom Corporation (15)
2017-02-14 05:10:34.410881 < HCI Command: Write LE Host Supported (0x03|0x006d) plen 2
01 00
2017-02-14 05:10:34.411255 > HCI Event: Command Complete (0x0e) plen 4
Write LE Host Supported (0x03|0x006d) ncmd 1
00
2017-02-14 05:10:34.411282 < HCI Command: Read LE Host Supported (0x03|0x006c) plen 0
2017-02-14 05:10:34.411723 > HCI Event: Command Complete (0x0e) plen 6
Read LE Host Supported (0x03|0x006c) ncmd 1
00 01 00
2017-02-14 05:10:34.411746 < HCI Command: Read BD ADDR (0x04|0x0009) plen 0
2017-02-14 05:10:34.412163 > HCI Event: Command Complete (0x0e) plen 10
Read BD ADDR (0x04|0x0009) ncmd 1
status 0x00 bdaddr B8:27:EB:48:B2:32
2017-02-14 05:10:34.448193 < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
value 0x00 (scanning disabled)
filter duplicates 0x01 (enabled)
2017-02-14 05:10:34.448607 > HCI Event: Command Complete (0x0e) plen 4
LE Set Scan Enable (0x08|0x000c) ncmd 1
status 0x0c
Error: Command Disallowed
2017-02-14 05:10:34.448712 < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7
type 0x01 (active)
interval 10.000ms window 10.000ms
own address: 0x00 (Public) policy: All
2017-02-14 05:10:34.449211 > HCI Event: Command Complete (0x0e) plen 4
LE Set Scan Parameters (0x08|0x000b) ncmd 1
status 0x00
2017-02-14 05:10:34.454251 < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
value 0x01 (scanning enabled)
filter duplicates 0x01 (enabled)
2017-02-14 05:10:34.454727 > HCI Event: Command Complete (0x0e) plen 4
LE Set Scan Enable (0x08|0x000c) ncmd 1
status 0x00
2017-02-14 05:10:34.570930 > HCI Event: LE Meta Event (0x3e) plen 26
LE Advertising Report
ADV_IND - Connectable undirected advertising (0)
bdaddr FF:FF:70:00:D8:D4 (Public)
Flags: 0x05
TX power level: 0
Unknown type 0x19 with 2 bytes data
Shortened service classes: 0xffe0
RSSI: -77
2017-02-14 05:10:34.571889 > HCI Event: LE Meta Event (0x3e) plen 30
LE Advertising Report
SCAN_RSP - Scan Response (4)
bdaddr FF:FF:70:00:D8:D4 (Public)
Complete local name: 'iTAG '
RSSI: -77
2017-02-14 05:10:34.584237 < HCI Command: LE Create Connection (0x08|0x000d) plen 25
bdaddr FF:FF:70:00:D8:D4 type 0
interval 96 window 48 initiator_filter 0
own_bdaddr_type 0 min_interval 6 max_interval 12
latency 0 supervision_to 200 min_ce 4 max_ce 6
2017-02-14 05:10:34.587013 > HCI Event: Command Status (0x0f) plen 4
LE Create Connection (0x08|0x000d) status 0x00 ncmd 1
2017-02-14 05:10:34.773704 > HCI Event: LE Meta Event (0x3e) plen 19
LE Connection Complete
status 0x00 handle 64, role master
bdaddr FF:FF:70:00:D8:D4 (Public)
2017-02-14 05:10:34.773914 < HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2
40 00
2017-02-14 05:10:34.775093 > HCI Event: Command Status (0x0f) plen 4
LE Read Remote Used Features (0x08|0x0016) status 0x00 ncmd 1
2017-02-14 05:10:34.775139 < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
value 0x00 (scanning disabled)
filter duplicates 0x00 (disabled)
2017-02-14 05:10:34.776648 > HCI Event: Command Complete (0x0e) plen 4
LE Set Scan Enable (0x08|0x000c) ncmd 1
status 0x00
2017-02-14 05:10:34.847490 > HCI Event: LE Meta Event (0x3e) plen 12
LE Read Remote Used Features Complete
status 0x00 handle 64
Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
2017-02-14 05:10:34.860459 < ACL data: handle 64 flags 0x00 dlen 7
ATT: MTU req (0x02)
client rx mtu 256
2017-02-14 05:10:34.892324 > ACL data: handle 64 flags 0x02 dlen 7
ATT: MTU resp (0x03)
server rx mtu 23
2017-02-14 05:10:34.951833 < ACL data: handle 64 flags 0x00 dlen 11
ATT: Read By Group req (0x10)
start 0x0001, end 0xffff
type-uuid 0x2800
2017-02-14 05:10:34.967404 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 64 packets 2
2017-02-14 05:10:34.983121 > ACL data: handle 64 flags 0x02 dlen 24
ATT: Read By Group resp (0x11)
attr handle 0x0001, end group handle 0x0005
value 0x00 0x18
attr handle 0x0006, end group handle 0x0008
value 0x0f 0x18
attr handle 0x0009, end group handle 0x000b
value 0x02 0x18
2017-02-14 05:10:34.984430 < ACL data: handle 64 flags 0x00 dlen 11
ATT: Read By Group req (0x10)
start 0x0001, end 0xffff
type-uuid 0x2800
2017-02-14 05:10:35.013122 > ACL data: handle 64 flags 0x02 dlen 24
ATT: Read By Group resp (0x11)
attr handle 0x0001, end group handle 0x0005
value 0x00 0x18
attr handle 0x0006, end group handle 0x0008
value 0x0f 0x18
attr handle 0x0009, end group handle 0x000b
value 0x02 0x18
2017-02-14 05:10:35.013577 < ACL data: handle 64 flags 0x00 dlen 11
ATT: Read By Group req (0x10)
start 0x000c, end 0xffff
type-uuid 0x2800
2017-02-14 05:10:35.027418 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 64 packets 2
2017-02-14 05:10:35.042401 > ACL data: handle 64 flags 0x02 dlen 12
ATT: Read By Group resp (0x11)
attr handle 0x000c, end group handle 0x000e
value 0xe0 0xff
2017-02-14 05:10:35.042683 < ACL data: handle 64 flags 0x00 dlen 11
ATT: Read By Group req (0x10)
start 0x000c, end 0xffff
type-uuid 0x2800
2017-02-14 05:10:35.072417 > ACL data: handle 64 flags 0x02 dlen 12
ATT: Read By Group resp (0x11)
attr handle 0x000c, end group handle 0x000e
value 0xe0 0xff
2017-02-14 05:10:35.072665 < ACL data: handle 64 flags 0x00 dlen 11
ATT: Read By Group req (0x10)
start 0x000f, end 0xffff
type-uuid 0x2800
2017-02-14 05:10:35.087399 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 64 packets 2
2017-02-14 05:10:35.102347 > ACL data: handle 64 flags 0x02 dlen 9
ATT: Error (0x01)
Error: Attribute not found (10)
Read By Group req (0x10) on handle 0x000f
2017-02-14 05:10:35.104562 < ACL data: handle 64 flags 0x00 dlen 11
ATT: Read By Group req (0x10)
start 0x000f, end 0xffff
type-uuid 0x2800
2017-02-14 05:10:35.132346 > ACL data: handle 64 flags 0x02 dlen 9
ATT: Error (0x01)
Error: Attribute not found (10)
Read By Group req (0x10) on handle 0x000f
2017-02-14 05:10:35.286870 > HCI Event: Number of Completed Packets (0x13) plen 5
handle 64 packets 1
2017-02-14 05:10:42.432386 < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
value 0x00 (scanning disabled)
filter duplicates 0x01 (enabled)
2017-02-14 05:10:42.432872 > HCI Event: Command Complete (0x0e) plen 4
LE Set Scan Enable (0x08|0x000c) ncmd 1
status 0x0c
Error: Command Disallowed
2017-02-14 05:10:42.434162 < HCI Command: Disconnect (0x01|0x0006) plen 3
handle 64 reason 0x13
Reason: Remote User Terminated Connection
2017-02-14 05:10:42.434600 > HCI Event: Command Status (0x0f) plen 4
Disconnect (0x01|0x0006) status 0x00 ncmd 1
2017-02-14 05:10:42.437961 > HCI Event: Disconn Complete (0x05) plen 4
status 0x00 handle 64 reason 0x16
Reason: Connection Terminated by Local Host

[curioussavage]

@sandeepmistry here it is. I see at least two errors. That said I really have no idea what I'm looking at.

[gandhimonik]

I am facing a similar issue but its kind of intermittent for me.

I am trying to connect my Mac (macOS Sierra) with the rolling spider drone using noble but whenever I call either discoverSomeServicesAndCharacteristics or discoverAllServicesAndCharacteristics, sometimes the callbacks do get called and I get the services and characteristics array but most of the times, the callbacks don't get called.

[sandeepmistry]

@curioussavage I think it's related to this:

2017-02-14 05:10:42.434162 < HCI Command: Disconnect (0x01|0x0006) plen 3
handle 64 reason 0x13
Reason: Remote User Terminated Connection

I think the Linux kernel is sending a disconnect out. Probably related to #465 and #480.

[benjaminhon]

i have the same issue, the noble bindings for the event servicesDiscover always returns undefined for the serviceUuids, but the callback way works

[ojack]

@gandhimonik did you find any solution for this? I am also having the same problem intermittently with the rolling spider

[gandhimonik]

@ojack I've started using discoverServices and discoverCharacteristics since then. I've observed that these 2 methods are more reliable. Basically, you call discoverServices on the peripheral object and then you call discoverCharacteristics on each service object.

[ojack]

Thanks @gandhimonik !
In case this helps anyone, I also have found that I don't have this problem when I turn off WIFI (Ubuntu 18.04).

[TomWS1]

I have the same problem that discoverAllServicesAndCharacteristics and discoverServices do not get a callback on Raspberry Pi 3 (stretch) with a CSR USB BT module in some cases.
However, I have discovered, quite by accident, that this error will go away if I unplug & replug the module after booting. I can consistently get the failure if I reboot (or start from unpowered state), and the callback always succeeds if I replug the adapter. After both cases the hciconfig -a results are the same except for the number of rx & tx bytes & events are much higher after reboot.
I am attaching a zip file with the test code, fail and ok logs, and hciconfig results. Let me know if you need anything else.
discoverServicesFail.zip

[TomWS1]

Eureka! After looking at dmesg output after reboot, it appeared that the USB BT dongle was enumerated before the Bluetooth drivers were loaded. And, when the USB BT dongle was replugged later, the USB device was obviously restarted after the Bluetooth drivers were loaded.
Searching around, I found a useful tool, resetusb, that allowed me to programmatically 'replug' the dongle. If I did this prior to running my application, then the discoverServices callbacks always returned properly.
While there may be other approaches to this problem, this certainly seems like a good workaround.
The resetusb code can be found at https://www.clearchain.com/blog/posts/resetting-the-usb-bus-under-linux