Closed github-actions[bot] closed 5 months ago
christophfroehlich
commented
6 months ago Not sure why this failed.
There is a timeout of this assertion https://github.com/ros-controls/ros2_control_ci/actions/runs/8119504060/job/22195468568#step:6:22777
Let's see if it also fails with the next scheduled test.
christophfroehlich
commented
5 months ago @ahcorde do you have maybe an idea why the launch_test from ign_ros2_control fails here? The output contains the test string, but it times out.
fmauch
commented
5 months ago I can reproduce that locally. Will further debug this at a later point.
christophfroehlich
commented
5 months ago Really? How? I used act, and it succeeded.
fmauch
commented
5 months ago I created a new workspace, did
vcs import --input https://raw.githubusercontent.com/ros-controls/ros2_control_ci/master/ros_controls.humble.repos .and ran
rosdep install --from-path . --ignore-src
colcon build --symlink-install --cmake-args -DCMAKE_EXPORT_COMPILE_COMMANDS=1
source install/setup.zsh
colcon test --event-handlers console_direct+Well, actually, my traceback looks different:
9: xacro_file /home/ubuntu/checkout/ros2_control_humble/colcon_ws/install/gz_ros2_control_tests/share/gz_ros2_control_tests/urdf/test_cart_position.xacro.urdf
9: [INFO] [launch]: All log files can be found below /home/ubuntu/.ros/log/2024-03-14-11-33-24-218648-jamy-71836
9: [INFO] [launch]: Default logging verbosity is set to INFO
9: test_arm (gz_ros2_control_tests.TestFixture) ... [INFO] [ruby $(which ign) gazebo-1]: process started with pid [71839]
9: [INFO] [create-2]: process started with pid [71841]
9: [INFO] [robot_state_publisher-3]: process started with pid [71843]
9: [INFO] [python3-4]: process started with pid [71846]
9: [robot_state_publisher-3] [INFO] [1710416004.339071300] [robot_state_publisher]: got segment cart
9: [robot_state_publisher-3] [INFO] [1710416004.339145184] [robot_state_publisher]: got segment slideBar
9: [robot_state_publisher-3] [INFO] [1710416004.339153758] [robot_state_publisher]: got segment world
9: [create-2] [INFO] [1710416004.352468729] [ros_gz_sim]: Requesting list of world names.
9: [create-2] [INFO] [1710416004.569629871] [ros_gz_sim]: Requested creation of entity.
9: [create-2] [INFO] [1710416004.569669428] [ros_gz_sim]: OK creation of entity.
9: [INFO] [create-2]: process has finished cleanly [pid 71841]
9: [INFO] [ros2-5]: process started with pid [71904]
9: [ros2-5] Error loading controller, check controller_manager logs
9: [ERROR] [ros2-5]: process has died [pid 71904, exit code 1, cmd 'ros2 control load_controller --set-state active joint_state_broadcaster'].
9: [INFO] [ros2-6]: process started with pid [71924]
9: [ruby $(which ign) gazebo-1] [Wrn] [SimulationRunner.cc:662] Found additional publishers on /stats, using namespaced stats topic only
9: [ruby $(which ign) gazebo-1] [Msg] Ignition Gazebo Server v6.16.0
9: [ruby $(which ign) gazebo-1] [Msg] Loading SDF world file[/usr/share/ignition/ignition-gazebo6/worlds/empty.sdf].
9: [ruby $(which ign) gazebo-1] [Msg] Serving entity system service on [/entity/system/add]
9: [ruby $(which ign) gazebo-1] [Dbg] [Physics.cc:804] Loaded [ignition::physics::dartsim::Plugin] from library [/usr/lib/x86_64-linux-gnu/ign-physics-5/engine-plugins/libignition-physics-dartsim-plugin.so]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::Physics] for entity [1]
9: [ruby $(which ign) gazebo-1] [Msg] Create service on [/world/empty/create]
9: [ruby $(which ign) gazebo-1] [Msg] Remove service on [/world/empty/remove]
9: [ruby $(which ign) gazebo-1] [Msg] Pose service on [/world/empty/set_pose]
9: [ruby $(which ign) gazebo-1] [Msg] Pose service on [/world/empty/set_pose_vector]
9: [ruby $(which ign) gazebo-1] [Msg] Light configuration service on [/world/empty/light_config]
9: [ruby $(which ign) gazebo-1] [Msg] Physics service on [/world/empty/set_physics]
9: [ruby $(which ign) gazebo-1] [Msg] SphericalCoordinates service on [/world/empty/set_spherical_coordinates]
9: [ruby $(which ign) gazebo-1] [Msg] Enable collision service on [/world/empty/enable_collision]
9: [ruby $(which ign) gazebo-1] [Msg] Disable collision service on [/world/empty/disable_collision]
9: [ruby $(which ign) gazebo-1] [Msg] Material service on [/world/empty/visual_config]
9: [ruby $(which ign) gazebo-1] [Msg] Material service on [/world/empty/wheel_slip]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::UserCommands] for entity [1]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::SceneBroadcaster] for entity [1]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::Contact] for entity [1]
9: [ruby $(which ign) gazebo-1] [Msg] Loaded level [3]
9: [ruby $(which ign) gazebo-1] [Msg] Serving world controls on [/world/empty/control], [/world/empty/control/state] and [/world/empty/playback/control]
9: [ruby $(which ign) gazebo-1] [Msg] Serving GUI information on [/world/empty/gui/info]
9: [ruby $(which ign) gazebo-1] [Msg] World [empty] initialized with [1ms] physics profile.
9: [ruby $(which ign) gazebo-1] [Msg] Serving world SDF generation service on [/world/empty/generate_world_sdf]
9: [ruby $(which ign) gazebo-1] [Msg] Serving world names on [/gazebo/worlds]
9: [ruby $(which ign) gazebo-1] [Msg] Resource path add service on [/gazebo/resource_paths/add].
9: [ruby $(which ign) gazebo-1] [Msg] Resource path get service on [/gazebo/resource_paths/get].
9: [ruby $(which ign) gazebo-1] [Msg] Resource path resolve service on [/gazebo/resource_paths/resolve].
9: [ruby $(which ign) gazebo-1] [Msg] Resource paths published on [/gazebo/resource_paths].
9: [ruby $(which ign) gazebo-1] [Msg] Server control service on [/server_control].
9: [ruby $(which ign) gazebo-1] [Dbg] [SimulationRunner.cc:664] Publishers [Address, Message Type]:
9: [ruby $(which ign) gazebo-1] [Wrn] [SimulationRunner.cc:695] Found additional publishers on /clock, using namespaced clock topic only
9: [ros2-6] Error loading controller, check controller_manager logs
9: [ERROR] [ros2-6]: process has died [pid 71924, exit code 1, cmd 'ros2 control load_controller --set-state active joint_trajectory_controller'].
[Processing: gz_ros2_control_tests]
[Processing: gz_ros2_control_tests]
[Processing: gz_ros2_control_tests]
9: FAIL
9:
9: ======================================================================
9: FAIL: test_arm (gz_ros2_control_tests.TestFixture)
9: ----------------------------------------------------------------------
9: Traceback (most recent call last):
9: File "/home/ubuntu/checkout/ros2_control_humble/colcon_ws/src/ros-controls/gz_ros2_control/gz_ros2_control_tests/tests/position_test.py", line 123, in test_arm
9: proc_output.assertWaitFor('Sucessfully loaded controller joint_trajectory_controller '
9: File "/opt/ros/humble/lib/python3.10/site-packages/launch_testing/io_handler.py", line 146, in assertWaitFor
9: assert success, 'Waiting for output timed out'
9: AssertionError: Waiting for output timed out
9:
9: ----------------------------------------------------------------------
9: Ran 1 test in 100.001sI'll try again using a fresh docker container and with running sequentially.
fmauch
commented
5 months ago I created a new docker container:
docker run -it --rm ros:humbleInside the container I ran
apt update
apt dist-upgrade
rosdep update
mkdir -p colcon_ws/src
cd colcon_ws/src
vcs import --input https://raw.githubusercontent.com/ros-controls/ros2_control_ci/master/ros_controls.humble.repos .
rosdep install --from-path . --ignore-src -y
cd ..
colcon build --symlink-install --cmake-args -DCMAKE_EXPORT_COMPILE_COMMANDS=1
source install/setup.bash
colcon test --event-handlers console_direct+ --packages-select ign_ros2_control ign_ros2_control_demos gz_ros2_control_testsResult:
Start 9: test_position_controller
9: Test command: /usr/bin/python3 "-u" "/opt/ros/humble/share/ament_cmake_test/cmake/run_test.py" "/colcon_ws/build/gz_ros2_control_tests/test_results/gz_ros2_control_tests/test_position_controller.xunit.xml" "--package-name" "gz_ros2_control_tests" "--output-file" "/colcon_ws/build/gz_ros2_control_tests/launch_test/test_position_controller.txt" "--command" "/usr/bin/python3" "-m" "launch_testing.launch_test" "/colcon_ws/src/ros-controls/gz_ros2_control/gz_ros2_control_tests/tests/position_test.py" "-
-junit-xml=/colcon_ws/build/gz_ros2_control_tests/test_results/gz_ros2_control_tests/test_position_controller.xunit.xml" "--package-name=gz_ros2_control_tests"
9: Test timeout computed to be: 120
9: -- run_test.py: invoking following command in '/colcon_ws/build/gz_ros2_control_tests/tests':
9: - /usr/bin/python3 -m launch_testing.launch_test /colcon_ws/src/ros-controls/gz_ros2_control/gz_ros2_control_tests/tests/position_test.py --junit-xml=/colcon_ws/build/gz_ros2_control_tests/test_results/gz_ros2_control_tests/test_position_controller.xunit.xml --package-name=gz_ros2_control_tests
9: xacro_file /colcon_ws/install/gz_ros2_control_tests/share/gz_ros2_control_tests/urdf/test_cart_position.xacro.urdf
9: [INFO] [launch]: All log files can be found below /root/.ros/log/2024-03-14-11-56-06-019876-a6c3bfc60d62-34187
9: [INFO] [launch]: Default logging verbosity is set to INFO
9: test_arm (gz_ros2_control_tests.TestFixture) ... [INFO] [ruby $(which ign) gazebo-1]: process started with pid [34189]
9: [INFO] [create-2]: process started with pid [34191]
9: [INFO] [robot_state_publisher-3]: process started with pid [34193]
9: [INFO] [python3-4]: process started with pid [34195]
9: [robot_state_publisher-3] [INFO] [1710417366.120964905] [robot_state_publisher]: got segment cart
9: [robot_state_publisher-3] [INFO] [1710417366.121103810] [robot_state_publisher]: got segment slideBar
9: [robot_state_publisher-3] [INFO] [1710417366.121116942] [robot_state_publisher]: got segment world
9: [create-2] [INFO] [1710417366.130844815] [ros_gz_sim]: Requesting list of world names.
9: [create-2] [INFO] [1710417366.552531779] [ros_gz_sim]: Requested creation of entity.
9: [create-2] [INFO] [1710417366.552571706] [ros_gz_sim]: OK creation of entity.
9: [INFO] [create-2]: process has finished cleanly [pid 34191]
9: [INFO] [ros2-5]: process started with pid [34253]
9: [ruby $(which ign) gazebo-1] [Msg] Ignition Gazebo Server v6.16.0
9: [ruby $(which ign) gazebo-1] [Msg] Loading SDF world file[/usr/share/ignition/ignition-gazebo6/worlds/empty.sdf].
9: [ruby $(which ign) gazebo-1] [Msg] Serving entity system service on [/entity/system/add]
9: [ruby $(which ign) gazebo-1] [Dbg] [Physics.cc:804] Loaded [ignition::physics::dartsim::Plugin] from library [/usr/lib/x86_64-linux-gnu/ign-physics-5/engine-plugins/libignition-physics-dartsim-plugin.so]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::Physics] for entity [1]
9: [ruby $(which ign) gazebo-1] [Msg] Create service on [/world/empty/create]
9: [ruby $(which ign) gazebo-1] [Msg] Remove service on [/world/empty/remove]
9: [ruby $(which ign) gazebo-1] [Msg] Pose service on [/world/empty/set_pose]
9: [ruby $(which ign) gazebo-1] [Msg] Pose service on [/world/empty/set_pose_vector]
9: [ruby $(which ign) gazebo-1] [Msg] Light configuration service on [/world/empty/light_config]
9: [ruby $(which ign) gazebo-1] [Msg] Physics service on [/world/empty/set_physics]
9: [ruby $(which ign) gazebo-1] [Msg] SphericalCoordinates service on [/world/empty/set_spherical_coordinates]
9: [ruby $(which ign) gazebo-1] [Msg] Enable collision service on [/world/empty/enable_collision]
9: [ruby $(which ign) gazebo-1] [Msg] Disable collision service on [/world/empty/disable_collision]
9: [ruby $(which ign) gazebo-1] [Msg] Material service on [/world/empty/visual_config]
9: [ruby $(which ign) gazebo-1] [Msg] Material service on [/world/empty/wheel_slip]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::UserCommands] for entity [1]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::SceneBroadcaster] for entity [1]
9: [ruby $(which ign) gazebo-1] [Dbg] [SystemManager.cc:70] Loaded system [gz::sim::systems::Contact] for entity [1]
9: [ruby $(which ign) gazebo-1] [Msg] Loaded level [3]
9: [ruby $(which ign) gazebo-1] [Msg] Serving world controls on [/world/empty/control], [/world/empty/control/state] and [/world/empty/playback/control]
9: [ruby $(which ign) gazebo-1] [Msg] Serving GUI information on [/world/empty/gui/info]
9: [ruby $(which ign) gazebo-1] [Msg] World [empty] initialized with [1ms] physics profile.
9: [ruby $(which ign) gazebo-1] [Msg] Serving world SDF generation service on [/world/empty/generate_world_sdf]
9: [ruby $(which ign) gazebo-1] [Msg] Serving world names on [/gazebo/worlds]
9: [ruby $(which ign) gazebo-1] [Msg] Resource path add service on [/gazebo/resource_paths/add].
9: [ruby $(which ign) gazebo-1] [Msg] Resource path get service on [/gazebo/resource_paths/get].
9: [ruby $(which ign) gazebo-1] [Msg] Resource path resolve service on [/gazebo/resource_paths/resolve].
9: [ruby $(which ign) gazebo-1] [Msg] Resource paths published on [/gazebo/resource_paths].
9: [ruby $(which ign) gazebo-1] [Msg] Server control service on [/server_control].
9: [ruby $(which ign) gazebo-1] [Msg] Found no publishers on /stats, adding root stats topic
9: [ruby $(which ign) gazebo-1] [Msg] Found no publishers on /clock, adding root clock topic
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.486834205] [gz_ros2_control]: [ign_ros2_control] Fixed joint [world_to_base] (Entity=17)] is skipped
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.489713584] [gz_ros2_control]: connected to service!! robot_state_publisher asking for robot_description
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.490513804] [gz_ros2_control]: Received URDF from param server
9: [ruby $(which ign) gazebo-1] [WARN] [1710417368.532812557] [gz_ros2_control]: The position_proportional_gain parameter was not defined, defaulting to: 0.1
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.532972562] [gz_ros2_control]: Loading joint: slider_to_cart
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.532998530] [gz_ros2_control]: State:
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533010047] [gz_ros2_control]: position
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533080648] [gz_ros2_control]: found initial value: 0.000000
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533090872] [gz_ros2_control]: velocity
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533120742] [gz_ros2_control]: effort
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533137990] [gz_ros2_control]: Command:
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533144244] [gz_ros2_control]: position
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.533729018] [resource_manager]: Initialize hardware 'IgnitionSystem'
9: [ruby $(which ign) gazebo-1] [WARN] [1710417368.533772206] [gz_ros2_control]: On init...
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.534084994] [resource_manager]: Successful initialization of hardware 'IgnitionSystem'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.540174956] [resource_manager]: 'configure' hardware 'IgnitionSystem'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.540230806] [gz_ros2_control]: System Successfully configured!
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.540261273] [resource_manager]: Successful 'configure' of hardware 'IgnitionSystem'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.540300664] [resource_manager]: 'activate' hardware 'IgnitionSystem'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.540306402] [resource_manager]: Successful 'activate' of hardware 'IgnitionSystem'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.540316862] [gz_ros2_control]: Loading controller_manager
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.600194175] [controller_manager]: Loading controller 'joint_state_broadcaster'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.610437132] [controller_manager]: Configuring controller 'joint_state_broadcaster'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417368.610727738] [joint_state_broadcaster]: 'joints' or 'interfaces' parameter is empty. All available state interfaces will be published
9: [ros2-5] Successfully loaded controller joint_state_broadcaster into state active
9: [INFO] [ros2-5]: process has finished cleanly [pid 34253]
9: [INFO] [ros2-6]: process started with pid [34293]
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.609735581] [controller_manager]: Loading controller 'joint_trajectory_controller'
9: [ruby $(which ign) gazebo-1] [WARN] [1710417369.620761288] [joint_trajectory_controller]: [Deprecated]: "allow_nonzero_velocity_at_trajectory_end" is set to true. The default behavior will change to false.
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.622130635] [controller_manager]: Configuring controller 'joint_trajectory_controller'
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.622319969] [joint_trajectory_controller]: No specific joint names are used for command interfaces. Using 'joints' parameter.
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.622577496] [joint_trajectory_controller]: Command interfaces are [position] and state interfaces are [position velocity].
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.622597576] [joint_trajectory_controller]: Using 'splines' interpolation method.
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.625140889] [joint_trajectory_controller]: Controller state will be published at 50.00 Hz.
9: [ruby $(which ign) gazebo-1] [INFO] [1710417369.626722355] [joint_trajectory_controller]: Action status changes will be monitored at 20.00 Hz.
9: [ros2-6] Successfully loaded controller joint_trajectory_controller into state active
9: [INFO] [ros2-6]: process has finished cleanly [pid 34293]
[Processing: gz_ros2_control_tests]
[Processing: gz_ros2_control_tests]
[Processing: gz_ros2_control_tests]
9: FAIL
9:
9: ======================================================================
9: FAIL: test_arm (gz_ros2_control_tests.TestFixture)
9: ----------------------------------------------------------------------
9: Traceback (most recent call last):
9: File "/colcon_ws/src/ros-controls/gz_ros2_control/gz_ros2_control_tests/tests/position_test.py", line 123, in test_arm
9: proc_output.assertWaitFor('Sucessfully loaded controller joint_trajectory_controller '
9: File "/opt/ros/humble/lib/python3.10/site-packages/launch_testing/io_handler.py", line 146, in assertWaitFor
9: assert success, 'Waiting for output timed out'
9: AssertionError: Waiting for output timed out
9:
9: ----------------------------------------------------------------------
9: Ran 1 test in 100.001sEdit:
9: [ros2-6] Successfully loaded controller joint_trajectory_controller into state active
...
# failure:
9: proc_output.assertWaitFor('Sucessfully loaded controller joint_trajectory_controller ' I guess, I'll call that a success... Still weird that this doesn't popup in the repo build.
fmauch
commented
5 months ago Has that been a recent fix?
Edit: Yep: https://github.com/ros-controls/ros2_control/pull/1414
Case closed. :-)
christophfroehlich
commented
5 months ago Aaaaah, this was me :D I just haven't seen this difference.
christophfroehlich
commented
5 months ago
An automated scheduled build failed on
master: https://github.com/ros-controls/ros2_control_ci/actions/runs/8134894075