search

ARMmbed / mbed-os-experimental-ble-services

Incubator of Bluetooth services
Apache License 2.0
7 stars 8 forks source link

Update BLE testing helpers to non-blocking #48

Closed noonfom closed 3 years ago

noonfom commented 3 years ago

The integration testing utilities contain slow IO operations that can block the event loop, and asyncio code is only effective if the main execution thread contains no blocking code. Basically, blocking code is any code that "holds up" the event loop, i.e. prevents it from smoothly executing awaitables on the loop. For example, placing time.sleep() in an asyncio program is a bad idea since it completely halts the main execution thread.

This PR updates the integration testing utilities to non-blocking. The objective is not to completely remove/hide synchronous code because whether a function is blocking or not depends very much on its use and execution context. Moreover, the process of making code non-blocking often entails running it in a background thread, which comes with some cost. This is how the wait_for_output() function of the Device class is made non-blocking, and aioserial makes extensive use of this approach too.

Reviewers

@pan- @paul-szczepanek-arm

pan- commented 3 years ago

I'm not in sufficient shape to provide an accurate review but I tried it on Mac OS; outside of a docker image. Somehow there's issues to install the cryptography. While applying the fix listed here: https://cryptography.io/en/latest/installation.html . It seems it has an impact on how pyobjc is builded and it makes bleak not usable, it crashes at start with an exception .

Using another environment I build previously, I've been able to run the tests but they are not as reliable as they used to be: 

LinkLoss/host/test_link_loss.py:65 (test_alert_mechanism[alert_level1-High Alert!])
board = <common.serial_device.SerialDevice object at 0x10c96e340>, client = None
alert_level = bytearray(b'\x02'), alert_message = 'High Alert!'

Last, it seems that The aioserial library is not installed as part of the bootstrap.

I will dig further in the issues latter.

noonfom commented 3 years ago

@pan- I found a few bugs in the code:

  1. BoardAllocator.allocate() was not awaiting the new asynchronous flush()
  2. It should also set the client to None if it fails to connect after exceeding the max. number of attempts
  3. The host needs to disconnect in the teardown even if the peripheral disconnects in the test

I also added aioserial to requirements.txt.

Can you please run the tests again? I recommend using the DEBUG trace level.

noonfom commented 3 years ago

@paul-szczepanek-arm Can you please re review?

paul-szczepanek-arm commented 3 years ago

2 Failures

===================================================================================================================================================== test session starts =====================================================================================================================================================
platform linux -- Python 3.8.5, pytest-6.2.2, py-1.10.0, pluggy-0.13.1
rootdir: /home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS, configfile: pytest.ini
plugins: asyncio-0.14.0
collected 8 items                                                                                                                                                                                                                                                                                                             

LinkLoss/host/test_link_loss.py::test_read_alert_level_initial_value 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:13.851   WARNING   Error loading database /home/pawszc02/.local/share/mbedls/platforms.json: Platform Database is out of date; Recreating
08:54:13.857   INFO   Starting runner threads for "LinkLoss"
08:54:14.008   INFO   <--|LinkLoss| Device advertising, please connect
08:54:20.858   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
08:54:22.224   ERROR   A message handler raised an exception: This service is already present in this BleakGATTServiceCollection!.
Traceback (most recent call last):
  File "/home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS/venv/lib/python3.8/site-packages/dbus_next/message_bus.py", line 656, in _process_message
    result = handler(msg)
  File "/home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS/venv/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py", line 986, in _parse_msg
    self.services.add_service(BleakGATTServiceBlueZDBus(obj, path))
  File "/home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS/venv/lib/python3.8/site-packages/bleak/backends/service.py", line 125, in add_service
    raise BleakError(
bleak.exc.BleakError: This service is already present in this BleakGATTServiceCollection!

08:54:22.226   ERROR   A message handler raised an exception: This characteristic is already present in this BleakGATTServiceCollection!.
Traceback (most recent call last):
  File "/home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS/venv/lib/python3.8/site-packages/dbus_next/message_bus.py", line 656, in _process_message
    result = handler(msg)
  File "/home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS/venv/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py", line 995, in _parse_msg
    self.services.add_characteristic(
  File "/home/pawszc02/gh/mbed-os-experimental-ble-services/tests/TESTS/venv/lib/python3.8/site-packages/bleak/backends/service.py", line 160, in add_characteristic
    raise BleakError(
bleak.exc.BleakError: This characteristic is already present in this BleakGATTServiceCollection!

PASSED                                                                                                                                                                                                                                                                                                                  [ 12%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:24.643   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:54:24.646   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_alert_level_write[alert_level0] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:25.653   INFO   Starting runner threads for "LinkLoss"
08:54:25.796   INFO   <--|LinkLoss| Device advertising, please connect
08:54:32.007   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
PASSED                                                                                                                                                                                                                                                                                                                  [ 25%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:35.759   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:54:35.761   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_alert_level_write[alert_level1] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:36.769   INFO   Starting runner threads for "LinkLoss"
08:54:36.917   INFO   <--|LinkLoss| Device advertising, please connect
08:54:43.869   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
PASSED                                                                                                                                                                                                                                                                                                                  [ 37%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:46.677   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:54:46.678   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_alert_level_write[alert_level2] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:47.685   INFO   Starting runner threads for "LinkLoss"
08:54:47.826   INFO   <--|LinkLoss| Device advertising, please connect
08:54:54.038   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
PASSED                                                                                                                                                                                                                                                                                                                  [ 50%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:57.743   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:54:57.744   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_alert_mechanism[alert_level0-Mild Alert!] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:54:58.752   INFO   Starting runner threads for "LinkLoss"
08:54:58.896   INFO   <--|LinkLoss| Device advertising, please connect
08:55:06.057   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
-------------------------------------------------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:06.953   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:55:06.954   INFO   <--|LinkLoss| Mild Alert!
08:55:07.956   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 4 s
08:55:08.957   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 3 s
08:55:09.957   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 2 s
08:55:10.958   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 1 s
08:55:11.954   INFO   <--|LinkLoss| Alert ended
PASSED                                                                                                                                                                                                                                                                                                                  [ 62%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:11.958   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_alert_mechanism[alert_level1-High Alert!] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:12.963   INFO   Starting runner threads for "LinkLoss"
08:55:13.106   INFO   <--|LinkLoss| Device advertising, please connect
08:55:19.850   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
-------------------------------------------------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:20.749   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:55:20.750   INFO   <--|LinkLoss| High Alert!
08:55:21.751   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 4 s
08:55:22.751   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 3 s
08:55:23.752   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 2 s
08:55:24.753   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 1 s
08:55:25.751   INFO   <--|LinkLoss| Alert ended
PASSED                                                                                                                                                                                                                                                                                                                  [ 75%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:25.754   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_disconnection_reconnection[alert_level0-Mild Alert!] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:26.760   INFO   Starting runner threads for "LinkLoss"
08:55:26.906   INFO   <--|LinkLoss| Device advertising, please connect
08:55:34.174   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
-------------------------------------------------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:35.082   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:55:35.083   INFO   <--|LinkLoss| Mild Alert!
FAILED                                                                                                                                                                                                                                                                                                                  [ 87%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:35.179   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_disconnection_reconnection[alert_level1-High Alert!] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:36.091   INFO   Starting runner threads for "LinkLoss"
08:55:36.236   INFO   <--|LinkLoss| Device advertising, please connect
08:55:42.872   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
-------------------------------------------------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:43.759   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:55:43.760   INFO   <--|LinkLoss| High Alert!
FAILED                                                                                                                                                                                                                                                                                                                  [100%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:43.862   INFO   Stopping "LinkLoss" runner...

========================================================================================================================================================== FAILURES ===========================================================================================================================================================
__________________________________________________________________________________________________________________________________ test_disconnection_reconnection[alert_level0-Mild Alert!] __________________________________________________________________________________________________________________________________

board = <common.serial_device.SerialDevice object at 0x7f218d0ec850>, client = <BleakClientBlueZDBus, D8:E2:FB:7F:0A:A8, <bleak.backends.bluezdbus.client.BleakClientBlueZDBus object at 0x7f218d0eab50>>, alert_level = bytearray(b'\x01'), alert_message = 'Mild Alert!'

    @pytest.mark.asyncio
    @pytest.mark.parametrize(
        "alert_level,alert_message", [(MILD_ALERT, "Mild Alert!"), (HIGH_ALERT, "High Alert!")])
    async def test_disconnection_reconnection(board, client, alert_level, alert_message):
        await client.write_gatt_char(UUID_ALERT_LEVEL_CHAR, alert_level)
        await client.write_gatt_char(UUID_DISCONNECTION_REASON_CHAR, CONNECTION_TIMEOUT)
        await board.wait_for_output(alert_message, timeout=10)
>       await client.connect()

LinkLoss/host/test_link_loss.py:82: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <BleakClientBlueZDBus, D8:E2:FB:7F:0A:A8, <bleak.backends.bluezdbus.client.BleakClientBlueZDBus object at 0x7f218d0eab50>>, kwargs = {}

    async def connect(self, **kwargs) -> bool:
        """Connect to the specified GATT server.

        Keyword Args:
            timeout (float): Timeout for required ``BleakScanner.find_device_by_address`` call. Defaults to 10.0.

        Returns:
            Boolean representing connection status.

        Raises:
            BleakError: If the device is already connected or if the device could not be found.
            BleakDBusError: If there was a D-Bus error
            asyncio.TimeoutError: If the connection timed out
        """
        logger.debug(f"Connecting to device @ {self.address} with {self._adapter}")

        if self.is_connected:
>           raise BleakError("Client is already connected")
E           bleak.exc.BleakError: Client is already connected

venv/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py:120: BleakError
----------------------------------------------------------------------------------------------------------------------------------------------------- Captured log setup ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:26.760   INFO   Starting runner threads for "LinkLoss"
08:55:26.906   INFO   <--|LinkLoss| Device advertising, please connect
08:55:34.174   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
------------------------------------------------------------------------------------------------------------------------------------------------------ Captured log call ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:35.082   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:55:35.083   INFO   <--|LinkLoss| Mild Alert!
---------------------------------------------------------------------------------------------------------------------------------------------------- Captured log teardown ----------------------------------------------------------------------------------------------------------------------------------------------------
08:55:35.179   INFO   Stopping "LinkLoss" runner...
__________________________________________________________________________________________________________________________________ test_disconnection_reconnection[alert_level1-High Alert!] __________________________________________________________________________________________________________________________________

board = <common.serial_device.SerialDevice object at 0x7f218e1915b0>, client = <BleakClientBlueZDBus, D8:E2:FB:7F:0A:A8, <bleak.backends.bluezdbus.client.BleakClientBlueZDBus object at 0x7f218e19a760>>, alert_level = bytearray(b'\x02'), alert_message = 'High Alert!'

    @pytest.mark.asyncio
    @pytest.mark.parametrize(
        "alert_level,alert_message", [(MILD_ALERT, "Mild Alert!"), (HIGH_ALERT, "High Alert!")])
    async def test_disconnection_reconnection(board, client, alert_level, alert_message):
        await client.write_gatt_char(UUID_ALERT_LEVEL_CHAR, alert_level)
        await client.write_gatt_char(UUID_DISCONNECTION_REASON_CHAR, CONNECTION_TIMEOUT)
        await board.wait_for_output(alert_message, timeout=10)
>       await client.connect()

LinkLoss/host/test_link_loss.py:82: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <BleakClientBlueZDBus, D8:E2:FB:7F:0A:A8, <bleak.backends.bluezdbus.client.BleakClientBlueZDBus object at 0x7f218e19a760>>, kwargs = {}

    async def connect(self, **kwargs) -> bool:
        """Connect to the specified GATT server.

        Keyword Args:
            timeout (float): Timeout for required ``BleakScanner.find_device_by_address`` call. Defaults to 10.0.

        Returns:
            Boolean representing connection status.

        Raises:
            BleakError: If the device is already connected or if the device could not be found.
            BleakDBusError: If there was a D-Bus error
            asyncio.TimeoutError: If the connection timed out
        """
        logger.debug(f"Connecting to device @ {self.address} with {self._adapter}")

        if self.is_connected:
>           raise BleakError("Client is already connected")
E           bleak.exc.BleakError: Client is already connected

venv/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py:120: BleakError
----------------------------------------------------------------------------------------------------------------------------------------------------- Captured log setup ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:36.091   INFO   Starting runner threads for "LinkLoss"
08:55:36.236   INFO   <--|LinkLoss| Device advertising, please connect
08:55:42.872   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
------------------------------------------------------------------------------------------------------------------------------------------------------ Captured log call ------------------------------------------------------------------------------------------------------------------------------------------------------
08:55:43.759   INFO   <--|LinkLoss| Client disconnected, restarting advertising
08:55:43.760   INFO   <--|LinkLoss| High Alert!
---------------------------------------------------------------------------------------------------------------------------------------------------- Captured log teardown ----------------------------------------------------------------------------------------------------------------------------------------------------
08:55:43.862   INFO   Stopping "LinkLoss" runner...
=================================================================================================================================================== short test summary info ===================================================================================================================================================
FAILED LinkLoss/host/test_link_loss.py::test_disconnection_reconnection[alert_level0-Mild Alert!] - bleak.exc.BleakError: Client is already connected
FAILED LinkLoss/host/test_link_loss.py::test_disconnection_reconnection[alert_level1-High Alert!] - bleak.exc.BleakError: Client is already connected
=========================================================================================================================================== 2 failed, 6 passed in 90.93s (0:01:30) ============================================================================================================================================
noonfom commented 3 years ago

@paul-szczepanek-arm Thanks for the re review. Unfortunately, I can't debug this as my Linux virtual machine doesn't recognize LE devices using bleak or bluetoothctl. However, I'll try it with a BT dongle and report back.

pan- commented 3 years ago

@paul-szczepanek-arm Can you verify it works for you ?

noonfom commented 3 years ago

@paul-szczepanek-arm Can you verify it works for you ?

That would be great. I'll check it on Windows.

noonfom commented 3 years ago

Update: works on Windows w/bleak 0.10.0, albeit poorly. \-> If the host connects, the test will pass.

paul-szczepanek-arm commented 3 years ago

It works with errors:

12:47:11.757   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_disconnection_reconnection[alert_level0-Mild Alert!] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
12:47:12.763   INFO   Starting runner threads for "LinkLoss"
12:47:12.910   INFO   <--|LinkLoss| Device advertising, please connect
12:47:19.860   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
-------------------------------------------------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------------------------------------------------
12:47:20.743   INFO   <--|LinkLoss| Client disconnected, restarting advertising
12:47:20.744   INFO   <--|LinkLoss| Mild Alert!
12:47:20.842   ERROR   Could not remove rule 1 (PropChanged): Connection was closed cleanly.
12:47:20.843   ERROR   Attempt to disconnect system bus failed: 'NoneType' object has no attribute 'disconnect'
12:47:21.748   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 9 s
12:47:22.748   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 8 s
12:47:23.749   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 7 s
12:47:24.750   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 6 s
12:47:25.746   INFO   <--|LinkLoss| Alert ended
PASSED                                                                                                                                                                                                                                                                                                                  [ 87%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
12:47:25.749   INFO   Stopping "LinkLoss" runner...

LinkLoss/host/test_link_loss.py::test_disconnection_reconnection[alert_level1-High Alert!] 
------------------------------------------------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------------------------------------------------
12:47:26.756   INFO   Starting runner threads for "LinkLoss"
12:47:26.900   INFO   <--|LinkLoss| Device advertising, please connect
12:47:33.850   INFO   <--|LinkLoss| Client connected, you may now subscribe to updates
-------------------------------------------------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------------------------------------------------
12:47:34.734   INFO   <--|LinkLoss| Client disconnected, restarting advertising
12:47:34.735   INFO   <--|LinkLoss| High Alert!
12:47:34.830   ERROR   Could not remove rule 1 (PropChanged): Connection was closed cleanly.
12:47:34.830   ERROR   Attempt to disconnect system bus failed: 'NoneType' object has no attribute 'disconnect'
12:47:35.748   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 9 s
12:47:36.749   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 8 s
12:47:37.750   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 7 s
12:47:38.750   INFO   LinkLoss: Waiting for "Alert ended" string... Timeout in 6 s
12:47:39.736   INFO   <--|LinkLoss| Alert ended
PASSED                                                                                                                                                                                                                                                                                                                  [100%]
------------------------------------------------------------------------------------------------------------------------------------------------------ live log teardown ------------------------------------------------------------------------------------------------------------------------------------------------------
12:47:39.739   INFO   Stopping "LinkLoss" runner...

also the activate script in the scripts directory has the wrong path so doesn't work

noonfom commented 3 years ago

@paul-szczepanek-arm Hmm, I don't get those errors. Can you please paste the output of the following from inside venv:

python --version; pip list

Can you elaborate on the issue with activate.sh? It can be sourced from anywhere, but try the following from root:

source ./scripts/activate.sh
paul-szczepanek-arm commented 3 years ago

Python 3.8.5 Package Version

aioserial 1.3.0 appdirs 1.4.4 asn1ate 0.6.0 atomicwrites 1.4.0 attrs 20.3.0 Automat 20.2.0 beautifulsoup4 4.6.3 bleak 0.10.0 cbor 1.0.0 certifi 2020.12.5 cffi 1.14.5 chardet 4.0.0 click 7.1.2 cmsis-pack-manager 0.2.10 colorama 0.3.9 constantly 15.1.0 cryptography 2.9.2 ecdsa 0.16.1 fasteners 0.16 future 0.18.2 gitdb 4.0.7 GitPython 3.1.14 hyperlink 21.0.0 icetea 1.2.4 idna 2.7 importlib-metadata 3.10.0 incremental 21.3.0 iniconfig 1.1.1 intelhex 2.3.0 Jinja2 2.10.3 jsonmerge 1.8.0 jsonschema 2.6.0 junit-xml 1.8 lockfile 0.12.2 Mako 1.1.4 manifest-tool 1.5.2 Markdown 3.3.4 MarkupSafe 1.1.1 mbed-cli 1.10.5 mbed-cloud-sdk 2.0.8 mbed-flasher 0.10.1 mbed-greentea 1.8.4 mbed-host-tests 1.8.4 mbed-ls 1.8.4 mbed-os-tools 1.8.4 mbed-tools 7.8.0 milksnake 0.1.5 packaging 20.9 pdoc3 0.9.2 pip 21.0.1 pluggy 0.13.1 prettytable 0.7.2 protobuf 3.5.2.post1 psutil 5.6.6 py 1.10.0 pyasn1 0.2.3 pycparser 2.20 pycryptodome 3.10.1 pyelftools 0.25 pyparsing 2.4.7 pyserial 3.4 pytest 6.2.2 pytest-asyncio 0.14.0 python-dateutil 2.8.1 python-dotenv 0.17.0 pyudev 0.22.0 pyusb 1.1.1 PyYAML 4.2b1 requests 2.25.1 semver 2.13.0 setuptools 54.0.0 six 1.12.0 smmap 4.0.0 soupsieve 2.2.1 tabulate 0.8.9 toml 0.10.2 tqdm 4.60.0 Twisted 21.2.0 txdbus 1.1.2 typing-extensions 3.7.4.3 urllib3 1.26.4 wcwidth 0.2.5 wheel 0.36.2 yattag 1.14.0 zipp 3.4.1 zope.interface 5.3.0

paul-szczepanek-arm commented 3 years ago

yeah, script only works if sourced, not when executed

noonfom commented 3 years ago

@paul-szczepanek-arm Thanks. We seem to have the same environments.

It looks like a D-Bus error. Can you set the log level to DEBUG and rerun the test? Unfortunately, our parser doesn't have an argument for this, so you'll have to set it in pytest.ini.

Please paste the log again.

noonfom commented 3 years ago

@paul-szczepanek-arm I can see the errors now. They go missing at a higher log level (i.e. DEBUG)

Adding WIP... we need to wait for the disconnection clean-up to finish before proceeding.

Update: I applied these changes in 14455c511781f896946eb3d368534639ac16a468