Fails to get services on Windows 11 when pkg_resources is imported and pywin32 package is installed

[zapta]

• bleak version:
• Python version:
• Operating System:
• BlueZ version (bluetoothctl -v) in case of Linux:

Win 11 Pro
OS: Windows-10-10.0.22621-SP0
Platform:: uname_result(system='Windows', node='DESKTOP-T0P7657', release='10', version='10.0.22621', machine='AMD64')
Python 3.10.7 (tags/v3.10.7:6cc6b13, Sep 5 2022, 14:08:36) [MSC v.1933 64 bit (AMD64)]

Description

Describe what you were trying to get done.
Tell us what happened, what went wrong, and what you expected to happen.

I have a a Python application that in some cases hangs when trying to establish a connection via Bleak. I reduced it to a small example that demonstrate the problem.

To reproduce:

1. Use Win 11. The issue doesn't exist under Win 10.
2. Use python 3.10.7 (I didn't try with other versions).
3. Start with all python packages removed. E.g. https://gankrin.org/how-to-remove-all-python-packages-installed-by-pip/
4. Install these python packages: pip install -r requirements_broken.txt . Use this file https://github.com/zapta/ble_stepper_motor_analyzer/blob/main/python/requirements_broken.txt
5. Update the device address in https://github.com/zapta/ble_stepper_motor_analyzer/blob/main/python/bleak_test_broken.py and run it to connect to your device. For me it fails consistently with this log https://pastebin.com/TnWgfWWG .

Two points that may help diagnosing the issue:
i. Uninstalling the ipykernel pip package also makes it to work.
ii. Removing 'import pkg_resources' from the test program makes it to work. (However, I do need it in my real application)

What I Did

It is preferable if an issue contains a Miminal Workable Example.
This will otherwise be one of the first questions you will get as a response.

It is also preferable if that example is not dependent on a specific peripheral device, but can be run and
reproduced with other BLE peripherals as well.

See example above. It's a subset of my full application.

Paste the command(s) you ran and the output.
If there was a crash, please include the traceback here as well.

Logs

Include any relevant logs here.

Logs are essential to understand what is going on behind the scenes.

See https://bleak.readthedocs.io/en/latest/troubleshooting.html for information on how to collect debug logs.

If you receive an OS error (WinError, BleakDBusError, NSError, etc.), Wireshark logs of Bluetooth packets are required to understand the issue!

[dlech]

bleak==0.18.1

Is this still a problem with Bleak v0.19.5? If it is, we will need to see debug logs and Bluetooth packet captures to see what is going on.

[zapta]

Same problem with bleak 0.19.5. Log below. What are debug logs? Something I can enable? How?

The test program doesn't rely on specific device properties. Can you try to reproduce it on your side with whatever BLE device you may have?

/c/projects/ble_stepper_motor_analyzer/repo/python$ cat requirements_broken.txt
async-timeout
bleak
bleak-winrt
numpy
PyQt6
PyQt6-Qt6
PyQt6-sip
pyqtgraph
ipykernel


/c/projects/ble_stepper_motor_analyzer/repo/python$ pip freeze
asttokens==2.1.0
async-timeout==4.0.2
backcall==0.2.0
bleak==0.19.5
bleak-winrt==1.2.0
colorama==0.4.6
debugpy==1.6.3
decorator==5.1.1
entrypoints==0.4
executing==1.2.0
ipykernel==6.17.1
ipython==8.6.0
jedi==0.18.1
jupyter_client==7.4.7
jupyter_core==5.0.0
matplotlib-inline==0.1.6
nest-asyncio==1.5.6
numpy==1.23.5
packaging==21.3
parso==0.8.3
pickleshare==0.7.5
platformdirs==2.5.4
prompt-toolkit==3.0.32
psutil==5.9.4
pure-eval==0.2.2
Pygments==2.13.0
pyparsing==3.0.9
PyQt6==6.4.0
PyQt6-Qt6==6.4.1
PyQt6-sip==13.4.0
pyqtgraph==0.13.1
python-dateutil==2.8.2
pywin32==305
pyzmq==24.0.1
six==1.16.0
stack-data==0.6.1
tornado==6.2
traitlets==5.5.0
wcwidth==0.2.5


/c/projects/ble_stepper_motor_analyzer/repo/python$ ./bleak_test_broken.py
Finding device EE:E7:C3:26:42:83 ...
Device: EE:E7:C3:26:42:83: STP-EEE7C3264283
Creating client...
Client created: BleakClient, EE:E7:C3:26:42:83
Connecting to device...
Traceback (most recent call last):
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 402, in connect
    _, pending = await asyncio.wait(
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\tasks.py", line 384, in wait
    return await _wait(fs, timeout, return_when, loop)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\tasks.py", line 491, in _wait
    await waiter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\projects\ble_stepper_motor_analyzer\repo\python\bleak_test_broken.py", line 34, in <module>
    asyncio.run(main())
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\base_events.py", line 646, in run_until_complete
    return future.result()
  File "C:\projects\ble_stepper_motor_analyzer\repo\python\bleak_test_broken.py", line 24, in main
    await client.connect(timeout=5)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 389, in connect
    async with async_timeout.timeout(timeout):
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\async_timeout\__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\async_timeout\__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
Task exception was never retrieved
future: <Task finished name='Task-3' coro=<BleakClientWinRT.get_services() done, defined at C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py:601> exception=OSError(22, 'The object has been closed', None, -2147483629, None)>
Traceback (most recent call last):
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 659, in get_services
    await FutureLike(service.get_characteristics_async(*args)),
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 1046, in __await__
    return self.result()  # May raise too.
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 988, in result
    pythonapi.PyErr_SetFromWindowsErr(error_code)
OSError: [WinError -2147483629] The object has been closed

[zapta]

I figured out how to enable debug logging. Here it is

/c/projects/ble_stepper_motor_analyzer/repo/python$ export BLEAK_LOGGING=1
/c/projects/ble_stepper_motor_analyzer/repo/python$ ./bleak_test_broken.py
Finding device EE:E7:C3:26:42:83 ...
2022-11-20 05:41:50,686 bleak.backends.winrt.scanner DEBUG: Received 7C:CC:07:FF:88:50: .
2022-11-20 05:41:50,686 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2022-11-20 05:41:50,686 bleak.backends.winrt.scanner DEBUG: Received 7C:CC:07:FF:88:50: .
2022-11-20 05:41:50,796 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: .
2022-11-20 05:41:50,796 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2022-11-20 05:41:50,811 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: BLE Device-7CF311.
2022-11-20 05:41:50,906 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: .
2022-11-20 05:41:50,921 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: BLE Device-7CF311.
2022-11-20 05:41:51,015 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: .
2022-11-20 05:41:51,031 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: BLE Device-7CF311.
2022-11-20 05:41:51,251 bleak.backends.winrt.scanner DEBUG: Received C0:77:8A:A5:D8:0D: .
2022-11-20 05:41:51,755 bleak.backends.winrt.scanner DEBUG: Received 4F:22:33:25:F6:EA: .
2022-11-20 05:41:51,755 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2022-11-20 05:41:51,755 bleak.backends.winrt.scanner DEBUG: Received 4F:22:33:25:F6:EA: .
2022-11-20 05:41:52,084 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: .
2022-11-20 05:41:52,084 bleak.backends.winrt.scanner DEBUG: Received 30:E2:83:7C:F3:11: BLE Device-7CF311.
2022-11-20 05:41:52,585 bleak.backends.winrt.scanner DEBUG: Received EE:E7:C3:26:42:83: .
2022-11-20 05:41:52,585 bleak.backends.winrt.scanner DEBUG: skipping callback, waiting for scan response
2022-11-20 05:41:52,585 bleak.backends.winrt.scanner DEBUG: Received EE:E7:C3:26:42:83: STP-EEE7C3264283.
2022-11-20 05:41:52,601 bleak.backends.winrt.scanner DEBUG: 5 devices found. Watcher status: 3.
Device: EE:E7:C3:26:42:83: STP-EEE7C3264283
Creating client...
Client created: BleakClient, EE:E7:C3:26:42:83
Connecting to device...
2022-11-20 05:41:52,617 bleak.backends.winrt.client DEBUG: Connecting to BLE device @ EE:E7:C3:26:42:83
2022-11-20 05:41:52,742 bleak.backends.winrt.client DEBUG: getting services (service_cache_mode=None, cache_mode=None)...
2022-11-20 05:41:53,104 bleak.backends.winrt.client DEBUG: max_pdu_size_changed_handler: 247
2022-11-20 05:41:53,104 bleak.backends.winrt.client DEBUG: session_status_changed_event_handler: id: <_bleak_winrt_Windows_Devices_Bluetooth.BluetoothDeviceId object at 0x000002B705B9D9B0>, error: BluetoothError.SUCCESS, status: GattSessionStatus.ACTIVE
2022-11-20 05:41:57,740 bleak.backends.winrt.client DEBUG: closing requester
2022-11-20 05:41:57,772 bleak.backends.winrt.client DEBUG: closing session
Traceback (most recent call last):
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 402, in connect
    _, pending = await asyncio.wait(
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\tasks.py", line 384, in wait
    return await _wait(fs, timeout, return_when, loop)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\tasks.py", line 491, in _wait
    await waiter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\projects\ble_stepper_motor_analyzer\repo\python\bleak_test_broken.py", line 34, in <module>
    asyncio.run(main())
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\asyncio\base_events.py", line 646, in run_until_complete
    return future.result()
  File "C:\projects\ble_stepper_motor_analyzer\repo\python\bleak_test_broken.py", line 24, in main
    await client.connect(timeout=5)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 389, in connect
    async with async_timeout.timeout(timeout):
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\async_timeout\__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\async_timeout\__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
Task exception was never retrieved
future: <Task finished name='Task-3' coro=<BleakClientWinRT.get_services() done, defined at C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py:601> exception=OSError(22, 'The object has been closed', None, -2147483629, None)>
Traceback (most recent call last):
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 659, in get_services
    await FutureLike(service.get_characteristics_async(*args)),
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 1046, in __await__
    return self.result()  # May raise too.
  File "C:\Users\user\AppData\Local\Programs\Python\Python310\lib\site-packages\bleak\backends\winrt\client.py", line 988, in result
    pythonapi.PyErr_SetFromWindowsErr(error_code)
OSError: [WinError -2147483629] The object has been closed
/c/projects/ble_stepper_motor_analyzer/repo/python$

[dlech]

We really need the Bluetooth packet logs to see what is going on behind the scenes. Usually, this failure is caused by devices not properly responding to the requests Windows is making.

See https://bleak.readthedocs.io/en/latest/troubleshooting.html#windows-10

[zapta]

Attached is a zip file with packet captures from bleak_test_good.py and bleak_test_broken.py respectively. Please let me know if you need anything else.

packets_captures.zip

[zapta]

... I was also able to replicate the issue with an arbitrary connectable BLE device that advertised in my neighborhood. It's very likely that you will be able to reproduce it on your side without having my specific device.

[dlech]

Thanks for the logs. I don't see any obvious differences between the "good" and "broken" ones. Do you have better luck if you make the timeout longer? I'm not able to reproduce with any of my local devices.

[zapta]

This screenshot shows the last matching row between the good (left) and bad (right). Everything after that is different. Does it help? It seems that the left (good) has a few HCI events that are not on the right side.

https://i.imgur.com/rMlEpBg.png

Also, can you post here your python and OS version and your pip freeze? I will try to reproduce with your configuration.

[dlech]

It just looks like stopping scanning is happening at a different time. All of the same requests and responses are made of the device. The "broken" one disconnects earlier, I assume because of the timeout, which is why I suggested extending the timeout to see if it makes a difference.

[zapta]

I see. Here it is. I increased the timeouts from 5secs to 60secs and behaviors are similar.

packets_60s.zip

Broken log: https://pastebin.com/WGMzR5Jp
Good log: https://pastebin.com/aETu8cPB

[zapta]

... long shot in the dark, can it be related to ipython/ipykernel#824 since the difference between the good and bad tests is the import of pkg_resources ?

[dlech]

since the difference between the good and bad tests

Doh, I missed that part. Can you check asyncio.get_event_loop_policy() for both cases?

[zapta]

I was not sure how to check asyncio.get_event_loop_policy() so used a simple print. Please let me know if I should do anything else.

https://github.com/zapta/ble_stepper_motor_analyzer/blob/main/python/bleak_test_broken.py#L33

https://pastebin.com/nPJuzVxP // log for good and broken tests.

[dlech]

Thanks. I went back and set up an environment like you described and I am able to reproduce the problem. There seems to be some strange side effect that is breaking cancellation in asyncio or winrt. I will keep digging.

[zapta]

Great! Thanks David.

…

On Sun, Nov 20, 2022 at 7:46 PM David Lechner ***@***.***> wrote: Thanks. I went back and set up an environment like you described and I am able to reproduce the problem. There seems to be some strange side effect that is breaking cancellation in asyncio or winrt. I will keep digging. — Reply to this email directly, view it on GitHub <#1132 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAQVMQJV3CJNIPYOURBMHP3WJLWC3ANCNFSM6AAAAAASFQIN2I> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[dlech]

I made some progress in understanding the issue (quite by accident) by printing the thread in the logs with %(threadName)s (note to self, add this to BLEAK_LOGGING) and adding a bunch more debug logs to trace the program flow.

The problem is that it is hanging waiting for get_gatt_services_async() to cancel. When things are working correctly and get_gatt_services_async() is cancelled, then the completed callback of the IAsyncOperation is called on a "dummy" thread. When we get the timeout, this callback is not called until the device disconnects. Then somehow it is called on the main thread when the device is disconnected (thinking about it just now, probably calling close() on the winrt objects does this).

So, if we can figure out what side effect is breaking cancel on get_gatt_services_async(), we can hopefully solve the issue.

[zapta]

I am not familiar with Python runtime but here is a data point that may help. I just tested this on my Win 11 box. 1. Remove all python packages such that pip freeze shows an empty list. 2. Install the packages listed here https://github.com/zapta/ble_stepper_motor_analyzer/blob/main/python/requirements_good.txt . Now bleak_test_broken.py will connect with no errors. 3. Install the package ipykernel (which will pull a bunch of dependencies). Now bleak_test_broken.py will fail again. This suggests that installing ipykernel changes the behavior of the system somehow. May it be related to this ipython/ipykernel#824 ?

…

On Sun, Nov 20, 2022 at 8:36 PM David Lechner ***@***.***> wrote: I made some progress in understanding the issue (quite by accident) by printing the thread in the logs with %(threadName)s (note to self, add this to BLEAK_LOGGING) and adding a bunch more debug logs to trace the program flow. The problem is that it is hanging waiting for get_gatt_services_async() to cancel. When things are working correctly and get_gatt_services_async() is cancelled, then the completed callback of the IAsyncOperation is called on a "dummy" thread. When we get the timeout, this callback is not called until the device disconnects. Then somehow it is called on the main thread when the device is disconnected (thinking about it just now, probably calling close() on the winrt objects does this). So, if we can figure out what side effect is breaking cancel on get_gatt_services_async(), we can solve the issue. — Reply to this email directly, view it on GitHub <#1132 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAQVMQJFYTZXFBH73HLZUPLWJL36NANCNFSM6AAAAAASFQIN2I> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[zapta]

... If you will confirm that its ipykernel related, maybe you can find a relevant issue here https://github.com/ipython/ipykernel/issues

[dlech]

Some other reports of GetGattServicesAsync hanging forever...

• https://stackoverflow.com/questions/63819254/c-ble-why-does-getgattservicesasync-hang-forever-is-there-a-work-around-such
• https://stackoverflow.com/questions/55594814/bug-in-windows-bluetooth-le-getgattservicesasync-method
• Windows 11 WinRT initialization failure OpenBluetoothToolbox/SimpleBLE#31

[dlech]

I think I have narrowed this down to the pywin32 package.

This is a sufficient requirements.txt to reproduce the problem:

bleak
pywin32

[zapta]

That's a very narrow requirements list. Very good. Does it make sense to try different versions to see if it's a regression? E.g. https://pypi.org/project/pywin32/#history

…

On Mon, Nov 21, 2022 at 3:11 PM David Lechner ***@***.***> wrote: I think I have narrowed this down to the pywin32 package. This is a sufficient requirements.txt to reproduce the problem: bleak pywin32 — Reply to this email directly, view it on GitHub <#1132 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAQVMQJP3IZ6OINMU6HUWCTWJP6S7ANCNFSM6AAAAAASFQIN2I> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[dlech]

I ran the test program with python -m trace --trace .\test.py > trace.log to find where something from the pywin32 package was being invoked. It is happening through the vendored copy of appdirs in the pkg_resources package.

https://setuptools.pypa.io/en/latest/pkg_resources.html says:

Use of pkg_resources is discouraged in favor of importlib.resources, importlib.metadata, and their backports (importlib_resources, importlib_metadata). Please consider using those libraries instead of pkg_resources.

So I think the easiest solution is to use avoid using pkg_resources.

But it would be nice if we could detect this problem somehow to help unsuspecting users.

I'm guessing that it would be something similar to OpenBluetoothToolbox/SimpleBLE#31 (comment) where pywin32 is somehow messing with the COM threading configuration.

[zapta]

Thanks David. I think that no using pkg_resources is a reasonable resolution. Thanks! How do you plan to detect it, detecting that pkg_resources is imported somewhere or detecting the condition in causes?

…

On Tue, Nov 22, 2022 at 10:11 AM David Lechner ***@***.***> wrote: I ran the test program with python -m trace --trace .\test.py > trace.log to find where something from the pywin32 package was being invoked. It is happening through the vendored copy of appdirs in the pkg_resources package. https://setuptools.pypa.io/en/latest/pkg_resources.html says: Use of pkg_resources is discouraged in favor of importlib.resources <https://docs.python.org/3/library/importlib.html#module-importlib.resources>, importlib.metadata <https://docs.python.org/3/library/importlib.metadata.html>, and their backports (importlib_resources <https://pypi.org/project/importlib_resources>, importlib_metadata <https://pypi.org/project/importlib_metadata>). Please consider using those libraries instead of pkg_resources. So I think the easiest solution is to use avoid using pkg_resources. But it would be nice if we could detect this problem somehow to help unsuspecting users. I'm guessing that it would be something similar to OpenBluetoothToolbox/SimpleBLE#31 (comment) <OpenBluetoothToolbox/SimpleBLE#31 (comment)> where pywin32 is somehow messing with the COM threading configuration. — Reply to this email directly, view it on GitHub <#1132 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAQVMQJGFD7JZ5RULQ3AJU3WJUED7ANCNFSM6AAAAAASFQIN2I> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[dlech]

The first step would be to call CoGetApartmentType as in the link I gave to see if it is the same problem. If it is, then we can see if we can do something in bleak-winrt to either make it "just work" or raise an error.

[wilddom]

The same thing happens when win32com is imported instead of pgk_resources.