peplin
Subscribe raises a ExpectedResponseTimeout even though receiving notifications
A ExpectedResponseTimeout exception is being thrown when conducting the following test:
- Connect to a BLE device (using the BGAPI backend)
- Subscribe to a characteristic
- Subscribe to a second characteristic
Step 3 raises a ExpectedResponseTimeout even though I am correctly receiving notifications from this second characteristic.
Minimum not working example:
import pygatt
import time
def callback_func(handle, data):
print(handle)
adapter = pygatt.BGAPIBackend()
try:
adapter.start()
device = adapter.connect('A0:E6:F8:75:49:05')
for index in range(2):
print('---------- {} ----------'.format(index))
uuid = pygatt.util.uuid16_to_uuid(0xBF01 + index)
device.subscribe(uuid, callback=callback_func)
time.sleep(10)
finally:
adapter.stop()
Output:
---------- 0 ----------
---------- 1 ----------
30
30
30
30
34
30
34
...
30
34
---------------------------------------------------------------------------
ExpectedResponseTimeout Traceback (most recent call last)
<ipython-input-4-aa24e1013855> in <module>()
15 print('---------- {} ----------'.format(index))
16 uuid = pygatt.util.uuid16_to_uuid(0xBF01 + index)
---> 17 device.subscribe(uuid, callback=callback_func)
18 time.sleep(10)
19 finally:
/usr/local/lib/python3.5/dist-packages/pygatt/device.py in subscribe(self, uuid, callback, indication)
158 characteristic_config_handle,
159 properties,
--> 160 wait_for_response=False
161 )
162 log.info("Subscribed to uuid=%s", uuid)
/usr/local/lib/python3.5/dist-packages/pygatt/backends/bgapi/device.py in wrapper(self, *args, **kwargs)
19 if self._handle is None:
20 raise exceptions.NotConnectedError()
---> 21 return func(self, *args, **kwargs)
22 return wrapper
23
/usr/local/lib/python3.5/dist-packages/pygatt/backends/bgapi/device.py in char_write_handle(self, char_handle, value, wait_for_response)
104 self._handle, char_handle, value_list))
105
--> 106 self._backend.expect(ResponsePacketType.attclient_attribute_write)
107 packet_type, response = self._backend.expect(
108 EventPacketType.attclient_procedure_completed)
/usr/local/lib/python3.5/dist-packages/pygatt/backends/bgapi/bgapi.py in expect(self, expected, *args, **kargs)
515
516 def expect(self, expected, *args, **kargs):
--> 517 return self.expect_any([expected], *args, **kargs)
518
519 def expect_any(self, expected_packet_choices, timeout=None,
/usr/local/lib/python3.5/dist-packages/pygatt/backends/bgapi/bgapi.py in expect_any(self, expected_packet_choices, timeout, assert_return_success)
551 expected_packet_choices, timeout)
552 exc.__cause__ = None
--> 553 raise exc
554 continue
555
ExpectedResponseTimeout: Timed out after 1.000000s waiting for [<ResponsePacketType.attclient_attribute_write: 43>]
Is this error normal? When trying to read the subscribe code I see in line 160: wait_for_response=False which I assumed means we are not waiting for a response.
That's odd - does it work if you drop time.sleep(1) in between the calls to subscribe? I'm not able to reproduce this error with my devices.
You are correct, it's not waiting for a response from the remote BLE device. Every command you send to the BGAPI devices return an ACK, so the error in this case is that we are sending the attribute_write command (to enable notifications for this characteristic), but never receiving the ACK. That ACK should be returned almost immediately over USB unless something's wrong (or it rejected the attribute write, perhaps, but even then I expect an error response).
If you don't mind enabling debug logging and sending me the log, that will include every low level command and ACK from the BGAPI layer, and it might give me an idea of what's going on.
Thank you for investigating this! Here is a log : https://gist.github.com/danjjl/b8e56e27b7e7a4590761fd38caf1ff23
These four lines in particular look suspicious:
DEBUG:pygatt.backends.bgapi.bgapi:Received a ResponsePacketType.connection_disconnect packet: Success
INFO:pygatt.backends.bgapi.device:Disconnected from A0:E6:F8:75:50:84
INFO:pygatt.backends.bgapi.bgapi:Stopping
INFO:pygatt.backends.bgapi.bgapi:Stopping receiver
Does it mean that the Bluetooth device disconnected or that the BLED112 disconnected?
(I also tried with a time.sleep(1) - produced the same result)
(To add to the weirdness - if I ignore the error - with an except statement and that I then subscribe to a third characteristic I do not have a problem)
Earlier in the log it looks like a disconnection from the BLE device is initiated from the Python side somehow. This is the log when you are first attempting to subscribe to the 2nd characteristic:
DEBUG:pygatt.device:Looking up handle for characteristic 0000bf02-0000-1000-8000-00805f9b34fb
DEBUG:pygatt.device:Found <Characteristic uuid=0000bf02-0000-1000-8000-00805f9b34fb handle=34>
DEBUG:pygatt.backends.bgapi.bgapi:Expecting a response of one of [<ResponsePacketType.attclient_attribute_write: 43>] within 1.000000s
INFO:pygatt.device:Received notification on handle=0x1e, value=0xb'28a804dba604f4a50400a50421a404'
DEBUG:pygatt.backends.bgapi.device:Disconnecting from A0:E6:F8:75:50:84
The Disconnecting from... is from BGAPIBLEDevice.disconnect which should only be called if you call it manually, you call adapter.stop() manually, or you call adapter.start() twice while it was already running.
It would be interesting if you print a a stacktrace from that disconnect method to see how we are getting there. Just drop this in the top of that function and run it:
import traceback
traceback.print_stack()
Debug + stacktrace : https://gist.github.com/danjjl/271a83e8dcc7451656ac841fb4e95961
From the stacktrace, I think the disconnect calls are normal. When subscribe throws an exception, the code executes the finally block:
adapter.stop()
which triggers the BGAPIBLEDevice.disconnect call.
If I now run this code:
import pygatt
import time
import logging
logging.basicConfig()
logging.getLogger('pygatt').setLevel(logging.DEBUG)
def callback_func(handle, data):
print(handle)
adapter = pygatt.BGAPIBackend()
adapter.start()
device = adapter.connect('A0:E6:F8:75:50:84')
for index in range(2):
print('---------- {} ----------'.format(index))
uuid = pygatt.util.uuid16_to_uuid(0xBF01 + index)
device.subscribe(uuid, callback=callback_func)
time.sleep(1)
time.sleep(10)
adapter.stop()
(same code as in the first comment with an extra time.sleep(1), debugging and removed the try-finally)
I no longer find the disconnect event in the log. However after line 282
DEBUG:pygatt.backends.bgapi.bgapi:Expecting a response of one of [<EventPacketType.attclient_procedure_completed: 17>] within 1.000000s
I do not receive:
DEBUG:pygatt.backends.bgapi.bgapi:Received a EventPacketType.attclient_procedure_completed packet: Success
Log without the try-except: https://gist.github.com/danjjl/1121dd0ed5fc70cf8fc32297559f5f98
(I tried with a second BLED112 dongle without success)
Was this ever closed? If so, how did you resolve it?
See this same issue now on only some of our test machines, but not others.
Hi, I have got same issue here: It points the error like this:
File "
File ".....pygatt\backends\bgapi\bgapi.py", line 417, in connect raise exc
NotConnectedError
when I scanned the adapter, I can see the BLE device, however when run the above code (adapter.connect), I am having this "ExpectedResponseTimeout" error.
Could you please help me here? Thanks Numan
Please give v4.0 a try if this is still an issue. I can't claim to have fixed it because we never figured out the root cause, but there are a lot of improvements in 4.0 that may help.
Hi all,
Version 4.0.3 still has this problem for me. However, if I simply ignore the exception on the second subscribe() and wait for the notification to time out, it works fine afterward. So, pseudocode example,
device.subscribe(uuid1, fn1)
try:
device.subscribe(uuid2, fn2)
except:
pass
# ~10 second delay here waiting for notification to time out
# Normal/Correct operation here: Both fn1() and fn2() are called as they receive notifications.
Note: This is using the GATTToolBackend on an Ubuntu machine
why i try to unsubscribe and i get this:
ExpectedResponseTimeout: Timed out after 30.000000s waiting for [<EventPacketType.attclient_procedure_completed: 17>]
why i try to unsubscribe and i get this:
ExpectedResponseTimeout: Timed out after 30.000000s waiting for [<EventPacketType.attclient_procedure_completed: 17>]
I also met the same question, I solved it after I add ACK in the MCU side. If no ACK after the unsubscribe it will show up the question, no matter you chose response = True or not.
