RP2040 intermittent send_and_assert_command test failures

[nateinaction]

F´ Version	v3.4.3
Affected Component	fprime_test_api.send_and_assert_command

---

Problem Description

I am experiencing intermittent integration test failures on an RP2040 board when attempting to assert the no op command.

Showing intermittent nature

This image shows back-to-back runs of the integration test:

Full error output

Uncollapse this section to see the full error output

====================================== test session starts ======================================
platform darwin -- Python 3.9.6, pytest-7.4.3, pluggy-1.3.0
rootdir: /Users/nate/code/github.com/proveskit/fprime-proves
plugins: fprime-gds-3.4.3
collected 1 item

Components/LedBlinker/test/int/led_integration_tests.py F                                 [100%]

=========================================== FAILURES ============================================
________________________________________ test_cmd_no_op _________________________________________

fprime_test_api = <fprime_gds.common.testing_fw.api.IntegrationTestAPI object at 0x1080107c0>

    def test_cmd_no_op(fprime_test_api):
        """Test command CMD_NO_OP

        Test that CMD_NO_OP can be sent and return without and errors
        """
>       fprime_test_api.send_and_assert_command("cmdDisp.CMD_NO_OP")

Components/LedBlinker/test/int/led_integration_tests.py:6:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
fprime-venv/lib/python3.9/site-packages/fprime_gds/common/testing_fw/api.py:425: in send_and_assert_command
    results = self.send_and_assert_event(command, args, events, timeout=timeout)
fprime-venv/lib/python3.9/site-packages/fprime_gds/common/testing_fw/api.py:488: in send_and_assert_event
    return self.assert_event_sequence(events, start=start, timeout=timeout)
fprime-venv/lib/python3.9/site-packages/fprime_gds/common/testing_fw/api.py:925: in assert_event_sequence
    self.__assert_pred("Event sequence", len_pred, len(results), msg)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <fprime_gds.common.testing_fw.api.IntegrationTestAPI object at 0x1080107c0>
name = 'Event sequence assertion', predicate = x == 2, value = 1
msg = 'checks if sequence search found every event', expect = False

    def __assert_pred(self, name, predicate, value, msg="", expect=False):
        """
        Helper to assert that a value satisfies a predicate. Includes arguments to provide more
        descriptive messages in the logs.
        Args:
            name: short name describing the check
            predicate: an instance of predicate to determine if the assert is successful
            value: the object evaluated by the predicate
            msg: a string message to describe what the assert is checking
            expect: a boolean value: True will be have as an expect and not raise an assertion.
        Returns:
            True if the assertion was successful, False otherwise
        """
        name = name + (" expectation" if expect else " assertion")
        pred_msg = predicates.get_descriptive_string(value, predicate)
        if predicate(value):
            ast_msg = f"{name} succeeded: {msg}\nassert {pred_msg}"
            self.__log(ast_msg, TestLogger.GREEN)
            if not expect:
                assert True, pred_msg
            return True
        ast_msg = f"{name} failed: {msg}\nassert {pred_msg}"
        if not expect:
            self.__log(ast_msg, TestLogger.RED)
>           assert False, pred_msg
E           AssertionError: F(1), where F(x) evaluates
E             	 x == 2
E           assert False

fprime-venv/lib/python3.9/site-packages/fprime_gds/common/testing_fw/api.py:1275: AssertionError
------------------------------------- Captured stdout setup -------------------------------------
16:53:51.122811 [Test API] [STARTING CASE] test_cmd_no_op
16:53:51.123157 [Test API] Clearing Test Histories
-------------------------------------- Captured log setup ---------------------------------------
INFO     root:__init__.py:44 Logging system initialized!
------------------------------------- Captured stdout call --------------------------------------
16:53:51.123665 [Test API] Sending Command: cmdDisp.CMD_NO_OP []
16:53:51.124132 [Test API] Beginning a sequence search of 2 items.
16:53:51.124423 [Test API] Sequence search now awaiting for at most 5 s.
16:53:51.142810 [GDS] Received EVR: TB_NONE: 918.918000000s, context=0: cmdDisp.OpCodeDispatched (257) (0(0)-918:918000000) EventSeverity.COMMAND : Opcode 0x100 dispatched to port 1
16:53:51.144468 [GDS] Received EVR: TB_NONE: 918.918000000s, context=0: cmdDisp.NoOpReceived (263) (0(0)-918:918000000) EventSeverity.ACTIVITY_HI : Received a NO-OP command
16:53:51.145083 [GDS] Received EVR: TB_NONE: 918.918000000s, context=0: cmdDisp.OpCodeCompleted (258) (0(0)-918:918000000) EventSeverity.COMMAND : Opcode 0x100 completed
16:53:51.230622 [Test API] Sequence search found the next item: TB_NONE: 918.918000000s, context=0: cmdDisp.OpCodeDispatched EventSeverity.COMMAND : Opcode 0x100 dispatched to port 1
16:53:56.128686 [Test API] Sequence search timed out and ended unsuccessfully.
16:53:56.131095 [Test API] Event sequence assertion failed: checks if sequence search found every event
assert F(1), where F(x) evaluates
	 x == 2
----------------------------------- Captured stdout teardown ------------------------------------
16:53:56.217548 [Test API] Clearing Test Histories
==================================== short test summary info ====================================
FAILED Components/LedBlinker/test/int/led_integration_tests.py::test_cmd_no_op - AssertionError: F(1), where F(x) evaluates
======================================= 1 failed in 5.18s =======================================

Showing GDS responsive

GDS showed new commands even when the test failed. This image shows GDS (no longer running in this screenshot) with command output from several test runs:

Branch and custom deployment where I'm seeing the issue: proveskit/fprime-proves:ngay-led-driver-int-test-issue-1

Things we tried:

• we extended the timeout from default 5 seconds to 10 seconds

Some suspicion was raised around the timestamp showing the beginning of unix epoch time. Or possibly the lack of priority in the arduino scheduler.

Context / Environment

Execute fprime-util version-check and share the output.

Operating System: Darwin
CPU Architecture: arm64
Platform: macOS-15.0.1-arm64-arm-64bit
Python version: 3.9.6
CMake version: 3.30.5
Pip version: 21.2.4
Pip packages:
    fprime-tools==3.4.4
    fprime-gds==3.4.3
    fprime-fpp-*==2.1.0a3

How to Reproduce

1. With an RP2040 board, follow the intro to fprime system testing steps to create a basic integration test which should look like:

def test_cmd_no_op(fprime_test_api):
    """Test command CMD_NO_OP

    Test that CMD_NO_OP can be sent and return without and errors
    """
    fprime_test_api.send_and_assert_command("cmdDisp.CMD_NO_OP")

2. Attempt to run the tests pytest Components/LedBlinker/test/int/led_integration_tests.py adding --dictionary if necessary due to the use of a non-native build toolchain.

Expected Behavior

Consistently passing noop command integration test.

[LeStarch]

@rlcheng I am going to be doing a bit of work in this area, but you may also want to try and reproduce.