RP2040 intermittent send_and_assert_command test failures


*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 = 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 = 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

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")

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.

nasa / fprime