[gazebo_ros] More than 1 gzserver rostest results in timeout #409

lucasw · 2016-03-22T04:00:14Z

I can create rostests that use gzserver that run fine when run individually using rostest or catkin_make run_tests and the individual test name, but trying two tests results in a timeout.

It looks like gazebo isn't getting shut down properly.

Example in https://github.com/lucasw/gazebo_ros_pkgs/tree/gazebo_ros_tests/gazebo_ros/test

$  catkin_make run_tests_gazebo_ros
####
#### Running command: "make run_tests_gazebo_ros -j4 -l4" in "/home/lucasw/catkin_ws/build"
####
-- run_tests.py: execute commands
-- run_tests.py: execute commands
  /opt/ros/jade/share/rostest/cmake/../../../bin/rostest --pkgdir=/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros --package=gazebo_ros --results-filename test_gazebo_ros.xml --results-base-dir /home/lucasw/catkin_ws/build/test_results /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros.test 
  /opt/ros/jade/share/rostest/cmake/../../../bin/rostest --pkgdir=/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros --package=gazebo_ros --results-filename test_gazebo_ros2.xml --results-base-dir /home/lucasw/catkin_ws/build/test_results /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros2.test 
INFO: cannot create a symlink to latest log directory: [Errno 2] No such file or directory: '/home/lucasw/.ros/latest'
... logging to /home/lucasw/.ros/log/rostest-glover-23010.log
... logging to /home/lucasw/.ros/log/rostest-glover-23011.log
[ROSUNIT] Outputting test results to /home/lucasw/catkin_ws/build/test_results/gazebo_ros/rostest-test_gazebo_ros2.xml
[ROSUNIT] Outputting test results to /home/lucasw/catkin_ws/build/test_results/gazebo_ros/rostest-test_gazebo_ros.xml
[ INFO] /gazebo /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/src/gazebo_ros_api_plugin.cpp:155 : Finished loading Gazebo ROS API Plugin.
[ INFO] /gazebo /tmp/binarydeb/ros-jade-roscpp-1.11.16/src/libros/service.cpp:80 : waitForService: Service [/gazebo/set_physics_properties] has not been advertised, waiting...
[ INFO] /gazebo /tmp/binarydeb/ros-jade-roscpp-1.11.16/src/libros/service.cpp:122 : waitForService: Service [/gazebo/set_physics_properties] is now available.
[ INFO] /gazebo /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/src/gazebo_ros_api_plugin.cpp:1985 : Physics dynamic reconfigure ready.
testgazebo_ros ... ok

[ROSTEST]-----------------------------------------------------------------------

[gazebo_ros.rosunit-gazebo_ros/cameraSubscribeTest][passed]

SUMMARY
 * RESULT: SUCCESS
 * TESTS: 1
 * ERRORS: 0
 * FAILURES: 0

rostest log file is in /home/lucasw/.ros/log/rostest-glover-23010.log
-- run_tests.py: verify result "/home/lucasw/catkin_ws/build/test_results/gazebo_ros/rostest-test_gazebo_ros.xml"
Built target run_tests_gazebo_ros_rostest_test_gazebo_ros.test
testgazebo_ros2 ... ERROR!
ERROR: max time [10.0s] allotted for test [gazebo_ros2] of type [gazebo_ros/gazebo_ros-test]
  File "/usr/lib/python2.7/unittest/case.py", line 331, in run
    testMethod()
  File "/opt/ros/jade/lib/python2.7/dist-packages/rostest/runner.py", line 148, in fn
    self.test_parent.run_test(test)
  File "/opt/ros/jade/lib/python2.7/dist-packages/rostest/rostest_parent.py", line 132, in run_test
    return self.runner.run_test(test)
  File "/opt/ros/jade/lib/python2.7/dist-packages/roslaunch/launch.py", line 681, in run_test
    (test.time_limit, test.test_name, test.package, test.type))
--------------------------------------------------------------------------------

[ROSTEST]-----------------------------------------------------------------------


SUMMARY
 * RESULT: FAIL
 * TESTS: 0
 * ERRORS: 1
 * FAILURES: 0

rostest log file is in /home/lucasw/.ros/log/rostest-glover-23011.log
-- run_tests.py: verify result "/home/lucasw/catkin_ws/build/test_results/gazebo_ros/rostest-test_gazebo_ros2.xml"
Built target run_tests_gazebo_ros_rostest_test_gazebo_ros2.test
Built target run_tests_gazebo_ros_rostest
Built target run_tests_gazebo_ros

The first test log:

<?xml version="1.0" encoding="utf-8"?>
<testsuite errors="0" failures="0" name="unittest.suite.TestSuite" tests="1" time="2.528">
  <testcase classname="rostest.runner.RosTest" name="testgazebo_ros" time="2.5279"></testcase>
  <system-out><![CDATA[[ROSTEST]setup[/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros.test] run_id[d5915346-efe1-11e5-887c-00dbdf11ceac] starting
?[1mstarted roslaunch server http://127.0.0.1:46179/?[0m

SUMMARY
========

PARAMETERS
 * /rosdistro: jade
 * /rosversion: 1.11.16
 * /use_sim_time: True

NODES
  /
    gazebo (gazebo_ros/gzserver)

[ROSTEST]setup[/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros.test] run_id[d5915346-efe1-11e5-887c-00dbdf11ceac] done
[ROSTEST]Running test [gazebo_ros]
?[1mROS_MASTER_URI=http://127.0.0.1:58817/?[0m
?[1msetting /run_id to d5915346-efe1-11e5-887c-00dbdf11ceac?[0m
?[1mprocess[rosout-1]: started with pid [23052]?[0m
started core service [/rosout]
?[1mprocess[gazebo-2]: started with pid [23061]?[0m
[ROSTEST]running test gazebo_ros
?[1mprocess[gazebo_ros-3]: started with pid [23066]?[0m
?[1m[gazebo_ros-3] process has finished cleanly
log file: /home/lucasw/.ros/log/d5915346-efe1-11e5-887c-00dbdf11ceac/gazebo_ros-3*.log?[0m
[ROSTEST]test [gazebo_ros] finished
[ROSTEST]test [gazebo_ros] results are in [/home/lucasw/catkin_ws/build/test_results/gazebo_ros/rosunit-gazebo_ros.xml]
[ROSTEST]test [gazebo_ros] results summary: 0 errors, 0 failures, 1 tests
[ROSTEST][ROSTEST] test [gazebo_ros] done
[ROSTEST]tearDown[/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros.test]
shutting down processing monitor...
[gazebo-2] killing on exit
[rosout-1] killing on exit
... shutting down processing monitor complete
[ROSTEST]rostest teardown /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros.test complete
]]></system-out>
  <system-err><![CDATA[]]></system-err>
</testsuite>

The second test log:

<?xml version="1.0" encoding="utf-8"?>
<testsuite errors="1" failures="0" name="unittest.suite.TestSuite" tests="1" time="25.667">
  <testcase classname="rostest.runner.RosTest" name="testgazebo_ros2" time="25.6671">
    <error type="RLTestTimeoutException">max time [10.0s] allotted for test [gazebo_ros2] of type [gazebo_ros/gazebo_ros-test]
  File "/usr/lib/python2.7/unittest/case.py", line 331, in run
    testMethod()
  File "/opt/ros/jade/lib/python2.7/dist-packages/rostest/runner.py", line 148, in fn
    self.test_parent.run_test(test)
  File "/opt/ros/jade/lib/python2.7/dist-packages/rostest/rostest_parent.py", line 132, in run_test
    return self.runner.run_test(test)
  File "/opt/ros/jade/lib/python2.7/dist-packages/roslaunch/launch.py", line 681, in run_test
    (test.time_limit, test.test_name, test.package, test.type))
    </error>
  </testcase>
  <system-out><![CDATA[[ROSTEST]setup[/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros2.test] run_id[d590c5de-efe1-11e5-98f7-00dbdf11ceac] starting
?[1mstarted roslaunch server http://127.0.0.1:44023/?[0m

SUMMARY
========

PARAMETERS
 * /rosdistro: jade
 * /rosversion: 1.11.16
 * /use_sim_time: True

NODES
  /
    gazebo (gazebo_ros/gzserver)

[ROSTEST]setup[/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros2.test] run_id[d590c5de-efe1-11e5-98f7-00dbdf11ceac] done
[ROSTEST]Running test [gazebo_ros2]
?[1mROS_MASTER_URI=http://127.0.0.1:59785/?[0m
?[1msetting /run_id to d590c5de-efe1-11e5-98f7-00dbdf11ceac?[0m
?[1mprocess[rosout-1]: started with pid [23053]?[0m
started core service [/rosout]
?[1mprocess[gazebo-2]: started with pid [23060]?[0m
[ROSTEST]removing previous test results file [/home/lucasw/catkin_ws/build/test_results/gazebo_ros/rosunit-gazebo_ros2.xml]
[ROSTEST]running test gazebo_ros2
?[1mprocess[gazebo_ros2-3]: started with pid [23072]?[0m
[ROSTEST]tearDown[/home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros2.test]
shutting down processing monitor...
[gazebo_ros2-3] killing on exit
[rosout-1] killing on exit
... shutting down processing monitor complete
[ROSTEST]rostest teardown /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/gazebo_ros2.test complete
]]></system-out>
  <system-err><![CDATA[?[31m[gazebo-2] process has died [pid 23060, exit code 255, cmd /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/scripts/gzserver -r /home/lucasw/catkin_ws/src/gazebo_ros_pkgs/gazebo_ros/test/empty.world __name:=gazebo __log:=/home/lucasw/.ros/log/d590c5de-efe1-11e5-98f7-00dbdf11ceac/gazebo-2.log].
log file: /home/lucasw/.ros/log/d590c5de-efe1-11e5-98f7-00dbdf11ceac/gazebo-2*.log?[0m
?[31m[gazebo_ros2-3] escalating to SIGTERM?[0m
]]></system-err>
</testsuite>

The text was updated successfully, but these errors were encountered:

jacquelinekay · 2016-04-25T22:11:12Z

@scpeters

Interesting, could this be due to issues with running parallel tests (multiple simultaneous gzservers is not possible, I believe)

j-rivero · 2016-04-26T21:59:58Z

Spawning different gzservers is possible although they will need different ports, I think that currently we are not at that point when running the test suite as it is now.

The workaround is to run tests one by one, by using the j1 option.

scpeters · 2016-04-26T22:14:31Z

The travis file was fixed with -j1 on indigo-devel in b972a83 from #353

I'll cherry-pick it to jade

scpeters · 2016-04-26T22:15:45Z

-j1 added to travis.yml in jade in b14eede

scpeters · 2016-04-26T22:16:53Z

I think using -j1 is the safest thing to do.

jacquelinekay · 2016-04-26T22:17:50Z

Maybe we could put that in the README.md for this repository as a reminder for developers who run the tests locally?

Closes ros-simulation#409.

scpeters · 2016-04-26T22:56:02Z

See #440 for the update to the documentation.

scpeters · 2016-04-26T23:23:44Z

I'm going to mark this closed by #440.

Closes #409.

…g 0.6 seconds to receive the messages (still well less than 2.0 seconds). Also all the tests can be run with run_tests_gazebo_plugins_rostest but only with the -j1 flag ros-simulation#409

…to receive the messages (still well less than 2.0 seconds). Also all the tests can be run with run_tests_gazebo_plugins_rostest but only with the -j1 flag #409

…g 0.6 seconds to receive the messages (still well less than 2.0 seconds). Also all the tests can be run with run_tests_gazebo_plugins_rostest but only with the -j1 flag ros-simulation#409

@j-rivero

* Fix for issue #408. The last measurement time is the time that gazebo generated the sensor data, so ought to be used. updateRate doesn't seem that useful. The other cameras need similar fixes to have the proper timestamps. * #408 Making a test for multicamra that shows the timestamps are currently outdated, will fix them similar to how the regular camera was fixed. * #408 Make the multi camera timestamps current rather than outdated, also reuse the same update code * Adding depth camera world to use in test to make depth camera have right timestamp #408- appears to be working (though only looking at horizon) but getting these sdf errors: Error [SDF.cc:789] Missing element description for [pointCloudTopicName] Error [SDF.cc:789] Missing element description for [depthImageCameraInfoTopicName] Error [SDF.cc:789] Missing element description for [pointCloudCutoff] * Disabling this test because of #409 * #408 Created test for depth camera, which fails, so next make it pass * #408 also test points publication * #408 fix timestamps for depth image, test passes now * #408 Increasing max time because some systems are taking 0.6 seconds to receive the messages (still well less than 2.0 seconds). Also all the tests can be run with run_tests_gazebo_plugins_rostest but only with the -j1 flag #409 * Adding @j-rivero default disabling of tests that require a display * change LastUpdateTime to LastMeasurementTime

…g 0.6 seconds to receive the messages (still well less than 2.0 seconds). Also all the tests can be run with run_tests_gazebo_plugins_rostest but only with the -j1 flag ros-simulation#409

lucasw mentioned this issue Mar 22, 2016

[gazebo_plugins] Fix for issue #408 - correct the timestamp used by the camera #410

Merged

lucasw added a commit to lucasw/gazebo_ros_pkgs that referenced this issue Mar 29, 2016

Disabling this test because of ros-simulation#409

b592db3

hsu added this to the kinetic release milestone Apr 25, 2016

scpeters self-assigned this Apr 25, 2016

scpeters added a commit to scpeters/gazebo_ros_pkgs that referenced this issue Apr 26, 2016

Recommend -j1 when running tests.

1d3293e

Closes ros-simulation#409.

scpeters mentioned this issue Apr 26, 2016

Recommend -j1 when running tests. #440

Merged

scpeters closed this as completed Apr 26, 2016

scpeters added a commit that referenced this issue Apr 26, 2016

Recommend -j1 when running tests.

069ef99

Closes #409.

j-rivero mentioned this issue Jul 1, 2016

[gazebo_plugins] Rapid projector toggle rostest #419

Closed

lucasw added a commit to lucasw/gazebo_ros_pkgs that referenced this issue Oct 18, 2016

Disabling this test because of ros-simulation#409

546f285

lucasw added a commit to lucasw/gazebo_ros_pkgs that referenced this issue Dec 21, 2016

Disabling this test because of ros-simulation#409

fe9119d

j-rivero pushed a commit that referenced this issue Feb 13, 2017

Disabling this test because of #409

edee42d

j-rivero mentioned this issue Feb 13, 2017

Correct the timestamp used by the camera (kinetic-devel) #540

Merged

j-rivero pushed a commit that referenced this issue Feb 16, 2017

Disabling this test because of #409

61cb624

davetcoleman pushed a commit to davetcoleman/gazebo_ros_pkgs that referenced this issue Feb 19, 2017

Disabling this test because of ros-simulation#409

3323e21

cohen39 pushed a commit to cohen39/gazebo_ros_pkgs that referenced this issue Nov 15, 2021

Disabling this test because of ros-simulation#409

85d470a

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[gazebo_ros] More than 1 gzserver rostest results in timeout #409

[gazebo_ros] More than 1 gzserver rostest results in timeout #409

lucasw commented Mar 22, 2016

jacquelinekay commented Apr 25, 2016

j-rivero commented Apr 26, 2016

scpeters commented Apr 26, 2016

scpeters commented Apr 26, 2016

scpeters commented Apr 26, 2016

jacquelinekay commented Apr 26, 2016

scpeters commented Apr 26, 2016

scpeters commented Apr 26, 2016

[gazebo_ros] More than 1 gzserver rostest results in timeout #409

[gazebo_ros] More than 1 gzserver rostest results in timeout #409

Comments

lucasw commented Mar 22, 2016

jacquelinekay commented Apr 25, 2016

j-rivero commented Apr 26, 2016

scpeters commented Apr 26, 2016

scpeters commented Apr 26, 2016

scpeters commented Apr 26, 2016

jacquelinekay commented Apr 26, 2016

scpeters commented Apr 26, 2016

scpeters commented Apr 26, 2016