search

osrf / srcsim

Space Robotics Challenge
Other
9 stars 4 forks source link

controller manager dies #6

Closed osrf-migration closed 7 years ago

osrf-migration commented 7 years ago

Original report (archived issue) by dan (Bitbucket: dan77062).

The original report had attachments: master.log, roslaunch-Mingo-Mtn-Robotics-24044.log, control_py_Mingo_Mtn_Robotics_24044_828331878780894790-3-stdout.log, roslaunch-Mingo-Mtn-Robotics-24096.log, rosout.log, rosout-1-stdout.log

The controller manager crashes as it tries to initialize the hardware interface. This continues after updating with the fix for the $HOME/valkyrie directory missing issue (issue #4). See the log below.

I am wondering if it is a race condition. It will load when gazebo_gui seg faults (that happens about 20% of the time). Log of that follows the controller manager crash log.

Here is the log of the controller manager crashing:

x1:~$ roslaunch srcsim qual2.launch extra_gazebo_args:="-r" init:="true"
... logging to /home/dbarry/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/roslaunch-x1-2380.log
Checking log directory for disk usage. This may take awhile.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.

started roslaunch server http://127.0.0.1:41208/

SUMMARY
========

PARAMETERS
 * /ihmc_ros/robot_name: valkyrie
 * /ihmc_ros/valkyrie/left_arm_joint_names: ['leftShoulderPit...
 * /ihmc_ros/valkyrie/left_foot_frame_name: leftFoot
 * /ihmc_ros/valkyrie/right_arm_joint_names: ['rightShoulderPi...
 * /ihmc_ros/valkyrie/right_foot_frame_name: rightFoot
 * /ihmc_valkyrie_control_java_bridge/jvm_args: -Djava.class.path...
 * /ihmc_valkyrie_control_java_bridge/main_class: us.ihmc.valkyrieR...
 * /ihmc_valkyrie_control_java_bridge/type: ihmc_ros_control/...
 * /ihmc_valkyrie_control_java_bridge/working_dir: /home/dbarry/valk...
 * /joint_state_controller/publish_rate: 50
 * /joint_state_controller/type: joint_state_contr...
 * /robot_description: <?xml version="1....
 * /rosdistro: indigo
 * /rosversion: 1.11.20
 * /use_sim_time: True
 * /valkyrie/robot_description: <?xml version="1....

NODES
  /
    IHMCValkyrieROSAPI (ihmc_ros_java_adapter/gradlew)
    control_py_x1_2380_7570232152004045897 (robonet_tools/control)
    controller_manager_x1_2380_5207285626105591507 (val_deploy/delayed_roslaunch.sh)
    controller_spawner_x1_2380_1851790389431894578 (controller_manager/spawner)
    gazebo (gazebo_ros/gzserver)
    gazebo_gui (gazebo_ros/gzclient)
    robot_state_publisher (robot_state_publisher/state_publisher)
    smtcore_x1_2380_2977631580949370987 (shared_memory_transport/smtcore)
    startup_robot (srcsim/init_robot.sh)
    urdf_spawner_x1_2380_8262126648062010210 (val_deploy/delayed_roslaunch.sh)

auto-starting new master
process[master]: started with pid [2415]
ROS_MASTER_URI=http://localhost:11311

setting /run_id to dcf01448-a48a-11e6-9a85-e4a47193b50c
process[rosout-1]: started with pid [2428]
started core service [/rosout]
process[smtcore_x1_2380_2977631580949370987-2]: started with pid [2439]
process[control_py_x1_2380_7570232152004045897-3]: started with pid [2448]
delaying: 4 seconds
process[controller_manager_x1_2380_5207285626105591507-4]: started with pid [2454]
process[gazebo-5]: started with pid [2456]
process[gazebo_gui-6]: started with pid [2460]
delaying: 6 seconds
process[urdf_spawner_x1_2380_8262126648062010210-7]: started with pid [2464]
process[robot_state_publisher-8]: started with pid [2466]
process[IHMCValkyrieROSAPI-9]: started with pid [2470]
process[controller_spawner_x1_2380_1851790389431894578-10]: started with pid [2472]
wait 60s for system to load
process[startup_robot-11]: started with pid [2480]
Log file /home/dbarry/.log already exists, proceeding...
Log file /home/dbarry/.log already exists, proceeding...
Gazebo multi-robot simulator, version 7.4.0
Copyright (C) 2012-2016 Open Source Robotics Foundation.
Released under the Apache 2 License.
http://gazebosim.org

[ INFO] [1478482701.248677300]: Finished loading Gazebo ROS API Plugin.
[Msg] Waiting for master.
[ INFO] [1478482701.250145508]: waitForService: Service [/gazebo/set_physics_properties] has not been advertised, waiting...
[Msg] Connected to gazebo master @ http://127.0.0.1:11345
[Msg] Publicized address: 192.168.1.227
[INFO] [WallTime: 1478482701.451136] [0.000000] Controller Spawner: Waiting for service controller_manager/load_controller
[ INFO] [1478482702.712379193, 0.024000000]: waitForService: Service [/gazebo/set_physics_properties] is now available.
[ INFO] [1478482702.788134648, 0.075000000]: Physics dynamic reconfigure ready.
starting: roslaunch val_deploy val_control_sim.launch controller_manager_looprate:=500 __name:=controller_manager_x1_2380_5207285626105591507 __log:=/home/user/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/controller_manager_x1_2380_5207285626105591507-4.log
... logging to /home/user/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/roslaunch-x1-2740.log
Checking log directory for disk usage. This may take awhile.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.

> Loading > buildSrcstarted roslaunch server http://127.0.0.1:46157/

SUMMARY
========

PARAMETERS
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    controller_manager_x1_2740_5196629567473667321 (val_controller_manager_rtt/controller_exec)

ROS_MASTER_URI=http://localhost:11311

core service [/rosout] found
process[controller_manager_x1_2740_5196629567473667321-1]: started with pid [2765]
exception subscribing to JointAPS_Angle_Rad : /pelvis/waist/JointAPS_Angle_Rad has not been registered.
exception subscribing to JointAPS_Vel_Radps : /pelvis/waist/JointAPS_Vel_Radps has not been registered.
exception subscribing to JointTorque_Des_Nm : /pelvis/waist/JointTorque_Des_Nm has not been registered.
exception subscribing to JointTorque_Meas_Nm : /pelvis/waist/JointTorque_Meas_Nm has not been registered.
exception subscribing to Position_Des_Rad : /pelvis/waist/Position_Des_Rad has not been registered.
exception subscribing to Velocity_Des_Radps : /pelvis/waist/Velocity_Des_Radps has not been registered.
2016-11-06 20:38:26 localhost ncl_cpp: [ERROR   ] [gov.nasa.RobotInterface.addJointsAndActuators] Exception encountered while attempting to add an actuator! Check your URDF for correct XML formatting!
[ERROR] [1478482706.638611814, 3.792000000]:  Exception encountered while attempting to add an actuator! Check your URDF for correct XML formatting!
2016-11-06 20:38:26 localhost ncl_cpp: [ERROR   ] [gov.nasa.HardwareInterface.makeHandle] Robot Hardware has failed Initialized properly. 

[ERROR] [1478482706.638921238, 3.792000000]: Fatal exception error encountered initializing RobotHardwareInterface, exiting
2016-11-06 20:38:26 localhost ncl_cpp: [FATAL   ] [gov.nasa.ControllerExec.ORO_main] Error encountered during configure hook for controller_manager component!
starting: roslaunch val_gazebo spawn_urdf_model_from_robot_description.launch modelName:=valkyrie zOffset:=1.25 __name:=urdf_spawner_x1_2380_8262126648062010210 __log:=/home/dbarry/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/urdf_spawner_x1_2380_8262126648062010210-7.log
================================================================================REQUIRED process [controller_manager_x1_2740_5196629567473667321-1] has died!
process has died [pid 2765, exit code 1, cmd /opt/nasa/indigo/lib/val_controller_manager_rtt/controller_exec --rate 500 -s __name:=controller_manager_x1_2740_5196629567473667321 __log:=/home/dbarry/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/controller_manager_x1_2740_5196629567473667321-1.log].
log file: /home/dbarry/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/controller_manager_x1_2740_5196629567473667321-1*.log
Initiating shutdown!
================================================================================
[controller_manager_x1_2740_5196629567473667321-1] killing on exit
shutting down processing monitor...
... shutting down processing monitor complete
done
[controller_manager_x1_2380_5207285626105591507-4] process has finished cleanly
log file: /home/dbarry/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/controller_manager_x1_2380_5207285626105591507-4*.log
... logging to /home/dbarry/.ros/log/dcf01448-a48a-11e6-9a85-e4a47193b50c/roslaunch-x1-2818.log
Checking log directory for disk usage. This may take awhile.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.

started roslaunch server http://127.0.0.1:43638/

Here the controller manager loads after gazebo_gui seg faults:

.............
core service [/rosout] found
process[controller_manager_x1_8269_8854522228583915511-1]: started with pid [8294]
Segmentation fault (core dumped)
[gazebo_gui-6] process has died [pid 7984, exit code 139, cmd /opt/ros/indigo/lib/gazebo_ros/gzclient __name:=gazebo_gui __log:=/home/dbarry/.ros/log/c00f0c74-a491-11e6-b149-e4a47193b50c/gazebo_gui-6.log].
log file: /home/dbarry/.ros/log/c00f0c74-a491-11e6-b149-e4a47193b50c/gazebo_gui-6*.log
starting: roslaunch val_gazebo spawn_urdf_model_from_robot_description.launch modelName:=valkyrie zOffset:=1.25 __name:=urdf_spawner_x1_7927_4442223900582953886 __log:=/home/dbarry/.ros/log/c00f0c74-a491-11e6-b149-e4a47193b50c/urdf_spawner_x1_7927_4442223900582953886-7.log
2016-11-06 21:27:44 localhost ncl_cpp: [NOTICE  ] [gov.nasa.HardwareInterface.makeHandle] Robot Hardware has Initialized. Ready to start loading Controllers. 

[INFO] [WallTime: 1478485664.666343] [4.582000] Controller Spawner: Waiting for service controller_manager/switch_controller
[INFO] [WallTime: 1478485664.669229] [4.585000] Controller Spawner: Waiting for service controller_manager/unload_controller
[INFO] [WallTime: 1478485664.671889] [4.588000] Loading controller: ihmc_valkyrie_control_java_bridge
[ INFO] [1478485664.756112539, 4.672000000]: Starting JVM with arguments: -Djava.class.path=ValkyrieController.jar -XX:+UseSerialGC -Xmx4g -Xms4g -XX:NewSize=3g -XX:MaxNewSize=3g -XX:CompileThreshold=1000 -verbosegc -Djava.library.path=lib/
Starting Java VM from path  /home/dbarry/valkyrie
Started Java VM: success
osrf-migration commented 7 years ago

Original comment by Nate Koenig (Bitbucket: Nathan Koenig).

Issue #21 was marked as a duplicate of this issue.

osrf-migration commented 7 years ago

Original comment by kapoor_amita@yahoo.com (Bitbucket: Amita94).

Attached is the roslaunch log and rqt_graph image when val falls (90% of time)rosgraph_qual1.png

Script started on Monday 21 November 2016 10:54:55 PM IST ... logging to /home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/roslaunch-am-Macmini-10908.log Checking log directory for disk usage. This may take awhile. Press Ctrl-C to interrupt Done checking log file disk usage. Usage is <1GB. ]2;/opt/ros/indigo/share/srcsim/launch/qual1.launch started roslaunch server http://am-Macmini:35969/

SUMMARY

PARAMETERS

NODES / IHMCValkyrieROSAPI (ihmc_ros_java_adapter/gradlew) control_py_am_Macmini_10908_6429243349245551040 (robonet_tools/control) controller_manager_am_Macmini_10908_1874398186530051490 (val_deploy/delayed_roslaunch.sh) controller_spawner_am_Macmini_10908_2491801057726095336 (controller_manager/spawner) gazebo (gazebo_ros/gzserver) gazebo_gui (gazebo_ros/gzclient) robot_state_publisher (robot_state_publisher/state_publisher) smtcore_am_Macmini_10908_3371504248313502897 (shared_memory_transport/smtcore) startup_robot (srcsim/init_robot.sh) urdf_spawner_am_Macmini_10908_1798110691714769919 (val_deploy/delayed_roslaunch.sh)

auto-starting new master process[master]: started with pid [10920] ROS_MASTER_URI=http://localhost:11311 ]2;/opt/ros/indigo/share/srcsim/launch/qual1.launch http://localhost:11311 setting /run_id to 6b65e308-b00f-11e6-af54-685b35a00088 process[rosout-1]: started with pid [10933] started core service [/rosout] process[smtcore_am_Macmini_10908_3371504248313502897-2]: started with pid [10952] process[control_py_am_Macmini_10908_6429243349245551040-3]: started with pid [10958] process[controller_manager_am_Macmini_10908_1874398186530051490-4]: started with pid [10959] delaying: 4 seconds process[gazebo-5]: started with pid [10961] process[gazebo_gui-6]: started with pid [10965] process[urdf_spawner_am_Macmini_10908_1798110691714769919-7]: started with pid [10969] delaying: 6 seconds process[robot_state_publisher-8]: started with pid [10971] process[IHMCValkyrieROSAPI-9]: started with pid [10972] process[controller_spawner_am_Macmini_10908_2491801057726095336-10]: started with pid [10976] wait 60s for system to load process[startup_robot-11]: started with pid [10996] Log file /home/am/.log already exists, proceeding... Log file /home/am/.log already exists, proceeding... Gazebo multi-robot simulator, version 7.4.0 Copyright (C) 2012-2016 Open Source Robotics Foundation. Released under the Apache 2 License. http://gazebosim.org

[ INFO] [1479749096.239155720]: Finished loading Gazebo ROS API Plugin. [Msg] Waiting for master. [ INFO] [1479749096.240310704]: waitForService: Service [/gazebo/set_physics_properties] has not been advertised, waiting... [Msg] Connected to gazebo master @ http://127.0.0.1:11345 [Msg] Publicized address: 192.168.1.3 [INFO] [WallTime: 1479749096.518506] [0.000000] Controller Spawner: Waiting for service controller_manager/load_controller > Loading > buildSrc > settings[ INFO] [1479749097.601352082, 0.022000000]: waitForService: Service [/gazebo/set_physics_properties] is now available. [ INFO] [1479749097.677227218, 0.088000000]: Physics dynamic reconfigure ready.  > Resolving dependencies ':runtime' > Resolving dependencies 'detachedConfiguration1' > :buildSrc:compileJava:buildSrc:compileJava > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:compileGroovy > Resolving dependencies ':compi:buildSrc:compileGroovy > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:processResources:buildSrc:processResources > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:classes:buildSrc:classes > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:jar:buildSrc:jar > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:assemble:buildSrc:assemble > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:compileTestJava:buildSrc:compileTestJava > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:compileTestGroovy:buildSrc:compileTestGroovy > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:processTestResources:buildSrc:processTestResources > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:testClasses:buildSrc:testClasses > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:test:buildSrc:test > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:check:buildSrc:check > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > :buildSrc:build:buildSrc:build > Loading > buildSrcUP-TO-DATE > Loading > buildSrc > Loading > buildSrc > settingsConfiguring > 0/1 projects > root project > Resolving dependencies ':classpatstarting: roslaunch val_deploy val_control_sim.launch controller_manager_looprate:=500 __name:=controller_manager_am_Macmini_10908_1874398186530051490 __log:=/home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/controller_manager_am_Macmini_10908_1874398186530051490-4.log  > Resolving dependencies ':ros'... logging to /home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/roslaunch-am-Macmini-11267.log Checking log directory for disk usage. This may take awhile. Press Ctrl-C to interrupt Done checking log file disk usage. Usage is <1GB. ]2;/opt/nasa/indigo/share/val_deploy/launch/val_control_sim.launch started roslaunch server http://am-Macmini:36884/

SUMMARY

PARAMETERS

NODES / controller_manager_am_Macmini_11267_3514388487941572722 (val_controller_manager_rtt/controller_exec)

ROS_MASTER_URI=http://localhost:11311 ]2;/opt/nasa/indigo/share/val_deploy/launch/val_control_sim.launch http://localhost:11311 core service [/rosout] found process[controller_manager_am_Macmini_11267_3514388487941572722-1]: started with pid [11288] 1/1 projects> Building 0% > :parseYaml:parseYaml > Building 0%UP-TO-DATE > Building 0% > Building 0%50% > :runJavaDelegate2016-11-21 22:55:01 localhost ncl_cpp: [NOTICE ] [gov.nasa.HardwareInterface.makeHandle] Robot Hardware has Initialized. Ready to start loading Controllers.

[INFO] [WallTime: 1479749101.652679] [4.037000] Controller Spawner: Waiting for service controller_manager/switch_controller [INFO] [WallTime: 1479749101.654604] [4.039000] Controller Spawner: Waiting for service controller_manager/unload_controller [INFO] [WallTime: 1479749101.656461] [4.041000] Loading controller: ihmc_valkyrie_control_java_bridge [ INFO] [1479749101.704968226, 4.091000000]: Starting JVM with arguments: -Djava.class.path=ValkyrieController.jar -XX:+UseSerialGC -Xmx4g -Xms4g -XX:NewSize=3g -XX:MaxNewSize=3g -XX:CompileThreshold=1000 -verbosegc -Djava.library.path=lib/ Starting Java VM from path /home/am/valkyrie :runJavaDelegate > Building 50% > :runJavaDelegateLoading robot model from: 'models/val_description/sdf/valkyrie_sim.sdf' > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegateStarted Java VM: success starting: roslaunch val_gazebo spawn_urdf_model_from_robot_description.launch modelName:=valkyrie zOffset:=1.25 __name:=urdf_spawner_am_Macmini_10908_1798110691714769919 __log:=/home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/urdf_spawner_am_Macmini_10908_1798110691714769919-7.log [ERROR] [1479749102.135462500, 4.519000000]: Nov 21, 2016 10:55:01 PM us.ihmc.valkyrieRosControl.ValkyrieAffinity  [ERROR] [1479749102.135513883, 4.519000000]: SEVERE: WARNING: Hyper-Threading is enabled. Expect higher amounts of jitter ... logging to /home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/roslaunch-am-Macmini-11410.log Checking log directory for disk usage. This may take awhile. Press Ctrl-C to interrupt Done checking log file disk usage. Usage is <1GB. ]2;/opt/nasa/indigo/share/val_gazebo/launch/spawn_urdf_model_from_robot_description.launch [ INFO] [1479749102.303692115, 4.675000000]: Loading robot model from: 'models/val_description/sdf/valkyrie_sim.sdf' started roslaunch server http://am-Macmini:35999/

SUMMARY

PARAMETERS

NODES / urdf_spawner (gazebo_ros/spawn_model)

ROS_MASTER_URI=http://localhost:11311 ]2;/opt/nasa/indigo/share/val_gazebo/launch/spawn_urdf_model_from_robot_description.launch http://localhost:11311 core service [/rosout] found process[urdf_spawner-1]: started with pid [11429] [INFO] (NetworkParameters.java:38): Looking for network parameters in network parameters file at /opt/ros/indigo/share/ihmc_valkyrie_ros/configurations/IHMCNetworkParametersSim.ini > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[INFO] (NetworkParameters.java:42): Found Network parameters file at /opt/ros/indigo/share/ihmc_valkyrie_ros/configurations/IHMCNetworkParametersSim.ini > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[INFO] (NetworkParameters.java:69): Looking for network parameters in environment variables > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[INFO] (NetworkParameters.java:70): Environment variables will override entries in the network parameters file. > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegatespawn_model script started [INFO] [WallTime: 1479749103.066184] [0.000000] Loading model xml from ros parameter [INFO] [WallTime: 1479749103.094208] [5.463000] Waiting for service /gazebo/spawn_urdf_model [INFO] [WallTime: 1479749103.097863] [5.470000] Calling service /gazebo/spawn_urdf_model Connecting to controller using TCP on localhost > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegateWarning [parser.cc:778] XML Element[imuTransform], child of element[sensor] not defined in SDF. Ignoring[imuTransform]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[node], child of element[sensor] not defined in SDF. Ignoring[node]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[api], child of element[sensor] not defined in SDF. Ignoring[api]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[port], child of element[sensor] not defined in SDF. Ignoring[port]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[imuTransform], child of element[sensor] not defined in SDF. Ignoring[imuTransform]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[node], child of element[sensor] not defined in SDF. Ignoring[node]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[api], child of element[sensor] not defined in SDF. Ignoring[api]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[port], child of element[sensor] not defined in SDF. Ignoring[port]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[sensor_number], child of element[sensor] not defined in SDF. Ignoring[sensor_number]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[node], child of element[sensor] not defined in SDF. Ignoring[node]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[api], child of element[sensor] not defined in SDF. Ignoring[api]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[sensor_number], child of element[sensor] not defined in SDF. Ignoring[sensor_number]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[node], child of element[sensor] not defined in SDF. Ignoring[node]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[api], child of element[sensor] not defined in SDF. Ignoring[api]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[imuTransform], child of element[sensor] not defined in SDF. Ignoring[imuTransform]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[node], child of element[sensor] not defined in SDF. Ignoring[node]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[api], child of element[sensor] not defined in SDF. Ignoring[api]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. Warning [parser.cc:778] XML Element[port], child of element[sensor] not defined in SDF. Ignoring[port]. You may have an incorrect SDF file, or an sdformat version that doesn't support this element. [WARN] YoVariable: desiredMomentumRateLinearX is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: desiredMomentumRateLinearY is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: desiredMomentumRateLinearZ is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: achievedMomentumRateLinearX is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: achievedMomentumRateLinearY is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: achievedMomentumRateLinearZ is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: residualRootJointForceX is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: residualRootJointForceY is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: residualRootJointForceZ is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: residualRootJointTorqueX is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: residualRootJointTorqueY is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[WARN] YoVariable: residualRootJointTorqueZ is getting created with a null registry > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegate[ INFO] [1479749104.454163884, 5.569000000]: Camera Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/' [ INFO] [1479749104.454444886, 5.569000000]: Camera Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/' [ INFO] [1479749104.460090991, 5.569000000]: Camera Plugin (ns = /) , set to "" [ INFO] [1479749104.465452994, 5.569000000]: Camera Plugin (ns = /) , set to "" [ INFO] [1479749104.478498956, 5.569000000]: Laser Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/' [ INFO] [1479749104.478659556, 5.569000000]: Starting GazeboRosLaser Plugin (ns = /)! [ INFO] [1479749104.525147605, 5.569000000]: GPU Laser Plugin (ns = /) , set to "" [ INFO] [1479749104.532458453, 5.569000000]: LoadThread function completed [1;33[ INFO] [1479749104.646495418, 5.569000000]: [INFO] (NetworkParameters.java:38): Looking for network parameters in network parameters file at /home/am/.ihmc/IHMCNetworkParameters.ini [ INFO] [1479749104.646817999, 5.569000000]: [INFO] (NetworkParameters.java:42): Found Network parameters file at /home/am/.ihmc/IHMCNetworkParameters.ini [ INFO] [1479749104.647547883, 5.569000000]: [INFO] (NetworkParameters.java:69): Looking for network parameters in environment variables [ INFO] [1479749104.647840085, 5.569000000]: [INFO] (NetworkParameters.java:70): Environment variables will override entries in the network parameters file. m[Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[multicamera] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[gpu_ray] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[force_torque] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[force_torque] not suppported. [INFO] [WallTime: 1479749104.661252] [5.569000] Spawn status: SpawnModel: Successfully spawned model Attaching native thread 11556 with priority 45 to JVM [urdf_spawner-1] process has finished cleanly log file: /home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/urdf_spawner-1.log all processes on machine have died, roslaunch will exit log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar). > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegatelog4j:WARN Please initialize the log4j system properly. > Building 50% > :runJavaDelegate[Wrn] [ColladaLoader.cc:1461] Polylist input semantic: 'COLOR' is currently not supported shutting down processing monitor... ... shutting down processing monitor complete done [Wrn] [msgs.cc:1793] Conversion of sensor type[force_torque] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[force_torque] not suppported. [ INFO] [1479749105.195264440, 5.569000000]: SharedMemoryInterfacePlugin: Loading 2016-11-21 22:55:05 localhost ncl_cpp: [ERROR ] [gov.nasa.SharedMemorySimInterfacePlugin.findUrdfSensors] Possibly missing an api or node tag from one or more imu sensors 2016-11-21 22:55:05 localhost ncl_cpp: [WARN ] [gov.nasa.SharedMemorySimInterfacePlugin.findUrdfSensors] Imu sensor head_imu_sensor doesn't have tag. It is likely that the data you receive from this sensor will be incorrect. [urdf_spawner_am_Macmini_10908_1798110691714769919-7] process has finished cleanly log file: /home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/urdf_spawner_am_Macmini_10908_1798110691714769919-7.log [ INFO] [1479749105.276313036, 5.569000000]: SharedMemorySimInterfacePlugin: Loading complete! [ INFO] [1479749105.290096303, 5.569000000]: Looking for forceSensorDefinition leftAnkleRoll [ INFO] [1479749105.299745479, 5.569000000]: Looking for forceSensorDefinition rightAnkleRoll [ INFO] [1479749105.753387095, 5.569000000]: imu plugin missing , defaults to  [ INFO] [1479749105.755447446, 5.569000000]: imu plugin missing , defaults to  [ INFO] [1479749105.755545821, 5.569000000]: imu plugin missing , defaults to  [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[imu] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[multicamera] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[gpu_ray] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[force_torque] not suppported. [Wrn] [msgs.cc:1793] Conversion of sensor type[force_torque] not suppported. IHMC ROS API node successfully started. > Building 50% > :runJavaDelegate[ INFO] [1479749108.207315868, 6.057000000]: IMUBasedPelvisRotationalStateUpdater: More than 1 IMU sensor, using only the first one: pelvis_pelvisRearImu [ INFO] [1479749108.257770228, 6.067000000]: PelvisIMUBasedLinearStateCalculator: More than 1 IMU sensor, using only the first one: pelvis_pelvisRearImu Attaching native thread 12575 with priority 45 to JVM [INFO] (KryoObjectClient.java:130): Success! Connected KryoClient to SCS at ip localhost/127.0.0.1 on port 4895 > Building 50% > :runJavaDelegate[ INFO] [1479749110.348349984, 6.491000000]: [INFO] (LogSessionBroadcaster.java:66): Announcing logging session on: name:lo (lo) [ INFO] [1479749110.378289952, 6.497000000]: [INFO] (LogSessionBroadcaster.java:307): Trying port 56356 Attaching native thread 12593 with priority 40 to JVM [ INFO] [1479749115.343440958, 7.641000000]: [INFO] (ValkyrieRosControlController.java:307): Running with blocking synchronous execution between estimator and controller [INFO] [WallTime: 1479749115.625541] [7.712000] Controller Spawner: Loaded controllers: ihmc_valkyrie_control_java_bridge [INFO] [WallTime: 1479749116.014584] [7.812000] Started controllers: ihmc_valkyrie_control_java_bridge [ INFO] [1479749116.014888192, 7.812000000]: Setting estimator thread affinity to processor 1 lower harness publishing and latching message for 3.0 seconds switch to high level control after 20 seconds publishing and latching message for 3.0 seconds detach in 5 seconds done [startup_robot-11] process has finished cleanly log file: /home/am/.ros/log/6b65e308-b00f-11e6-af54-685b35a00088/startup_robot-11*.log publishing and latching message for 3.0 seconds ^C[controller_spawner_am_Macmini_10908_2491801057726095336-10] killing on exit [IHMCValkyrieROSAPI-9] killing on exit [robot_state_publisher-8] killing on exit [gazebo_gui-6] killing on exit [INFO] [WallTime: 1479749266.956910] [26.880000] Shutting down spawner. Stopping and unloading controllers... [control_py_am_Macmini_10908_6429243349245551040-3] killing on exit [gazebo-5] killing on exit [controller_manager_am_Macmini_10908_1874398186530051490-4] killing on exit [smtcore_am_Macmini_10908_3371504248313502897-2] killing on exit Could not read error output of: command '/usr/lib/jvm/java-8-openjdk-amd64/bin/java'. > Building 50% > :runJavaDelegate > Building 50% > :runJavaDelegatejava.io.IOException: Stream closed > Building 50% > :runJavaDelegate at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) > Building 50% > :runJavaDelegate at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) > Building 50% > :runJavaDelegate at java.io.BufferedInputStream.read(BufferedInputStream.java:345) > Building 50% > :runJavaDelegate at java.io.FilterInputStream.read(FilterInputStream.java:107) > Building 50% > :runJavaDelegate at org.gradle.process.internal.streams.ExecOutputHandleRunner.run(ExecOutputHandleRunner.java:51) > Building 50% > :runJavaDelegate at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54) > Building 50% > :runJavaDelegate at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40) > Building 50% > :runJavaDelegate at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) > Building 50% > :runJavaDelegate at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) > Building 50% > :runJavaDelegate at java.lang.Thread.run(Thread.java:745) > Building 50% > :runJavaDelegate[controller_manager_am_Macmini_11267_3514388487941572722-1] killing on exit 2016-11-21 22:57:47 localhost ncl_cpp: [FATAL ] [gov.nasa.ControllerExec.ORO_main] Controller manager has stopped running! Stopping controller exec. #

A fatal error has been detected by the Java Runtime Environment:

#

SIGSEGV (0xb) at pc=0x00007fa8709bec4a, pid=11288, tid=140361427134400

#

JRE version: OpenJDK Runtime Environment (7.0_121) (build 1.7.0_121-b00)

Java VM: OpenJDK 64-Bit Server VM (24.121-b00 mixed mode linux-amd64 compressed oops)

Derivative: IcedTea 2.6.8

Distribution: Ubuntu 14.04 LTS, package 7u121-2.6.8-1ubuntu0.14.04.1

Problematic frame:

C [liborocos-rtt-gnulinux.so.2.8+0x159c4a] RTT::ComponentLoader::unloadComponent(RTT::TaskContext*)+0x6a

#

Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again

#

An error report file with more information is saved as:

/home/am/.ros/hs_err_pid11288.log

pure virtual method called terminate called without an active exception shutting down processing monitor... ... shutting down processing monitor complete done [controller_spawner_am_Macmini_10908_2491801057726095336-10] escalating to SIGTERM [IHMCValkyrieROSAPI-9] escalating to SIGTERM [gazebo-5] escalating to SIGTERM [controller_spawner_am_Macmini_10908_2491801057726095336-10] escalating to SIGKILL [IHMCValkyrieROSAPI-9] escalating to SIGKILL [rosout-1] killing on exit [master] killing on exit Shutdown errors:

Script done on Monday 21 November 2016 10:58:04 PM IST

osrf-migration commented 7 years ago

Original comment by Jordan Lack (Bitbucket: jordanlack).

@Amita94 it looks like this is a separate issue than what this ticket was initially opened up to address. It's a bit difficult to parse through that output, but it sounds like you're having a problem with Valkyrie actually falling down in Gazebo, where this issue was created due to a crashing issue.

I am currently working on a release that includes a number of features including a fix for the crashing issue reported by a few users here(see top of this thread).

osrf-migration commented 7 years ago

Original comment by Franky Lau (Bitbucket: frankylau).

hi @JordanLack, sorry that I am not going to hurry you up, but just want to make it clear.

is the new release will address the 2 physical cores problem as @dljsjr described?

thanks.

osrf-migration commented 7 years ago

Original comment by Steve Peters (Bitbucket: Steven Peters, GitHub: scpeters).

Ok, everyone, IHMC has released a new version of their controller (version 0.8.1), and I've uploaded a new valkyrie_controller.tar.gz (step 10 in installation instructions), so please delete the ~/valkyrie folder and download the new one and extract it in its place. This should fix the issues with dual-core CPU's.

Can some folks test this out to see if it helps?

osrf-migration commented 7 years ago

Original comment by Nuttaworn Sujumnong (Bitbucket: nsujumnong).

Excellent. The controller works on my computer now. Also, I don't get hyperthreading error message any longer, which is kinda cool. Thank you!

osrf-migration commented 7 years ago

Original comment by dan (Bitbucket: dan77062).

It no longer has the IndexOutOfBoundsException, so the patch has solved the 2 core problem-- thanks! Unfortunately, the robot still collapses. Since I think that is due to other reasons, I put a comment along with output into issue #9 I think this issue (2 cores) is resolved.

osrf-migration commented 7 years ago

Original comment by Adam Allevato (Bitbucket: Kukanani).

The new controller definitely seems to have improved software stability. Good work.

osrf-migration commented 7 years ago

Original comment by dan (Bitbucket: dan77062).

The two core problem is solved-- thanks!