Test `per_controller_equal_and_higher_update_rate` is flaky

[christophfroehlich]

https://github.com/ros-controls/ros2_control/actions/runs/12187928738/job/33999820752

on humble

2024-12-05T21:13:58.5971972Z 1: [ RUN      ] per_controller_equal_and_higher_update_rate/TestControllerManagerWithUpdateRates.per_controller_equal_and_higher_update_rate/2
2024-12-05T21:13:58.5973326Z 1: [INFO] [1733433003.025548700] [test_controller_manager]: Subscribing to '/robot_description' topic for robot description.
2024-12-05T21:13:58.5974383Z 1: [INFO] [1733433003.025668683] [test_controller_manager]: Received robot description from topic.
2024-12-05T21:13:58.5975401Z 1: [INFO] [1733433003.027117287] [ResourceManager.resource_manager]: Loading hardware 'TestActuatorHardware' 
2024-12-05T21:13:58.5977081Z 1: [INFO] [1733433003.027343066] [ResourceManager.resource_manager]: Loaded hardware 'TestActuatorHardware' from plugin 'test_actuator'
2024-12-05T21:13:58.5978362Z 1: [INFO] [1733433003.027395784] [ResourceManager.resource_manager]: Initialize hardware 'TestActuatorHardware' 
2024-12-05T21:13:58.5979592Z 1: [INFO] [1733433003.027462459] [ResourceManager.resource_manager]: Successful initialization of hardware 'TestActuatorHardware'
2024-12-05T21:13:58.5981097Z 1: [WARN] [1733433003.027526848] [ResourceManager.resource_manager]: Importing state interfaces for the hardware 'TestActuatorHardware' returned no state interfaces.
2024-12-05T21:13:58.5982655Z 1: [INFO] [1733433003.027596548] [ResourceManager.resource_manager]: Loading hardware 'TestSensorHardware' 
2024-12-05T21:13:58.5983851Z 1: [INFO] [1733433003.027810756] [ResourceManager.resource_manager]: Loaded hardware 'TestSensorHardware' from plugin 'test_sensor'
2024-12-05T21:13:58.5985053Z 1: [INFO] [1733433003.027856892] [ResourceManager.resource_manager]: Initialize hardware 'TestSensorHardware' 
2024-12-05T21:13:58.5986242Z 1: [INFO] [1733433003.027957860] [ResourceManager.resource_manager]: Successful initialization of hardware 'TestSensorHardware'
2024-12-05T21:13:58.5987717Z 1: [WARN] [1733433003.028001330] [ResourceManager.resource_manager]: Importing state interfaces for the hardware 'TestSensorHardware' returned no state interfaces.
2024-12-05T21:13:58.5989082Z 1: [INFO] [1733433003.028026908] [ResourceManager.resource_manager]: Loading hardware 'TestSystemHardware' 
2024-12-05T21:13:58.5990258Z 1: [INFO] [1733433003.028225457] [ResourceManager.resource_manager]: Loaded hardware 'TestSystemHardware' from plugin 'test_system'
2024-12-05T21:13:58.5991464Z 1: [INFO] [1733433003.028270070] [ResourceManager.resource_manager]: Initialize hardware 'TestSystemHardware' 
2024-12-05T21:13:58.5992653Z 1: [INFO] [1733433003.028405702] [ResourceManager.resource_manager]: Successful initialization of hardware 'TestSystemHardware'
2024-12-05T21:13:58.5994122Z 1: [WARN] [1733433003.028508834] [ResourceManager.resource_manager]: Importing state interfaces for the hardware 'TestSystemHardware' returned no state interfaces.
2024-12-05T21:13:58.5995396Z 1: [INFO] [1733433003.028679762] [resource_manager]: 'configure' hardware 'TestSystemHardware' 
2024-12-05T21:13:58.5996354Z 1: [INFO] [1733433003.028703275] [resource_manager]: Successful 'configure' of hardware 'TestSystemHardware'
2024-12-05T21:13:58.5997310Z 1: [INFO] [1733433003.028723764] [resource_manager]: 'activate' hardware 'TestSystemHardware' 
2024-12-05T21:13:58.5998254Z 1: [INFO] [1733433003.028734464] [resource_manager]: Successful 'activate' of hardware 'TestSystemHardware'
2024-12-05T21:13:58.5999206Z 1: [INFO] [1733433003.028753869] [resource_manager]: 'configure' hardware 'TestSensorHardware' 
2024-12-05T21:13:58.6000163Z 1: [INFO] [1733433003.028767846] [resource_manager]: Successful 'configure' of hardware 'TestSensorHardware'
2024-12-05T21:13:58.6001105Z 1: [INFO] [1733433003.028780018] [resource_manager]: 'activate' hardware 'TestSensorHardware' 
2024-12-05T21:13:58.6002051Z 1: [INFO] [1733433003.028788985] [resource_manager]: Successful 'activate' of hardware 'TestSensorHardware'
2024-12-05T21:13:58.6003015Z 1: [INFO] [1733433003.028804964] [resource_manager]: 'configure' hardware 'TestActuatorHardware' 
2024-12-05T21:13:58.6003996Z 1: [INFO] [1733433003.028814582] [resource_manager]: Successful 'configure' of hardware 'TestActuatorHardware'
2024-12-05T21:13:58.6004972Z 1: [INFO] [1733433003.028830041] [resource_manager]: 'activate' hardware 'TestActuatorHardware' 
2024-12-05T21:13:58.6005947Z 1: [INFO] [1733433003.028838437] [resource_manager]: Successful 'activate' of hardware 'TestActuatorHardware'
2024-12-05T21:13:58.6007216Z 1: [INFO] [1733433003.028854897] [test_controller_manager]: Resource Manager has been successfully initialized. Starting Controller Manager services...
2024-12-05T21:13:58.6008366Z 1: [INFO] [1733433003.031617925] [test_controller_manager]: Testing update rate : 400 Hz
2024-12-05T21:13:58.6009465Z 1: [INFO] [1733433003.031712350] [test_controller_manager]: Controller 'test_controller_name' node arguments: 
2024-12-05T21:13:58.6010490Z 1: [INFO] [1733433003.051956058] [test_controller_manager]: Configuring controller: 'test_controller_name'
2024-12-05T21:13:58.6011196Z 1: unknown file: Failure
2024-12-05T21:13:58.6011850Z 1: C++ exception with description "Error in state! Internal state_handle is NULL." thrown in the test body.
2024-12-05T21:13:58.6013319Z 1: [  FAILED  ] per_controller_equal_and_higher_update_rate/TestControllerManagerWithUpdateRates.per_controller_equal_and_higher_update_rate/2, where GetParam() = 400 (50 ms)

[saikishor]

2024-12-05T21:13:58.6011850Z 1: C++ exception with description "Error in state! Internal state_handle is NULL." thrown in the test body.

I'm just checking this and I think something else is wrong in the humble setup apart from the tests
https://github.com/ros2/rclcpp/blob/e9edc3fda0ec9fbdcb64669e7c6dfbb60924feab/rclcpp_lifecycle/src/state.cpp#L142-L160

[christophfroehlich]

Any suggestions how to debug this?

[saikishor]

Any suggestions how to debug this?

I'm not sure how to debug this. I can think about it. Is the failure very often?

[saikishor]

Seems to be related to #979

[christophfroehlich]

https://github.com/ros-controls/ros2_control/actions/runs/12655898208/job/35267401927?pr=1979

[christophfroehlich]

ros-controls/ros2_control_ci#319

   >>>
build/controller_manager/test_results/controller_manager/test_controller_manager.gtest.xml: 32 tests, 0 errors, 1 failure, 0 skipped
- controller_manager.per_controller_equal_and_higher_update_rate/TestControllerManagerWithUpdateRates per_controller_equal_and_higher_update_rate/1 (/home/runner/work/ros2_control_ci/ros2_control_ci/.work/target_ws/src/ros-controls/ros2_control/controller_manager/test/test_controller_manager.cpp:833)
  <<< failure message
    /home/runner/work/ros2_control_ci/ros2_control_ci/.work/target_ws/src/ros-controls/ros2_control/controller_manager/test/test_controller_manager.cpp:911
    Value of: test_controller->update_period_.seconds()
    Expected: (is >= 0.0085) and (is < 0.0115)
      Actual: 0.011670798 (of type double)
    /home/runner/work/ros2_control_ci/ros2_control_ci/.work/target_ws/src/ros-controls/ros2_control/controller_manager/test/test_controller_manager.cpp:911
    Value of: test_controller->update_period_.seconds()
    Expected: (is >= 0.0085) and (is < 0.0115)
      Actual: 0.0083265830000000002 (of type double)
  >>>

[christophfroehlich]

#2259

2025-05-21T03:16:35.2453002Z 1: /home/runner/work/ros2_control/ros2_control/.work/target_ws/src/ros2_control/controller_manager/test/test_controller_manager.cpp:911: Failure
2025-05-21T03:16:35.2457380Z 1: Value of: test_controller->update_period_.seconds()
2025-05-21T03:16:35.2458670Z 1: Expected: (is >= 0.008) and (is < 0.012)
2025-05-21T03:16:35.2460748Z 1:   Actual: 0.012761332 (of type double)
2025-05-21T03:16:35.2462319Z 1: 
2025-05-21T03:16:35.2476063Z 1: /home/runner/work/ros2_control/ros2_control/.work/target_ws/src/ros2_control/controller_manager/test/test_controller_manager.cpp:911: Failure
2025-05-21T03:16:35.2477259Z 1: Value of: test_controller->update_period_.seconds()
2025-05-21T03:16:35.2477782Z 1: Expected: (is >= 0.008) and (is < 0.012)
2025-05-21T03:16:35.2478235Z 1:   Actual: 0.0072416 (of type double)
2025-05-21T03:16:35.2478611Z 1: 
2025-05-21T03:16:35.2479259Z 1: [INFO] [1747797098.497848053] [test_controller_manager]: Deactivating controllers: [ test_controller_name ]
2025-05-21T03:16:35.2480283Z 1: [INFO] [1747797098.598067427] [test_controller_manager]: Successfully switched controllers!
2025-05-21T03:16:35.2481256Z 1: [INFO] [1747797098.619198880] [test_controller_manager]: Unloading controller: 'test_controller_name'
2025-05-21T03:16:35.2482254Z 1: [INFO] [1747797098.733567438] [test_controller_manager.pal_statistics]: Async messages lost 0
2025-05-21T03:16:35.2483232Z 1: [INFO] [1747797098.733602744] [test_controller_manager.pal_statistics]: publish_async_failures_ 0
2025-05-21T03:16:35.2484756Z 1: [  FAILED  ] per_controller_equal_and_higher_update_rate/TestControllerManagerWithUpdateRates.per_controller_equal_and_higher_update_rate/2, where GetParam() = 400 (2408 ms)
2025-05-21T03:16:35.2486646Z 1: [----------] 3 tests from per_controller_equal_and_higher_update_rate/TestControllerManagerWithUpdateRates (7215 ms total)