:farmer: rmw_zenoh_cpp tests failing for nightly_win/win2025_rep/rel by timeout

[miguelgonrod]

Generated by Generative AI

No response

Operating System:

Windows 10 and Windows 11

ROS version or commit hash:

rolling

RMW implementation (if applicable):

rmw_zenoh_cpp

RMW Configuration (if applicable):

No response

Client library (if applicable):

rclcpp

'ros2 doctor --report' output

No response

Steps to reproduce issue

1. Go to any of this jobs:
   • https://ci.ros2.org/view/nightly/job/nightly_win-2025_repeated
   • https://ci.ros2.org/view/nightly/job/nightly_win-2025_release
   • https://ci.ros2.org/view/nightly/job/nightly_win_rel
   • https://ci.ros2.org/view/nightly/job/nightly_win_rep
2. Build the job
3. See the tests failing

Expected behavior

To build without tests failures

Actual behavior

Build with lots of tests failing. Lots of them are with rmw_zenoh

Additional information

Failing tests

• projectroot.test_action_communication__rmw_zenoh_cpp
• projectroot.test_publisher__rmw_zenoh_cpp
• projectroot.test_subscription__rmw_zenoh_cpp
• rcl_action.test_action_communication__rmw_zenoh_cpp.gtest.missing_result
• test_rmw_implementation.test_publisher__rmw_zenoh_cpp.gtest.missing_result
• test_rmw_implementation.test_subscription__rmw_zenoh_cpp.gtest.missing_result

Log Output

53: [  SKIPPED ] TestSubscriptionUseLoan.rmw_return_loaned_message_from_subscription (4010 ms)
53: [----------] 3 tests from TestSubscriptionUseLoan (12030 ms total)
53: 
53: [----------] 6 tests from TestContentFilterSubscriptionUse
53: [ RUN      ] TestContentFilterSubscriptionUse.get_content_filter
53: �[2m2025-12-10T08:03:05.150436Z�[0m �[33m WARN�[0m ThreadId(06) �[2mzenoh::net::runtime::orchestrator�[0m�[2m:�[0m Scouting delay elapsed before start conditions are met.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: [       OK ] TestContentFilterSubscriptionUse.get_content_filter (4011 ms)
53: [ RUN      ] TestContentFilterSubscriptionUse.set_content_filter
53: �[2m2025-12-10T08:03:09.160456Z�[0m �[33m WARN�[0m ThreadId(06) �[2mzenoh::net::runtime::orchestrator�[0m�[2m:�[0m Scouting delay elapsed before start conditions are met.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: [       OK ] TestContentFilterSubscriptionUse.set_content_filter (4008 ms)
53: [ RUN      ] TestContentFilterSubscriptionUse.content_filter_get_begin
53: �[2m2025-12-10T08:03:13.169426Z�[0m �[33m WARN�[0m ThreadId(06) �[2mzenoh::net::runtime::orchestrator�[0m�[2m:�[0m Scouting delay elapsed before start conditions are met.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: [       OK ] TestContentFilterSubscriptionUse.content_filter_get_begin (4008 ms)
53: [ RUN      ] TestContentFilterSubscriptionUse.content_filter_get_later
53: �[2m2025-12-10T08:03:17.177839Z�[0m �[33m WARN�[0m ThreadId(06) �[2mzenoh::net::runtime::orchestrator�[0m�[2m:�[0m Scouting delay elapsed before start conditions are met.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: [       OK ] TestContentFilterSubscriptionUse.content_filter_get_later (4008 ms)
53: [ RUN      ] TestContentFilterSubscriptionUse.content_filter_reset
53: �[2m2025-12-10T08:03:21.186435Z�[0m �[33m WARN�[0m ThreadId(06) �[2mzenoh::net::runtime::orchestrator�[0m�[2m:�[0m Scouting delay elapsed before start conditions are met.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
53: logging system isn't initialized: call to rcutils_logging_console_output_handler failed.
    Test #53: test_subscription__rmw_zenoh_cpp ........................***Timeout 120.00 sec

Flakyness last 15 days

job_name	last_fail	first_fail	build_count	failure_count	failure_percentage
nightly_win_rep	2025-12-10	2025-12-07	14	4	28.57
nightly_win_rel	2025-12-10	2025-12-05	16	6	37.5

CC: @Crola1702 @claraberendsen

[JEnoch]

In each log I see that ZENOH_CONFIG_OVERRIDE=scouting/multicast/enabled=true is defined.
I think that's the same issue than discussed in ros2/ros_buildfarm_config#348 .

Multicast scouting should be disabled to avoid cross-tests interferences, which could be the cause those tests failures.
But the Zenoh router shall also be started for the tests to succeed.

CC: @cottsay @Yadunund

[claraberendsen]

I talked about this with @cottsay and it's not clear to us that this is due to isolation issues (see his comment here: ros2/ros_buildfarm_config#348 (comment)). There are slight differences on what we are running on build.ros2 and ci.ros2.

I took a look a drift between when it started and it points to this PR: #834. I cannot point specifically to what out of all the changes introduced by the zenoh version bump is causing this, could use your help here @JEnoch.

Testing before that change to validate:

[JEnoch]

Looking at the logs I see most of the tests actually are showing [ OK ]
For instance: https://ci.ros2.org/view/nightly/job/nightly_win_rel/3648/testReport/junit/(root)/projectroot/test_publisher__rmw_zenoh_cpp/

Is the WARN ... Scouting delay elapsed before start conditions are met log considered as a failure ?

Otherwise, I would need debug logs to analyse the issue. How could I trigger the tests adding a RUST_LOG=debug environment variable ?

[claraberendsen]

Let me take a look at how we can pass that env variable into CI.
The error that is marked is that the test produce no output and there are a number of logs pointing to the Zenoh router not being initialized.

Looking at the same job you referenced :
testReport/junit/(root)/projectroot/test_action_communication__rmw_zenoh_cpp/

[WARN] [1766131920.432840100] [rmw_zenoh_cpp]: Unable to connect to a Zenoh router. Have you started a router with `ros2 run rmw_zenoh_cpp rmw_zenohd`?
[WARN] [1766131920.432856600] [rmw_zenoh_cpp]: Unable to connect to a Zenoh router after 1 attempt(s). Please ensure that a Zenoh router is running and can be reached. You may increase the number of attempts to check for a router by setting the ZENOH_ROUTER_CHECK_ATTEMPTS environment variable. Proceeding with initialization but other peers will not discover or receive data from peers in this session until a router is started.

testReport/junit/(root)/projectroot/test_publisher__rmw_zenoh_cpp/

[NON-XML-CHAR-0x1B][2mzenoh::net::runtime::orchestrator[NON-XML-CHAR-0x1B][0m[NON-XML-CHAR-0x1B][2m:[NON-XML-CHAR-0x1B][0m Scouting delay elapsed before start conditions are met.
logging system isn't initialized: call to rcutils_logging_console_output_handler failed.

[JEnoch]

The error that is marked is that the test produce no output

Looking at the full log, I think the failure cause is rather a timeout after 60sec, which is not shown in testReport/junit/(root)/projectroot/test_action_communication__rmw_zenoh_cpp/ :

11: [----------] 6 tests from TestActionIntrospection
11: [ RUN      ] TestActionIntrospection.test_action_server_valid_send_goal_service_event
11: �[2m2025-12-19T08:08:44.357325Z�[0m �[33m WARN�[0m ThreadId(06) �[2mzenoh::net::runtime::orchestrator�[0m�[2m:�[0m Scouting delay elapsed before start conditions are met.
11: [WARN] [1766131724.357393400] [rmw_zenoh_cpp]: Unable to connect to a Zenoh router. Have you started a router with `ros2 run rmw_zenoh_cpp rmw_zenohd`?
11: [WARN] [1766131724.357410000] [rmw_zenoh_cpp]: Unable to connect to a Zenoh router after 1 attempt(s). Please ensure that a Zenoh router is running and can be reached. You may increase the number of attempts to check for a router by setting the ZENOH_ROUTER_CHECK_ATTEMPTS environment variable. Proceeding with initialization but other peers will not discover or receive data from peers in this session until a router is started.
11/26 Test #11: test_action_communication__rmw_zenoh_cpp ........***Timeout  60.01 sec
test 12
      Start 12: test_action_interaction__rmw_zenoh_cpp

It seems this 60 seconds timeout corresponds to the budget for the full set of tests, according to this log:

11: Test command: C:\pixi_ws\.pixi\envs\default\python.exe "-u" "C:/ci/ws/install/share/ament_cmake_test/cmake/run_test.py" "C:/ci/ws/build/rcl_action/test_results/rcl_action/test_action_communication__rmw_zenoh_cpp.gtest.xml" "--package-name" "rcl_action" "--output-file" "C:/ci/ws/build/rcl_action/ament_cmake_gtest/test_action_communication__rmw_zenoh_cpp.txt" "--env" "RMW_IMPLEMENTATION=rmw_zenoh_cpp" "ZENOH_CONFIG_OVERRIDE=scouting/multicast/enabled=true" "--command" "C:/ci/ws/build/rcl_action/Release/test_action_communication.exe" "--gtest_output=xml:C:/ci/ws/build/rcl_action/test_results/rcl_action/test_action_communication__rmw_zenoh_cpp.gtest.xml"
11: Working Directory: C:/ci/ws/build/rcl_action
11: Test timeout computed to be: 60

Since each of the 20 tests is wasting 4 seconds trying to connect to a router, the rcl_action tests are exceeding the 60 seconds.

The same timeout log appears for test_publisher__rmw_zenoh_cpp, due to the same cause.

there are a number of logs pointing to the Zenoh router not being initialized.

This shows that those tests are not using the rmw_test_fixture which is supposed to run a router.
The Scouting delay elapsed before start conditions are met warning log also occurs when a Node fails to connect to the configured router.

In my opinion a global solution has to be discussed in the scope of #881.

[ros-discourse]

This issue has been mentioned on Open Robotics Discourse. There might be relevant details there:

https://discourse.openrobotics.org/t/ros-pmc-minutes-for-march-3-2026/52968/1