Gazebo loading fails intermittently (ros ticket #351)

[ahendrix]

When running some executive trex test cases, I get intermittent failures starting gazebo. To repeat:
rosmake executive_trex_pr2
roscd executive_trex_pr2/arm.0

The final step may have to be repeated a number of times:

roslaunch launch.xml

trac data:

• Owner: hsu
• Reporter: mcgann
• Reported at: Wed Sep 24 08:52:24 2008
• URL: https://code.ros.org/trac/wg-ros-pkg/ticket/351

[ahendrix]

[hsu] I had a similar error, Ken and I figured out that it was due to unclean exit of gazebo. The current solution is to restart botherder/master.

see ticket
[https://prdev.willowgarage.com/trac/personalrobots/ticket/347 347]

[ahendrix]

[mcgann] Output Console Data when it failed.

{{{
mcgann@bcn:~/pr/highlevel/executive_trex/executive_trex_pr2/arm.0$ roslaunch launch.xml
... logging to /u/mcgann/ros/log/roslaunch-18892.log
... loading XML file [launch.xml]
... loading XML file [/u/mcgann/pr/highlevel/executive_trex/executive_trex_pr2/cfg/launch_gazebo.xml]
... loading XML file [/u/mcgann/pr/robot_descriptions/wg_robot_description/send.xml]
... executing command param [/u/mcgann/pr/robot_descriptions/wg_robot_description_parser/merge "/u/mcgann/pr/robot_descriptions/wg_robot_description/pr2/pr2.xml"]
... done importing include file [/u/mcgann/pr/robot_descriptions/wg_robot_description/send.xml]
... loading XML file [/u/mcgann/pr/world_models/world_3d_map/run.xml]
... done importing include file [/u/mcgann/pr/world_models/world_3d_map/run.xml]
... done importing include file [/u/mcgann/pr/highlevel/executive_trex/executive_trex_pr2/cfg/launch_gazebo.xml]
Added node of type [mechanism_control/mech.py] in namespace [/]
Added node of type [robot_mechanism_controllers/control.py] in namespace [/]
Added node of type [map_server/map_server] in namespace [/]
Added node of type [amcl_player/amcl_player] in namespace [/]
Added node of type [world_3d_map/world_3d_map] in namespace [/]
Added node of type [kinematic_planning/kinematic_planning] in namespace [/]
Added node of type [wavefront_player/wavefront_player] in namespace [/]
Added node of type [highlevel_controllers/move_arm] in namespace [/]
Added node of type [nav_view/nav_view] in namespace [/]
Added node of type [gazebo/gazebo] in namespace [/]
Added node of type [executive_trex_pr2/trex_fast] in namespace [/]
Added parameter [/robotdesc/pr2]
Added parameter [/world_3d_map/max_publish_frequency]
Added parameter [/world_3d_map/retain_pointcloud_duration]
Added parameter [/world_3d_map/retain_pointcloud_fraction]
Added parameter [/world_3d_map/retain_above_ground_threshold]
Added parameter [/world_3d_map/verbosity_level]

SUMMARY

PARAMETERS

• /world_3d_map/retain_pointcloud_duration
• /robotdesc/pr2
• /world_3d_map/verbosity_level
• /world_3d_map/retain_above_ground_threshold
• /world_3d_map/retain_pointcloud_fraction
• /world_3d_map/max_publish_frequency

MACHINES

NODES
/
mechanism_control/mech.py
robot_mechanism_controllers/control.py
map_server/map_server
amcl_player/amcl_player
world_3d_map/world_3d_map
kinematic_planning/kinematic_planning
wavefront_player/wavefront_player
highlevel_controllers/move_arm
nav_view/nav_view
gazebo/gazebo
executive_trex_pr2/trex_fast

starting new master
Creating process monitor thread
process[master]: started with pid [18914]
setting parameter [/world_3d_map/retain_pointcloud_duration]
setting parameter [/robotdesc/pr2]
setting parameter [/world_3d_map/verbosity_level]
setting parameter [/world_3d_map/retain_above_ground_threshold]
setting parameter [/world_3d_map/retain_pointcloud_fraction]
setting parameter [/world_3d_map/max_publish_frequency]
process[mech.py-1]: started with pid [18933]
process[control.py-2]: started with pid [18937]
process[map_server-3]: started with pid [18947]
process[amcl_player-4]: started with pid [18961]
process[world_3d_map-5]: started with pid [18977]
process[kinematic_planning-6]: started with pid [19006]
process[wavefront_player-7]: started with pid [19013]
WARNING: Should chain be defined here?
WARNING: Should chain be defined here?
Ignoring point cloud data that intersects with 20 robot parts
process[move_arm-8]: started with pid [19056]
process[nav_view-9]: started with pid [19059]
process[gazebo-10]: started with pid [19074]
... logging to /u/mcgann/ros/log/mech.py-18933.log
process[trex_fast-11]: started with pid [19092]
Gazebo multi-robot simulator, version 0.8-pre3

Part of the Player/Stage Project [http://playerstage.sourceforge.net].
Copyright (C) 2003 Nate Koenig, Andrew Howard, and contributors.
Released under the GNU General Public License.

creating /tmp/gazebo-mcgann-0
found a pid file: pid=18746
The gazebo process is not alive.
... logging to /u/mcgann/ros/log/control.py-18937.log
creating /tmp/gazebo-mcgann-0/simulation.default 112 144496
creating /tmp/gazebo-mcgann-0/camera.cam1_iface_0 112 3145884
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
setting gravity to zero for: cam1_body
-------------------- starting node in laser
creating /tmp/gazebo-mcgann-0/laser.ros_base_laser_iface 112 12448
================= base_scan
creating /tmp/gazebo-mcgann-0/camera.stereo_left_iface 112 3145884
================= stereo_left/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
creating /tmp/gazebo-mcgann-0/laser.stereo_laser_iface 112 12448
================= full_cloud
creating /tmp/gazebo-mcgann-0/camera.ptz_cam_left_iface 112 3145884
================= axis_left/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
creating /tmp/gazebo-mcgann-0/camera.ptz_cam_right_iface 112 3145884
================= axis_right/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
setting gravity to zero for: shoulder_pan_left
setting gravity to zero for: shoulder_pitch_left
setting gravity to zero for: upperarm_roll_left
setting gravity to zero for: elbow_flex_left
setting gravity to zero for: forearm_roll_left
creating /tmp/gazebo-mcgann-0/camera.forearm_cam_left_iface 112 3145884
================= forearm_left/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
setting gravity to zero for: forearm_camera_left
setting gravity to zero for: wrist_flex_left
setting gravity to zero for: gripper_roll_left
setting gravity to zero for: finger_l_left
setting gravity to zero for: finger_tip_l_left
setting gravity to zero for: finger_r_left
setting gravity to zero for: finger_tip_r_left
creating /tmp/gazebo-mcgann-0/camera.wrist_cam_left_iface 112 3145884
================= wrist_left/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
setting gravity to zero for: wrist_camera_left
setting gravity to zero for: shoulder_pan_right
setting gravity to zero for: shoulder_pitch_right
setting gravity to zero for: upperarm_roll_right
setting gravity to zero for: elbow_flex_right
setting gravity to zero for: forearm_roll_right
creating /tmp/gazebo-mcgann-0/camera.forearm_cam_right_iface 112 3145884
================= forearm_right/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
setting gravity to zero for: forearm_camera_right
setting gravity to zero for: wrist_flex_right
setting gravity to zero for: gripper_roll_right
setting gravity to zero for: finger_l_right
setting gravity to zero for: finger_tip_l_right
setting gravity to zero for: finger_r_right
setting gravity to zero for: finger_tip_r_right
creating /tmp/gazebo-mcgann-0/camera.wrist_cam_right_iface 112 3145884
================= wrist_right/image
Unable to read value with key[imageSize]
Unable to read value with key[imageSize]
setting gravity to zero for: wrist_camera_right
creating /tmp/gazebo-mcgann-0/laser.ros_tilt_laser_iface 112 12448
================= tilt_scan
creating /tmp/gazebo-mcgann-0/audio.dummy_ros_time_iface_should_not_be_here 112 420
creating /tmp/gazebo-mcgann-0/ptz.ptz_left_iface 112 124
publishing state topic for ptz axis_left/ptz_state
subscribing command topic for ptz axis_left/ptz_cmd
creating /tmp/gazebo-mcgann-0/ptz.ptz_right_iface 112 124
publishing state topic for ptz axis_right/ptz_state
subscribing command topic for ptz axis_right/ptz_cmd
creating /tmp/gazebo-mcgann-0/position.p3d_right_wrist_position 112 228
==== topic name for P3D ======== gripper_roll_right_pose_ground_truth
creating /tmp/gazebo-mcgann-0/position.p3d_left_wrist_position 112 228
==== topic name for P3D ======== gripper_roll_left_pose_ground_truth
creating /tmp/gazebo-mcgann-0/position.p3d_base_position 112 228
==== topic name for P3D ======== base_pose_ground_truth
creating /tmp/gazebo-mcgann-0/position.f3d_finger_tip_l_left_position 112 228
==== topic name for F3D ======== finger_tip_l_left_ground_truth
creating /tmp/gazebo-mcgann-0/position.f3d_finger_tip_r_left_position 112 228
==== topic name for F3D ======== finger_tip_r_left_ground_truth
creating /tmp/gazebo-mcgann-0/position.f3d_finger_tip_l_right_position 112 228
==== topic name for F3D ======== finger_tip_l_right_ground_truth
creating /tmp/gazebo-mcgann-0/position.f3d_finger_tip_r_right_position 112 228
==== topic name for F3D ======== finger_tip_r_right_ground_truth
creating /tmp/gazebo-mcgann-0/audio.gazebo_actuators_dummy_iface 112 420
Loading /u/mcgann/pr/robot_descriptions/gazebo_robot_description/world/pr2.xml
Spawning base_controller: 0949b94c
base controller name: base_controller
name:wheel_front_left_l_joint
controller type:JointVelocityControllerNode
sub controller : wheel_front_left_l_controller
name:wheel_front_left_r_joint
controller type:JointVelocityControllerNode
sub controller : wheel_front_left_r_controller
name:wheel_front_right_l_joint
controller type:JointVelocityControllerNode
sub controller : wheel_front_right_l_controller
name:wheel_front_right_r_joint
controller type:JointVelocityControllerNode
sub controller : wheel_front_right_r_controller
name:wheel_rear_left_l_joint
controller type:JointVelocityControllerNode
sub controller : wheel_rear_left_l_controller
name:wheel_rear_left_r_joint
controller type:JointVelocityControllerNode
sub controller : wheel_rear_left_r_controller
name:wheel_rear_right_l_joint
controller type:JointVelocityControllerNode
sub controller : wheel_rear_right_l_controller
name:wheel_rear_right_r_joint
controller type:JointVelocityControllerNode
sub controller : wheel_rear_right_r_controller
name:caster_front_left_joint
controller type:JointVelocityControllerNode
sub controller : caster_front_left_controller
name:caster_front_right_joint
controller type:JointVelocityControllerNode
sub controller : caster_front_right_controller
name:caster_rear_left_joint
controller type:JointVelocityControllerNode
sub controller : caster_rear_left_controller
name:caster_rear_right_joint
controller type:JointVelocityControllerNode
sub controller : caster_rear_right_controller
WARNING: Should chain be defined here?
WARNING: Should chain be defined here?
Loading /u/mcgann/pr/robot_descriptions/gazebo_robot_description/world/gazebo_joints.xml
Gazebo does not know about a joint named "base_joint"
recv() failedResource temporarily unavailable
recv() failedResource temporarily unavailable
recv() failedResource temporarily unavailable
[gazebo-10] process has died
Accepting input scans...
Shutting down process monitor thread
tried to call unregisterPublisher on /world_3d_map, but an exception was thrown: [Error in XmlRpcClient::writeRequest: write error (Connection refused).]
tried to call unregisterSubscriber on /TransformArray, but an exception was thrown: [Error in XmlRpcClient::writeRequest: write error (Connection refused).]
[master] killing on exit
tried to call unregisterSubscriber on /localizedpose, but an exception was thrown: [Error in XmlRpcClient::writeRequest: write error (Connection refused).]
tried to call unregisterSubscriber on /mechanism_state, but an exception was thrown: [Error in XmlRpcClient::writeRequest: write error (Connection refused).]
tried to call unregisterSubscriber on /tilt_scan, but an exception was thrown: [Error in XmlRpcClient::writeRequest: write error (Connection refused).]
tried to call unregisterSubscriber on /cloud, but an exception was thrown: [Error in XmlRpcClient::writeRequest: write error (Connection refused).]
trex_fast: /u/mcgann/ros/core/roscpp/src/libros/node.cpp:634: void ros::node::vlog(ros::log_level_t, const char_, char_): Assertion `(false)' failed.
[mech.py-1] killing on exit
Traceback (most recent call last):
File "/u/mcgann/pr/controllers/robot_mechanism_controllers/scripts/control.py", line 31, in
controllers.set_controller(sys.argv[2], float(sys.argv[3]))
File "/u/mcgann/pr/controllers/robot_mechanism_controllers/src/robot_mechanism_controllers/controllers.py", line 20, in set_controller
rospy.wait_for_service(controller + '/set_command')
File "/u/mcgann/ros/core/rospy/src/rospy/client.py", line 368, in wait_for_service
while master.lookupService(service)[0] != 1 and not isShutdown():
File "/u/mcgann/ros/core/rospy/src/rospy/msproxy.py", line 89, in wrappedF
return f(_args, *_kwds)
File "/usr/lib/python2.5/xmlrpclib.py", line 1147, in call
return self.__send(self.__name, args)
File "/usr/lib/python2.5/xmlrpclib.py", line 1437, in __request
verbose=self.__verbose
File "/usr/lib/python2.5/xmlrpclib.py", line 1183, in request
self.send_content(h, request_body)
File "/usr/lib/python2.5/xmlrpclib.py", line 1297, in send_content
connection.endheaders()
File "/usr/lib/python2.5/httplib.py", line 856, in endheaders
self._send_output()
File "/usr/lib/python2.5/httplib.py", line 728, in _send_output
self.send(msg)
File "/usr/lib/python2.5/httplib.py", line 695, in send
self.connect()
File "/usr/lib/python2.5/httplib.py", line 679, in connect
raise socket.error, msg
socket.error: (111, 'Connection refused')

[mech.py-1] escalating to SIGTERM
[mech.py-1] escalating to SIGKILL
[control.py-2] killing on exit
[map_server-3] killing on exit
[amcl_player-4] killing on exit
[world_3d_map-5] killing on exit
[kinematic_planning-6] killing on exit
[wavefront_player-7] killing on exit
[move_arm-8] killing on exit
[nav_view-9] killing on exit
[trex_fast-11] killing on exit
done
mcgann@bcn:/pr/highlevel/executive_trex/executive_trex_pr2/arm.0$
mcgann@bcn:/pr/highlevel/executive_trex/executive_trex_pr2/arm.0$
mcgann@bcn:/pr/highlevel/executive_trex/executive_trex_pr2/arm.0$ vi
2008.267.1/ 2008.267.12/ 2008.267.2/ 2008.267.5/ 2008.267.8/ 2008.268.2/ 2008.268.5/ Debug.log launch.xml pr2.exec.nddl
2008.267.10/ 2008.267.13/ 2008.267.3/ 2008.267.6/ 2008.267.9/ 2008.268.3/ clock.log frames_0/ logfile.xml pr2.exec.xml
2008.267.11/ 2008.267.14/ 2008.267.4/ 2008.267.7/ 2008.268.1/ 2008.268.4/ Debug.cfg latest/ Ogre.log .svn/
mcgann@bcn:/pr/highlevel/executive_trex/executive_trex_pr2/arm.0$ vi launch.xml
mcgann@bcn:~/pr/highlevel/executive_trex/executive_trex_pr2/arm.0$
}}}

[ahendrix]

[hsu] core dump yields BaseController's member variable robot_state_->model_ == null
at spawn time:

{{{
#0 0xb1a0b879 in mechanism::RobotState::getJointState (this=0x0, name=@0xab8ff074) at /u/johnhsu/projects/pr2/mechanism/mechanism_model/src/robot.cpp:206
where
206 int i = model_->getJointIndex(name);
(gdb) where
#0 0xb1a0b879 in mechanism::RobotState::getJointState (this=0x0, name=@0xab8ff074) at /u/johnhsu/projects/pr2/mechanism/mechanism_model/src/robot.cpp:206
#1 0xb1e5f45b in controller::BaseController::init (this=0xab933ca8, jcp=@0xab8ff120, robot_state=0x0) at /u/johnhsu/projects/pr2/controllers/pr2_mechanism_controllers/src/base_controller.cpp:122
#2 0xb1e6014e in controller::BaseController::initXml (this=0xab933ca8, robot_state=0x0, config=0x8e4e680) at /u/johnhsu/projects/pr2/controllers/pr2_mechanism_controllers/src/base_controller.cpp:239
#3 0xb1e5e060 in controller::BaseControllerNode::initXml (this=0xab933b60, robot_state=0x0, config=0x8e4e680) at /u/johnhsu/projects/pr2/controllers/pr2_mechanism_controllers/src/base_controller.cpp:566
#4 0xb1dc20e2 in MechanismControl::spawnController (this=0x8dea2f0, type=@0xab8ff2cc, name=@0xab8ff2c8, config=0x8e4e680)
at /u/johnhsu/projects/pr2/mechanism/mechanism_control/src/mechanism_control.cpp:144
#5 0xb1dc23aa in MechanismControlNode::spawnController (this=0x8dea668, req=@0x8e0ce98, resp=@0x8dfb678) at /u/johnhsu/projects/pr2/mechanism/mechanism_control/src/mechanism_control.cpp:345
#6 0xb1dc75d1 in ros::srvFunctor<MechanismControlNode, mechanism_control::SpawnController::request, mechanism_control::SpawnController::response>::call (this=0x8e0d8f0, req=0x8e0ce98, res=0x8dfb678)
at /u/johnhsu/projects/ros/core/roscpp/include/ros/node.h:95
#7 0xb0dd0c33 in ros::ServiceServer::read (this=0x8e0d8f8) at /u/johnhsu/projects/ros/core/roscpp/src/libros/service_server.cpp:278
#8 0xb0dd0deb in ros::ServiceServer::service_server_thread_func (this=0x8e0d8f8) at /u/johnhsu/projects/ros/core/roscpp/src/libros/service_server.cpp:92
#9 0xb0dd0eab in ros::ServiceServer::s_service_server_thread_func (parent=0x8e0d8f8) at /u/johnhsu/projects/ros/core/roscpp/src/libros/service_server.cpp:111
#10 0xb701fe5a in start_thread () from /lib/libpthread.so.0
#11 0xab8ff450 in ?? ()
#12 0xab8ff450 in ?? ()
#13 0xab8ff450 in ?? ()
#14 0xab8ff450 in ?? ()
#15 0x00000000 in ?? ()
(gdb) p model_
Cannot access memory at address 0x0
(gdb)
}}}

[ahendrix]

[hsu] between gdb steps #3 and #4,
during the call mechanism_control.cpp:144 to initXml in base_controller.cpp, state_ appears valid in mechanism_control.cpp, but is NULL in base_controller.cpp:566. See attached core.5294

[ahendrix]

[hsu] sorry, core dump too large (119M). email me if you want a copy.

[ahendrix]

[hsu] appears to be working after proper destruction of Plugins, Mechanism and Controller Nodes.