flaky test: test_fault_injection_node.test.py

[xmfcx]

Checklist

• I've read the contribution guidelines.
• I've searched other issues and no duplicate issues were found.
• I'm convinced that this is not my fault but a bug.

Description

https://github.com/autowarefoundation/autoware.universe/actions/runs/9743179438/job/26886066688#step:16:11812

It has been passing successfully for a long while but it failed randomly here.

FAIL: test_receive_multiple_message_simultaneously (fault_injection.TestFaultInjectionLink)

2: Traceback (most recent call last):
2:   File "/__w/autoware.universe/autoware.universe/simulator/fault_injection/test/test_fault_injection_node.test.py", line 175, in test_receive_multiple_message_simultaneously
2:     self.assertEqual(stat.level, DiagnosticStatus.ERROR)
2: AssertionError: b'\x00' != b'\x02'

Failure line:
https://github.com/autowarefoundation/autoware.universe/blob/c1dbd5bf938fbdd9e91505cc5344020fbf4ea752/simulator/fault_injection/test/test_fault_injection_node.test.py#L175

History:

cc. @KeisukeShima @TomohitoAndo

Expected behavior

Test should have passed.

Actual behavior

But it failed.

Steps to reproduce

colcon test --event-handlers console_cohesion+ --mixin coverage-pytest --packages-select fault_injection

This command passed on my machine and also passed in CI many times.

Update: See this comment: #7772 (comment)

But it failed in this one instance here.

Versions

No response

Possible causes

Maybe we can increase evaluation_time from 0.5s to 2s to compensate for slow test environment.

https://github.com/autowarefoundation/autoware.universe/blob/c1dbd5bf938fbdd9e91505cc5344020fbf4ea752/simulator/fault_injection/test/test_fault_injection_node.test.py#L70

Additional context

No response

[xmfcx]

Ok I can reproduce it too:

sudo apt install stress

Terminal 1

stress -c 24 -m 200

(I have 12c24t CPU and 64GB RAM, adjust to your system)

Terminal 2

colcon test --event-handlers console_cohesion+ --mixin coverage-pytest --packages-select fault_injection

🖱️Click here to expand🔛

mfc@mfc-leo:~/projects/autoware$ colcon test --event-handlers console_cohesion+ --mixin coverage-pytest --packages-select fault_injection
Starting >>> fault_injection
[37.076s] WARNING:colcon.colcon_ros.prefix_path.ament:The path '/home/mfc/projects/autoware/install/lidar_centerpoint_tvm' in the environment variable AMENT_PREFIX_PATH doesn't exist
[37.155s] WARNING:colcon.colcon_ros.prefix_path.catkin:The path '/home/mfc/projects/autoware/install/lidar_centerpoint_tvm' in the environment variable CMAKE_PREFIX_PATH doesn't exist
[Processing: fault_injection]                       
--- output: fault_injection                          
UpdateCTestConfiguration  from :/home/mfc/projects/autoware/build/fault_injection/CTestConfiguration.ini
Parse Config file:/home/mfc/projects/autoware/build/fault_injection/CTestConfiguration.ini
   Site: mfc-leo
   Build name: (empty)
 Add coverage exclude regular expressions.
Create new tag: 20240701-1226 - Experimental
UpdateCTestConfiguration  from :/home/mfc/projects/autoware/build/fault_injection/CTestConfiguration.ini
Parse Config file:/home/mfc/projects/autoware/build/fault_injection/CTestConfiguration.ini
Test project /home/mfc/projects/autoware/build/fault_injection
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 1
    Start 1: test_fault_injection_node_component

1: Test command: /usr/bin/python3.10 "-u" "/opt/ros/humble/share/ament_cmake_ros/cmake/run_test_isolated.py" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_node_component.gtest.xml" "--package-name" "fault_injection" "--output-file" "/home/mfc/projects/autoware/build/fault_injection/ament_cmake_gtest/test_fault_injection_node_component.txt" "--command" "/home/mfc/projects/autoware/build/fault_injection/test_fault_injection_node_component" "--gtest_output=xml:/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_node_component.gtest.xml"
1: Test timeout computed to be: 60
1: Running with ROS_DOMAIN_ID 1
1: -- run_test.py: invoking following command in '/home/mfc/projects/autoware/build/fault_injection':
1:  - /home/mfc/projects/autoware/build/fault_injection/test_fault_injection_node_component --gtest_output=xml:/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_node_component.gtest.xml
1: [==========] Running 2 tests from 1 test suite.
1: [----------] Global test environment set-up.
1: [----------] 2 tests from TestDiagnosticStorage
1: [ RUN      ] TestDiagnosticStorage.call_update_with_correct_key
1: [       OK ] TestDiagnosticStorage.call_update_with_correct_key (0 ms)
1: [ RUN      ] TestDiagnosticStorage.raise_exception_with_wrong_key
1: [       OK ] TestDiagnosticStorage.raise_exception_with_wrong_key (0 ms)
1: [----------] 2 tests from TestDiagnosticStorage (0 ms total)
1: 
1: [----------] Global test environment tear-down
1: [==========] 2 tests from 1 test suite ran. (1 ms total)
1: [  PASSED  ] 2 tests.
1: -- run_test.py: return code 0
1: -- run_test.py: inject classname prefix into gtest result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_node_component.gtest.xml'
1: -- run_test.py: verify result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_node_component.gtest.xml'
1/6 Test #1: test_fault_injection_node_component ...   Passed    5.34 sec
test 2
    Start 2: test_fault_injection_launch_test

2: Test command: /usr/bin/python3.10 "-u" "/home/mfc/projects/autoware/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_launch_test.xunit.xml" "--package-name" "fault_injection" "--output-file" "/home/mfc/projects/autoware/build/fault_injection/launch_test/test_fault_injection_launch_test.txt" "--command" "/usr/bin/python3" "-m" "launch_testing.launch_test" "/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/test/test_fault_injection_node.test.py" "--junit-xml=/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_launch_test.xunit.xml" "--package-name=fault_injection"
2: Test timeout computed to be: 60
2: -- run_test.py: invoking following command in '/home/mfc/projects/autoware/build/fault_injection':
2:  - /usr/bin/python3 -m launch_testing.launch_test /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/test/test_fault_injection_node.test.py --junit-xml=/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_launch_test.xunit.xml --package-name=fault_injection
2: [INFO] [launch]: All log files can be found below /home/mfc/.ros/log/2024-07-01-15-26-50-491627-mfc-leo-3958620
2: [INFO] [launch]: Default logging verbosity is set to INFO
2: test_node_link (fault_injection.TestFaultInjectionLink)
2: Test node linkage. ... [INFO] [fault_injection_node-1]: process started with pid [3959103]
2: [fault_injection_node-1] [DEBUG 1719836817.466051133] [fault_injection]: Parameter: cpu_load_average, value: : CPU Load Average (read_event_diag_list() at /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/src/fault_injection_node/fault_injection_node.cpp:99)
2: [fault_injection_node-1] [DEBUG 1719836817.468677231] [fault_injection]: Parameter: cpu_temperature, value: : CPU Temperature (read_event_diag_list() at /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/src/fault_injection_node/fault_injection_node.cpp:99)
2: [fault_injection_node-1] [DEBUG 1719836817.469807464] [fault_injection]: Parameter: cpu_usage, value: : CPU Usage (read_event_diag_list() at /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/src/fault_injection_node/fault_injection_node.cpp:99)
2: FAIL
2: test_receive_multiple_message_simultaneously (fault_injection.TestFaultInjectionLink)
2: Test for https://github.com/autowarefoundation/autoware.universe/pull/4042. ... [fault_injection_node-1] [DEBUG 1719836818.216154680] [fault_injection]: Received data: stamp:
2: [fault_injection_node-1]   sec: 0
2: [fault_injection_node-1]   nanosec: 0
2: [fault_injection_node-1] fault_injection_events:
2: [fault_injection_node-1] -
2: [fault_injection_node-1]   level: 2
2: [fault_injection_node-1]   name: "cpu_temperature"
2: [fault_injection_node-1]  (on_simulation_events() at /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/src/fault_injection_node/fault_injection_node.cpp:67)
2: [fault_injection_node-1] [DEBUG 1719836818.216765752] [fault_injection]: Received data: stamp:
2: [fault_injection_node-1]   sec: 0
2: [fault_injection_node-1]   nanosec: 0
2: [fault_injection_node-1] fault_injection_events:
2: [fault_injection_node-1] -
2: [fault_injection_node-1]   level: 2
2: [fault_injection_node-1]   name: "cpu_usage"
2: [fault_injection_node-1]  (on_simulation_events() at /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/src/fault_injection_node/fault_injection_node.cpp:67)
2: ok
2: 
2: ======================================================================
2: FAIL: test_node_link (fault_injection.TestFaultInjectionLink)
2: Test node linkage.
2: ----------------------------------------------------------------------
2: Traceback (most recent call last):
2:   File "/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/test/test_fault_injection_node.test.py", line 128, in test_node_link
2:     self.assertGreaterEqual(self.get_num_valid_data(msg_buffer, DiagnosticStatus.ERROR), 1)
2: AssertionError: 0 not greater than or equal to 1
2: 
2: ----------------------------------------------------------------------
2: Ran 2 tests in 2.715s
2: 
2: FAILED (failures=1)
2: [INFO] [fault_injection_node-1]: sending signal 'SIGINT' to process[fault_injection_node-1]
2: [fault_injection_node-1] [INFO 1719836818.978081363] [rclcpp]: signal_handler(signum=2) (signal_handler() at ./src/rclcpp/signal_handler.cpp:71)
2: [INFO] [fault_injection_node-1]: process has finished cleanly [pid 3959103]
2: test_exit_code (fault_injection.TestProcessOutput)
2: Test process exit code. ... ok
2: 
2: ----------------------------------------------------------------------
2: Ran 1 test in 0.001s
2: 
2: OK
2: -- run_test.py: return code 1
2: -- run_test.py: verify result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/test_fault_injection_launch_test.xunit.xml'
2/6 Test #2: test_fault_injection_launch_test ......***Failed   14.91 sec
test 3
    Start 3: copyright

3: Test command: /usr/bin/python3.10 "-u" "/home/mfc/projects/autoware/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/copyright.xunit.xml" "--package-name" "fault_injection" "--output-file" "/home/mfc/projects/autoware/build/fault_injection/ament_copyright/copyright.txt" "--command" "/opt/ros/humble/bin/ament_copyright" "--xunit-file" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/copyright.xunit.xml"
3: Test timeout computed to be: 200
3: -- run_test.py: invoking following command in '/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection':
3:  - /opt/ros/humble/bin/ament_copyright --xunit-file /home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/copyright.xunit.xml
3: No problems found, checked 7 files
3: -- run_test.py: return code 0
3: -- run_test.py: verify result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/copyright.xunit.xml'
3/6 Test #3: copyright .............................   Passed   10.76 sec
test 4
    Start 4: cppcheck

4: Test command: /usr/bin/python3.10 "-u" "/home/mfc/projects/autoware/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/cppcheck.xunit.xml" "--package-name" "fault_injection" "--output-file" "/home/mfc/projects/autoware/build/fault_injection/ament_cppcheck/cppcheck.txt" "--command" "/opt/ros/humble/bin/ament_cppcheck" "--xunit-file" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/cppcheck.xunit.xml" "--include_dirs" "/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/include"
4: Test timeout computed to be: 300
4: -- run_test.py: invoking following command in '/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection':
4:  - /opt/ros/humble/bin/ament_cppcheck --xunit-file /home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/cppcheck.xunit.xml --include_dirs /home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection/include
4: cppcheck 2.7 has known performance issues and therefore will not be used, set the AMENT_CPPCHECK_ALLOW_SLOW_VERSIONS environment variable to override this.
4: -- run_test.py: return code 0
4: -- run_test.py: verify result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/cppcheck.xunit.xml'
4/6 Test #4: cppcheck ..............................   Passed    5.31 sec
test 5
    Start 5: lint_cmake

5: Test command: /usr/bin/python3.10 "-u" "/home/mfc/projects/autoware/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/lint_cmake.xunit.xml" "--package-name" "fault_injection" "--output-file" "/home/mfc/projects/autoware/build/fault_injection/ament_lint_cmake/lint_cmake.txt" "--command" "/opt/ros/humble/bin/ament_lint_cmake" "--xunit-file" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/lint_cmake.xunit.xml"
5: Test timeout computed to be: 60
5: -- run_test.py: invoking following command in '/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection':
5:  - /opt/ros/humble/bin/ament_lint_cmake --xunit-file /home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/lint_cmake.xunit.xml
5: 
5: No problems found
5: -- run_test.py: return code 0
5: -- run_test.py: verify result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/lint_cmake.xunit.xml'
5/6 Test #5: lint_cmake ............................   Passed    4.44 sec
test 6
    Start 6: xmllint

6: Test command: /usr/bin/python3.10 "-u" "/home/mfc/projects/autoware/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/xmllint.xunit.xml" "--package-name" "fault_injection" "--output-file" "/home/mfc/projects/autoware/build/fault_injection/ament_xmllint/xmllint.txt" "--command" "/opt/ros/humble/bin/ament_xmllint" "--xunit-file" "/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/xmllint.xunit.xml"
6: Test timeout computed to be: 60
6: -- run_test.py: invoking following command in '/home/mfc/projects/autoware/src/universe/autoware.universe/simulator/fault_injection':
6:  - /opt/ros/humble/bin/ament_xmllint --xunit-file /home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/xmllint.xunit.xml
6: File 'package.xml' is valid
6: 
6: File 'launch/fault_injection.launch.xml' is valid
6: 
6: File 'test/launch/test_fault_injection.launch.xml' is valid
6: 
6: No problems found
6: -- run_test.py: return code 0
6: -- run_test.py: verify result file '/home/mfc/projects/autoware/build/fault_injection/test_results/fault_injection/xmllint.xunit.xml'
6/6 Test #6: xmllint ...............................   Passed    8.39 sec

83% tests passed, 1 tests failed out of 6

Label Time Summary:
copyright      =  10.76 sec*proc (1 test)
cppcheck       =   5.31 sec*proc (1 test)
gtest          =   5.34 sec*proc (1 test)
launch_test    =  14.91 sec*proc (1 test)
lint_cmake     =   4.44 sec*proc (1 test)
linter         =  28.90 sec*proc (4 tests)
xmllint        =   8.39 sec*proc (1 test)

Total Test time (real) =  49.23 sec

The following tests FAILED:
	  2 - test_fault_injection_launch_test (Failed)
Errors while running CTest
Output from these tests are in: /home/mfc/projects/autoware/build/fault_injection/Testing/Temporary/LastTest.log
Use "--rerun-failed --output-on-failure" to re-run the failed cases verbosely.
---
--- stderr: fault_injection
Errors while running CTest
Output from these tests are in: /home/mfc/projects/autoware/build/fault_injection/Testing/Temporary/LastTest.log
Use "--rerun-failed --output-on-failure" to re-run the failed cases verbosely.
---
Finished <<< fault_injection [57.6s]	[ with test failures ]

Summary: 1 package finished [1min 32s]
  1 package had stderr output: fault_injection
  1 package had test failures: fault_injection

[KeisukeShima]

@xmfcx Thanks for your cooperate 👍
In the short term, extending evaluation time is a good idea. However, the root cause of the problem is the lack of resources in the testing environment. I have always struggled with that.
Whether it is Flaky test or Flaky testing environment, our work is never done until we solve it.

[xmfcx]

@KeisukeShima the build-and-test jobs (not differential) are running on:

Either on:

• EC2 c6a.xlarge with 4vCPU 8GiB RAM
• leo-copper machine with 4c8t CPU and 32GB RAM

On this failure instance, it was running on leo-copper machine

And if we look into the colcon test command, we can see it is being called with sequential flag:
https://github.com/autowarefoundation/autoware-github-actions/blob/a1960b03b1d3f5c4320ec1d4e7916ffac437f4f1/colcon-test/action.yaml#L89-L93

colcon test --event-handlers console_cohesion+ \
  --mixin coverage-pytest \
  --packages-above ${{ inputs.target-packages }} \
  --executor sequential \
  --return-code-on-test-failure

However, the root cause of the problem is the lack of resources in the testing environment.

What would be your suggestion for improvements? Do you think for example:

• leo-copper is not strong enough?
• If not, what kind of machine would you suggest?

We already run these sequentially and I think machines are strong enough.
And by design of github-actions-runner, they can only perform one job at a time.

[KeisukeShima]

@xmfcx Thanks for the explanation. I would like to investigate as the situation seems to have changed from before.

[stale]

This pull request has been automatically marked as stale because it has not had recent activity.