osrf / srcsim

Space Robotics Challenge
Other
9 stars 4 forks source link

Valkyrie Falling to Ground due to Java Exceptions #45

Closed osrf-migration closed 7 years ago

osrf-migration commented 7 years ago

Original report (archived issue) by Jake Webster (Bitbucket: TopGunSnake).


The robot is falling to ground, seemingly after seeing an exception from java.io:

#!

Dec 12, 2016 1:59:30 PM org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink
WARNING: Failed to accept a connection.
java.io.IOException: Too many open files
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
    at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink$Boss.run(NioServerSocketPipelineSink.java:238)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Dec 12, 2016 1:59:30 PM org.jboss.netty.channel.DefaultChannelPipeline
WARNING: An exception was thrown by a user handler while handling an exception event ([id: 0x5539fe9d] EXCEPTION: org.jboss.netty.channel.ChannelException: Failed to create a selector.)
org.ros.exception.RosRuntimeException: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.ros.internal.transport.ConnectionTrackingHandler.exceptionCaught(ConnectionTrackingHandler.java:81)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:166)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:111)
    at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:55)
    at org.jboss.netty.channel.Channels.connect(Channels.java:642)
    at org.jboss.netty.channel.AbstractChannel.connect(AbstractChannel.java:207)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:230)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:183)
    at org.ros.internal.transport.tcp.TcpClient.connect(TcpClient.java:101)
    at org.ros.internal.transport.tcp.TcpClientManager.connect(TcpClientManaa:69)av
    at org.ros.internal.node.topic.DefaultSubscriber.addPublisher(DefaultSubscriber.java:150)
    at org.ros.internal.node.topic.UpdatePublisherRunnable.run(UpdatePublisherRunnable.java:73)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:212)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:161)
    ... 13 more
Caused by: java.io.IOException: Too many open files
    at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
    at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
    at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
    at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
    at java.nio.channels.Selector.open(Selector.java:227)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:210)
    ... 14 more

Dec 12, 2016 1:59:30 PM org.jboss.netty.channel.DefaultChannelPipeline
WARNING: An exception was thrown by a user handler while handling an exception event ([id: 0xfabf3c0b] EXCEPTION: org.jboss.netty.channel.ChannelException: Failed to create a selector.)
org.ros.exception.RosRuntimeException: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.ros.internal.transport.ConnectionTrackingHandler.exceptionCaught(ConnectionTrackingHandler.java:81)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:166)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:111)
    at org.jboss.nettyr.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:55)
    at org.jboss.netty.channel.Channels.connect(Channels.java:642)
    at org.jboss.netty.channel.AbstractChannel.connect(AbstractChannel.java:207)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:230)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:183)
    at org.ros.internal.transport.tcp.TcpClient.connect(TcpClient.java:101)
    at org.ros.internal.transport.tcp.TcpClientManager.connect(TcpClientManager.java:69)
    at org.ros.internal.node.topic.DefaultSubscriber.addPublisher(DefaultSubscriber.java:150)
    at org.ros.internal.node.topic.UpdatePublisherRunnable.run(UpdatePublisherRunnable.java:73)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:212)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:161)
    ... 13 more
Caused by: java.io.IOException: Too many open files
    at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
    at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
    at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
    at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
    at java.nio.channels.Selector.open(Selector.java:227)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:210)
    ... 14 more

IHMC ROS API node successfully started.

I manually released the robot for this, giving ample time for the controller to come online. I have not manipulated the sleeps that occur earlier, though.

Also, I have yet to have a clean exit for either task.

System is Ubuntu 14.04.5 LTS, with 2x 6-core Intel Xeon, 64GB Ram.

Full console output is below:

#!

jake@ubuntu-SER3040:~$ roslaunch srcsim qual2.launch
... logging to /home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-2998.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:39060/

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/jake/valkyrie
 * /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_ubuntu_SER3040_2998_3691283938542798629 (robonet_tools/control)
    controller_manager_ubuntu_SER3040_2998_439239008329951092 (val_deploy/delayed_roslaunch.sh)
    controller_spawner_ubuntu_SER3040_2998_2114081573183867240 (controller_manager/spawner)
    gazebo (gazebo_ros/gzserver)
    gazebo_gui (gazebo_ros/gzclient)
    robot_state_publisher (robot_state_publisher/state_publisher)
    smtcore_ubuntu_SER3040_2998_714146815997592256 (shared_memory_transport/smtcore)
    urdf_spawner_ubuntu_SER3040_2998_6216829015108794449 (val_deploy/delayed_roslaunch.sh)

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

setting /run_id to 78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6
process[rosout-1]: started with pid [3023]
started core service [/rosout]
process[smtcore_ubuntu_SER3040_2998_714146815997592256-2]: started with pid [3026]
process[control_py_ubuntu_SER3040_2998_3691283938542798629-3]: started with pid [3031]
process[controller_manager_ubuntu_SER3040_2998_439239008329951092-4]: started with pid [3046]
delaying: 4 seconds
process[gazebo-5]: started with pid [3051]
process[gazebo_gui-6]: started with pid [3055]
process[urdf_spawner_ubuntu_SER3040_2998_6216829015108794449-7]: started with pid [3059]
delaying: 6 seconds
process[robot_state_publisher-8]: started with pid [3061]
process[IHMCValkyrieROSAPI-9]: started with pid [3066]
Log file /home/jake/.log already exists, proceeding...
process[controller_spawner_ubuntu_SER3040_2998_2114081573183867240-10]: started with pid [3083]
Log file /home/jake/.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] [1481572762.165274724]: Finished loading Gazebo ROS API Plugin.
[ INFO] [1481572762.165423319]: waitForService: Service [/gazebo/set_physics_properties] has not been advertised, waiting...
[Msg] Waiting for master.
[Msg] Connected to gazebo master @ http://127.0.0.1:11345
[Msg] Publicized address: 10.115.103.231
[INFO] [WallTime: 1481572762.297258] [0.000000] Controller Spawner: Waiting for service controller_manager/load_controller
[ INFO] [1481572762.885653917, 0.023000000]: waitForService: Service [/gazebo/set_physics_properties] is now available.
[ INFO] [1481572762.918781724, 0.055000000]: Physics dynamic reconfigure ready.
:buildSrc:compileJava UP-TO-DATE
:buildSrc:compileGroovy UP-TO-DATE
:buildSrc:processResources UP-TO-DATE
:buildSrc:classes UP-TO-DATE
:buildSrc:jar UP-TO-DATE
:buildSrc:assemble UP-TO-DATE
:buildSrc:compileTestJava UP-TO-DATE
:buildSrc:compileTestGroovy UP-TO-DATE
:buildSrc:processTestResources UP-TO-DATE
:buildSrc:testClasses UP-TO-DATE
:buildSrc:test UP-TO-DATE
:buildSrc:check UP-TO-DATE
:buildSrc:build UP-TO-DATE
> Loading > buildSrcstarting: roslaunch val_deploy val_control_sim.launch controller_manager_looprate:=500 __name:=controller_manager_ubuntu_SER3040_2998_439239008329951092 __log:=/home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/controller_manager_ubuntu_SER3040_2998_439239008329951092-4.log
Configuring > 0/1 projects > root project... logging to /home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-3528.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.

 > Resolving dependencies ':ros'started roslaunch server http://127.0.0.1:33391/

SUMMARY
========

PARAMETERS
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    controller_manager_ubuntu_SER3040_3528_4851789448662283063 (val_controller_manager_rtt/controller_exec)

ROS_MASTER_URI=http://localhost:11311

core service [/rosout] found
process[controller_manager_ubuntu_SER3040_3528_4851789448662283063-1]: started with pid [3560]
2016-12-12 13:59:27 localhost ncl_cpp: [NOTICE  ] [gov.nasa.HardwareInterface.makeHandle] Robot Hardware has Initialized. Ready to start loading Controllers. 

:parseYaml UP-TO-DATE
> Building 50% > :runJavaDelegate[INFO] [WallTime: 1481572767.446933] [4.541000] Controller Spawner: Waiting for service controller_manager/switch_controller
[INFO] [WallTime: 1481572767.448643] [4.543000] Controller Spawner: Waiting for service controller_manager/unload_controller
[INFO] [WallTime: 1481572767.449839] [4.544000] Loading controller: ihmc_valkyrie_control_java_bridge
[ INFO] [1481572767.507931292, 4.598000000]: 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/jake/valkyrie
Started Java VM: success
starting: roslaunch val_gazebo spawn_urdf_model_from_robot_description.launch modelName:=valkyrie zOffset:=1.25 __name:=urdf_spawner_ubuntu_SER3040_2998_6216829015108794449 __log:=/home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/urdf_spawner_ubuntu_SER3040_2998_6216829015108794449-7.log
... logging to /home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-3776.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.

:runJavaDelegate
Loading robot model from: 'models/val_description/sdf/valkyrie_sim.sdf'
> Building 50% > :runJavaDelegatestarted roslaunch server http://127.0.0.1:45144/

SUMMARY
========

PARAMETERS
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    urdf_spawner (gazebo_ros/spawn_model)

ROS_MASTER_URI=http://localhost:11311

core service [/rosout] found
process[urdf_spawner-1]: started with pid [3801]
[ INFO] [1481572768.255137537, 5.329000000]: Loading robot model from: 'models/val_description/sdf/valkyrie_sim.sdf'
spawn_model script started
[INFO] [WallTime: 1481572768.558385] [0.000000] Loading model xml from ros parameter
[INFO] (NetworkParameters.java:38): Looking for network parameters in network parameters file at /opt/ros/indigo/share/ihmc_valkyrie_ros/configurations/IHMCNetworkParametersSim.ini
[INFO] (NetworkParameters.java:42): Found Network parameters file at /opt/ros/indigo/share/ihmc_valkyrie_ros/configurations/IHMCNetworkParametersSim.ini
[INFO] (NetworkParameters.java:69): Looking for network parameters in environment variables
[INFO] (NetworkParameters.java:70): Environment variables will override entries in the network parameters file.
> Building 50% > :runJavaDelegate[INFO] [WallTime: 1481572768.591526] [5.651000] Waiting for service /gazebo/spawn_urdf_model
[INFO] [WallTime: 1481572768.593791] [5.657000] Calling service /gazebo/spawn_urdf_model
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[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.
Connecting to controller using TCP on localhost
[WARN] YoVariable: desiredMomentumRateLinearX is getting created with a null registry
[WARN] YoVariable: desiredMomentumRateLinearY is getting created with a null registry
[WARN] YoVariable: desiredMomentumRateLinearZ is getting created with a null registry
[WARN] YoVariable: achievedMomentumRateLinearX is getting created with a null registry
[WARN] YoVariable: achievedMomentumRateLinearY is getting created with a null registry
[WARN] YoVariable: achievedMomentumRateLinearZ is getting created with a null registry
[WARN] YoVariable: residualRootJointForceX is getting created with a null registry
[WARN] YoVariable: residualRootJointForceY is getting created with a null registry
[WARN] YoVariable: residualRootJointForceZ is getting created with a null registry
[WARN] YoVariable: residualRootJointTorqueX is getting created with a null registry
[WARN] YoVariable: residualRootJointTorqueY is getting created with a null registry
[WARN] YoVariable: residualRootJointTorqueZ is getting created with a null registry
> Building 50% > :runJavaDelegate[ INFO] [1481572769.857131033, 5.895000000]: Camera Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/'
[ INFO] [1481572769.857325751, 5.895000000]: Camera Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/'
[ INFO] [1481572769.862813588, 5.895000000]: Camera Plugin (ns = /)  <tf_prefix_>, set to ""
[ INFO] [1481572769.862870849, 5.895000000]: Camera Plugin (ns = /)  <tf_prefix_>, set to ""
[ INFO] [1481572769.890773329, 5.895000000]: Laser Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/'
[ INFO] [1481572769.891065047, 5.895000000]: Starting GazeboRosLaser Plugin (ns = /)!
[ INFO] [1481572769.907805518, 5.895000000]: GPU Laser Plugin (ns = /) <tf_prefix_>, set to ""
[ INFO] [1481572769.909212119, 5.895000000]: LoadThread function completed
[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: 1481572769.934357] [5.895000] Spawn status: SpawnModel: Successfully spawned model
[ INFO] [1481572769.978897229, 5.895000000]: [INFO] (NetworkParameters.java:38): Looking for network parameters in network parameters file at /home/jake/.ihmc/IHMCNetworkParameters.ini
[ INFO] [1481572769.979183166, 5.895000000]: [INFO] (NetworkParameters.java:42): Found Network parameters file at /home/jake/.ihmc/IHMCNetworkParameters.ini
[ INFO] [1481572769.979695341, 5.895000000]: [INFO] (NetworkParameters.java:69): Looking for network parameters in environment variables
[ INFO] [1481572769.979905384, 5.895000000]: [INFO] (NetworkParameters.java:70): Environment variables will override entries in the network parameters file.
[Wrn] [ColladaLoader.cc:1461] Polylist input semantic: 'COLOR' is currently not supported
Attaching native thread 4040 with priority 45 to JVM
log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar).
log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN Please initialize the log4j system properly.
> Building 50% > :runJavaDelegate[urdf_spawner-1] process has finished cleanly
log file: /home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/urdf_spawner-1*.log
all processes on machine have died, roslaunch will exit
[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] [1481572770.275981100, 5.895000000]: SharedMemoryInterfacePlugin: Loading
2016-12-12 13:59:30 localhost ncl_cpp: [ERROR   ] [gov.nasa.SharedMemorySimInterfacePlugin.findUrdfSensors] Possibly missing an api or node tag from one or more imu sensors
2016-12-12 13:59:30 localhost ncl_cpp: [WARN    ] [gov.nasa.SharedMemorySimInterfacePlugin.findUrdfSensors] Imu sensor head_imu_sensor doesn't have <imuTransform> tag. It is likely that the data you receive from this sensor will be incorrect.
shutting down processing monitor...
... shutting down processing monitor complete
done
[ INFO] [1481572770.379702191, 5.895000000]: SharedMemorySimInterfacePlugin: Loading complete!
[urdf_spawner_ubuntu_SER3040_2998_6216829015108794449-7] process has finished cleanly
log file: /home/jake/.ros/log/78ee9e06-c0a5-11e6-977c-0cc47a6ee6d6/urdf_spawner_ubuntu_SER3040_2998_6216829015108794449-7*.log
[ INFO] [1481572770.538365761, 5.895000000]: Looking for forceSensorDefinition leftAnkleRoll
[ INFO] [1481572770.554277844, 5.895000000]: Looking for forceSensorDefinition rightAnkleRoll
[ INFO] [1481572770.708996273, 5.895000000]: imu plugin missing <frameName>, defaults to <bodyName>
[ INFO] [1481572770.709246552, 5.895000000]: imu plugin missing <frameName>, defaults to <bodyName>
[ INFO] [1481572770.709852481, 5.895000000]: imu plugin missing <frameName>, defaults to <bodyName>
[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.
Dec 12, 2016 1:59:30 PM org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink
WARNING: Failed to accept a connection.
java.io.IOException: Too many open files
    at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
    at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
    at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink$Boss.run(NioServerSocketPipelineSink.java:238)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Dec 12, 2016 1:59:30 PM org.jboss.netty.channel.DefaultChannelPipeline
WARNING: An exception was thrown by a user handler while handling an exception event ([id: 0x5539fe9d] EXCEPTION: org.jboss.netty.channel.ChannelException: Failed to create a selector.)
org.ros.exception.RosRuntimeException: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.ros.internal.transport.ConnectionTrackingHandler.exceptionCaught(ConnectionTrackingHandler.java:81)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:166)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:111)
    at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:55)
    at org.jboss.netty.channel.Channels.connect(Channels.java:642)
    at org.jboss.netty.channel.AbstractChannel.connect(AbstractChannel.java:207)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:230)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:183)
    at org.ros.internal.transport.tcp.TcpClient.connect(TcpClient.java:101)
    at org.ros.internal.transport.tcp.TcpClientManager.connect(TcpClientManaa:69)av
    at org.ros.internal.node.topic.DefaultSubscriber.addPublisher(DefaultSubscriber.java:150)
    at org.ros.internal.node.topic.UpdatePublisherRunnable.run(UpdatePublisherRunnable.java:73)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:212)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:161)
    ... 13 more
Caused by: java.io.IOException: Too many open files
    at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
    at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
    at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
    at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
    at java.nio.channels.Selector.open(Selector.java:227)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:210)
    ... 14 more

Dec 12, 2016 1:59:30 PM org.jboss.netty.channel.DefaultChannelPipeline
WARNING: An exception was thrown by a user handler while handling an exception event ([id: 0xfabf3c0b] EXCEPTION: org.jboss.netty.channel.ChannelException: Failed to create a selector.)
org.ros.exception.RosRuntimeException: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.ros.internal.transport.ConnectionTrackingHandler.exceptionCaught(ConnectionTrackingHandler.java:81)
    at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:166)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:111)
    at org.jboss.nettyr.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:55)
    at org.jboss.netty.channel.Channels.connect(Channels.java:642)
    at org.jboss.netty.channel.AbstractChannel.connect(AbstractChannel.java:207)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:230)
    at org.jboss.netty.bootstrap.ClientBootstrap.connect(ClientBootstrap.java:183)
    at org.ros.internal.transport.tcp.TcpClient.connect(TcpClient.java:101)
    at org.ros.internal.transport.tcp.TcpClientManager.connect(TcpClientManager.java:69)
    at org.ros.internal.node.topic.DefaultSubscriber.addPublisher(DefaultSubscriber.java:150)
    at org.ros.internal.node.topic.UpdatePublisherRunnable.run(UpdatePublisherRunnable.java:73)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.jboss.netty.channel.ChannelException: Failed to create a selector.
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:212)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.connect(NioClientSocketPipelineSink.java:161)
    ... 13 more
Caused by: java.io.IOException: Too many open files
    at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
    at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
    at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
    at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
    at java.nio.channels.Selector.open(Selector.java:227)
    at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink$Boss.register(NioClientSocketPipelineSink.java:210)
    ... 14 more

IHMC ROS API node successfully started.
> Building 50% > :runJavaDelegate[ INFO] [1481572772.168378793, 6.341000000]: IMUBasedPelvisRotationalStateUpdater: More than 1 IMU sensor, using only the first one: pelvis_pelvisRearImu
[ INFO] [1481572772.201945397, 6.353000000]: PelvisIMUBasedLinearStateCalculator: More than 1 IMU sensor, using only the first one: pelvis_pelvisRearImu
Attaching native thread 5717 with priority 45 to JVM
[ INFO] [1481572773.801883287, 6.872000000]: [INFO] (LogSessionBroadcaster.java:66): Announcing logging session on: name:lo (lo)
[ INFO] [1481572773.851369761, 6.886000000]: [INFO] (LogSessionBroadcaster.java:307): Trying port 56352
[INFO] (KryoObjectClient.java:130): Success! Connected KryoClient to SCS at ip localhost/127.0.0.1 on port 4895
> Building 50% > :runJavaDelegateAttaching native thread 5795 with priority 40 to JVM
[ INFO] [1481572779.279435942, 8.571000000]: [INFO] (ValkyrieRosControlController.java:307): Running with blocking synchronous execution between estimator and controller
[INFO] [WallTime: 1481572779.581023] [8.648000] Controller Spawner: Loaded controllers: ihmc_valkyrie_control_java_bridge
[INFO] [WallTime: 1481572779.980936] [8.748000] Started controllers: ihmc_valkyrie_control_java_bridge
^C[controller_spawner_ubuntu_SER3040_2998_2114081573183867240-10] killing on exit
[IHMCValkyrieROSAPI-9] killing on exit
[INFO] [WallTime: 1481573269.276942] [143.391000] Shutting down spawner. Stopping and unloading controllers...
[robot_state_publisher-8] killing on exit
[gazebo_gui-6] killing on exit
[gazebo-5] killing on exit
[controller_manager_ubuntu_SER3040_2998_439239008329951092-4] killing on exit
[control_py_ubuntu_SER3040_2998_3691283938542798629-3] killing on exit
[smtcore_ubuntu_SER3040_2998_714146815997592256-2] killing on exit
[controller_manager_ubuntu_SER3040_3528_4851789448662283063-1] killing on exit
2016-12-12 14:07:49 localhost ncl_cpp: [FATAL   ] [gov.nasa.ControllerExec.ORO_main] Controller manager has stopped running! Stopping controller exec.
terminate called after throwing an instance of 'boost::exception_detail::clone_impl<boost::exception_detail::error_info_injector<boost::lock_error> >'
  what():  boost: mutex lock failed in pthread_mutex_lock: Invalid argument
shutting down processing monitor...
... shutting down processing monitor complete
done
[controller_spawner_ubuntu_SER3040_2998_2114081573183867240-10] escalating to SIGTERM
[gazebo-5] escalating to SIGTERM
[controller_spawner_ubuntu_SER3040_2998_2114081573183867240-10] escalating to SIGKILL
[rosout-1] killing on exit
[master] killing on exit
Shutdown errors:
 * process[controller_spawner_ubuntu_SER3040_2998_2114081573183867240-10, pid 3083]: required SIGKILL. May still be running.
shutting down processing monitor...
... shutting down processing monitor complete
done
jake@ubuntu-SER3040:~$ 
osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


osrf-migration commented 7 years ago

Original comment by Nathan Mertins (Bitbucket: nmertins).


@TopGunSnake I believe this question was asked in another issue as well. I believe this is originating in ROSJava so I'm not sure how much we can do to fix this if it a legitimate bug. Is there a procedure I can follow to reliably reproduce what you're seeing?

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


The procedure is simply running the srcsim qual2.launch file. I added a manual control on the harness detach and high-level control switch to ensure the robot falling was not due to the controller safety feature.

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


So, a crash report was generated the last time I ran the launch file, and I found that it references /usr/lib/jvm/java-7-openjdk-amd64/jre/lib/amd64/ object files, instead of java-8. My environment variable for JAVA_HOME is /usr/lib/jvm/java-8-openjdk-amd64 though. As I do not know how Java works, is this normal, or could this be the issue?

Note: I have both versions, as shown below:

#!

jake@ubuntu-SER3040:/usr/lib/jvm$ ls -als
total 60
 4 drwxr-xr-x   4 root root  4096 Nov 28 14:56 .
40 drwxr-xr-x 176 root root 36864 Dec 16 11:25 ..
 0 lrwxrwxrwx   1 root root    24 Mar 22  2014 default-java -> java-1.7.0-openjdk-amd64
 0 lrwxrwxrwx   1 root root    20 Nov 16 02:09 java-1.7.0-openjdk-amd64 -> java-7-openjdk-amd64
 4 -rw-r--r--   1 root root  2439 Nov 16 02:09 .java-1.7.0-openjdk-amd64.jinfo
 0 lrwxrwxrwx   1 root root    20 Apr 22  2016 java-1.8.0-openjdk-amd64 -> java-8-openjdk-amd64
 4 -rw-r--r--   1 root root  2600 Apr 22  2016 .java-1.8.0-openjdk-amd64.jinfo
 4 drwxr-xr-x   7 root root  4096 Nov 28 14:56 java-7-openjdk-amd64
 4 drwxr-xr-x   7 root root  4096 Dec  8 20:04 java-8-openjdk-amd64
osrf-migration commented 7 years ago

Original comment by Nathan Mertins (Bitbucket: nmertins).


On my test machine I have the same Java version mismatch you've described and the sim still runs without any problem. You could try manually changing the default version to point to the Java 8 OpenJDK though using the following command:

sudo update-alternatives --config java

and then selecting the number corresponding to OpenJDK 8. You'd also want to update the link for javac as well:

sudo update-alternatives --config javac

Have you tried removing and reinstalling SRCSim? I realize that isn't a very satisfying fix, but it may be the quickest path to a working sim as I have yet to reproduce this bug on my end.

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


I'll try the default version change first, and if that does not work, I'll try a clean reinstall.

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


So, the changes to the alternatives has stopped the java exceptions. However, the robot still cannot stand, even with the updates to srcsim. @nmertins , I would like to trace the control flow, and see if I can find where the controller fails to interface with the simulator. Along those lines, what topics, either ROS or Gazebo, would indicate joint effort, and where in the control loop do they occur? Right now, this is the only roadblock in my development for this competition. It would be a shame to not qualify due to the provided code simply not working in my case.

osrf-migration commented 7 years ago

Original comment by Nathan Mertins (Bitbucket: nmertins).


I agree and want to get to the bottom of this issue. First, I want to confirm that you are still having problems after a clean install and not just an update. If something went wrong during you're initial install, it would likely persist even after updating. Perhaps @nkoenig or @caguero could provide some documentation for uninstalling/purging SRCSim. Second, we should close this issue as it appears the exceptions you were seeing were not what is causing the robot to fall. We can take our troubleshooting "offline" (whether that's direct email or some other channel of communication) until we have a more concrete idea about what's causing these issues and then make that information public along with whatever fix we discover.

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


Sounds good.

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


Clean install was performed as follows:

#!

sudo apt remove srcsim; sudo apt-get autoremove; sudo apt update; sudo apt full-upgrade; sudo apt install srcsim

No success.

osrf-migration commented 7 years ago

Original comment by Jake Webster (Bitbucket: TopGunSnake).


Here is the printout from the test:

#!

jake@ubuntu-SER3040:~$ roslaunch srcsim qual2.launch init:=true walk_test:=true
... logging to /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-3055.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:36676/

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/jake/valkyrie
 * /joint_state_controller/publish_rate: 50
 * /joint_state_controller/type: joint_state_contr...
 * /multisense/camera/stereo_proc/approximate_sync: False
 * /multisense/camera/stereo_proc/disparity_range: 128
 * /multisense_points2_color_relay/lazy: True
 * /multisense_points2_relay/lazy: True
 * /robot_description: <?xml version="1....
 * /rosdistro: indigo
 * /rosversion: 1.11.20
 * /use_sim_time: True
 * /valkyrie/robot_description: <?xml version="1....

NODES
  /multisense/camera/
    stereo_proc (stereo_image_proc/stereo_image_proc)
  /
    IHMCValkyrieROSAPI (ihmc_ros_java_adapter/gradlew)
    control_py_ubuntu_SER3040_3055_7921696170919686115 (robonet_tools/control)
    controller_manager_ubuntu_SER3040_3055_4201712645798236583 (val_deploy/delayed_roslaunch.sh)
    controller_spawner_ubuntu_SER3040_3055_1372834138709541353 (controller_manager/spawner)
    gazebo (gazebo_ros/gzserver)
    gazebo_gui (gazebo_ros/gzclient)
    multisense_points2_color_relay (topic_tools/relay)
    multisense_points2_relay (topic_tools/relay)
    robot_state_publisher (robot_state_publisher/state_publisher)
    sim_smt_topic_creator_ubuntu_SER3040_3055_3193409939978786417 (val_deploy/delayed_roslaunch.sh)
    smtcore_ubuntu_SER3040_3055_5280512276805407083 (shared_memory_transport/smtcore)
    startup_robot (srcsim/init_robot.sh)
    urdf_spawner_ubuntu_SER3040_3055_6944250832883580208 (val_deploy/delayed_roslaunch.sh)

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

setting /run_id to 62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6
process[rosout-1]: started with pid [3080]
started core service [/rosout]
process[smtcore_ubuntu_SER3040_3055_5280512276805407083-2]: started with pid [3098]
process[control_py_ubuntu_SER3040_3055_7921696170919686115-3]: started with pid [3105]
process[sim_smt_topic_creator_ubuntu_SER3040_3055_3193409939978786417-4]: started with pid [3106]
delaying: 3 seconds
process[controller_manager_ubuntu_SER3040_3055_4201712645798236583-5]: started with pid [3108]
delaying: 5 seconds
process[gazebo-6]: started with pid [3110]
process[gazebo_gui-7]: started with pid [3113]
process[urdf_spawner_ubuntu_SER3040_3055_6944250832883580208-8]: started with pid [3120]
delaying: 7 seconds
Log file /home/jake/.log already exists, proceeding...
process[robot_state_publisher-9]: started with pid [3122]
process[IHMCValkyrieROSAPI-10]: started with pid [3124]
process[controller_spawner_ubuntu_SER3040_3055_1372834138709541353-11]: started with pid [3127]
process[startup_robot-12]: started with pid [3133]
INIT: Wait 15s (ROS time) for system to load
process[multisense/camera/stereo_proc-13]: started with pid [3141]
process[multisense_points2_relay-14]: started with pid [3144]
process[multisense_points2_color_relay-15]: started with pid [3145]
Log file /home/jake/.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: /gazebo] [1482865939.788719800]: Finished loading Gazebo ROS API Plugin.
[Msg] Waiting for master.
[ INFO: /gazebo] [1482865939.789235944]: 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: 10.115.103.231
[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [0.000000]: Controller Spawner: Waiting for service controller_manager/load_controller
[ INFO: /gazebo] [1482865940.478142101, 0.022000000]: waitForService: Service [/gazebo/set_physics_properties] is now available.
[ INFO: /gazebo] [1482865940.526318645, 0.067000000]: Physics dynamic reconfigure ready.
> Loading > buildSrcstarting: roslaunch val_gazebo smt_topic_creator.launch __name:=sim_smt_topic_creator_ubuntu_SER3040_3055_3193409939978786417 __log:=/home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/sim_smt_topic_creator_ubuntu_SER3040_3055_3193409939978786417-4.log
... logging to /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-3955.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:41264/

SUMMARY
========

PARAMETERS
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    sim_smt_topic_creator_ubuntu_SER3040_3955_4550495074502678181 (val_gazebo/shm_topic_creator)

ROS_MASTER_URI=http://localhost:11311

core service [/rosout] found
process[sim_smt_topic_creator_ubuntu_SER3040_3955_4550495074502678181-1]: started with pid [3985]
:buildSrc:compileJava UP-TO-DATE
:buildSrc:compileGroovy UP-TO-DATE
:buildSrc:processResources UP-TO-DATE
:buildSrc:classes UP-TO-DATE
:buildSrc:jar UP-TO-DATE
:buildSrc:assemble UP-TO-DATE
:buildSrc:compileTestJava UP-TO-DATE
:buildSrc:compileTestGroovy UP-TO-DATE
:buildSrc:processTestResources UP-TO-DATE
:buildSrc:testClasses UP-TO-DATE
:buildSrc:test UP-TO-DATE
:buildSrc:check UP-TO-DATE
:buildSrc:build UP-TO-DATE
> Loading > settings[sim_smt_topic_creator_ubuntu_SER3040_3955_4550495074502678181-1] process has finished cleanly
log file: /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/sim_smt_topic_creator_ubuntu_SER3040_3955_4550495074502678181-1*.log
all processes on machine have died, roslaunch will exit
Configuring > 0/1 projects > root projectshutting down processing monitor...
... shutting down processing monitor complete
done
[sim_smt_topic_creator_ubuntu_SER3040_3055_3193409939978786417-4] process has finished cleanly
log file: /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/sim_smt_topic_creator_ubuntu_SER3040_3055_3193409939978786417-4*.log
 > Resolving dependencies ':ros'starting: roslaunch val_deploy val_control_sim.launch controller_manager_looprate:=500 __name:=controller_manager_ubuntu_SER3040_3055_4201712645798236583 __log:=/home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/controller_manager_ubuntu_SER3040_3055_4201712645798236583-5.log
... logging to /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-4059.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:32914/

SUMMARY
========

PARAMETERS
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    controller_manager_ubuntu_SER3040_4059_8410037243123490693 (val_controller_manager_rtt/controller_exec)

ROS_MASTER_URI=http://localhost:11311

core service [/rosout] found
process[controller_manager_ubuntu_SER3040_4059_8410037243123490693-1]: started with pid [4087]
:parseYaml UP-TO-DATE
> Building 50% > :runJavaDelegate2016-12-27 13:12:25 localhost ncl_cpp: [NOTICE  ] [gov.nasa.HardwareInterface.initializeRobotHardware] Robot Hardware has Initialized. Ready to start loading Controllers. 

:runJavaDelegate
Loading robot model from: 'models/val_description/sdf/valkyrie_sim.sdf'
> Building 50% > :runJavaDelegate[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [5.450000]: Controller Spawner: Waiting for service controller_manager/switch_controller
[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [5.452000]: Controller Spawner: Waiting for service controller_manager/unload_controller
[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [5.453000]: Loading controller: ihmc_valkyrie_control_java_bridge
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865946.027314387, 5.496000000]: 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/jake/valkyrie
Started Java VM: success
starting: roslaunch val_gazebo spawn_urdf_model_from_robot_description.launch modelName:=valkyrie zOffset:=1.25 __name:=urdf_spawner_ubuntu_SER3040_3055_6944250832883580208 __log:=/home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/urdf_spawner_ubuntu_SER3040_3055_6944250832883580208-8.log
[INFO] (NetworkParameters.java:38): Looking for network parameters in network parameters file at /opt/ros/indigo/share/ihmc_valkyrie_ros/configurations/IHMCNetworkParametersSim.ini
[INFO] (NetworkParameters.java:42): Found Network parameters file at /opt/ros/indigo/share/ihmc_valkyrie_ros/configurations/IHMCNetworkParametersSim.ini
[INFO] (NetworkParameters.java:69): Looking for network parameters in environment variables
[INFO] (NetworkParameters.java:70): Environment variables will override entries in the network parameters file.
> Building 50% > :runJavaDelegate... logging to /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/roslaunch-ubuntu-SER3040-4251.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.

[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865946.581584353, 6.050000000]: Loading robot model from: 'models/val_description/sdf/valkyrie_sim.sdf'
started roslaunch server http://127.0.0.1:38916/

SUMMARY
========

PARAMETERS
 * /rosdistro: indigo
 * /rosversion: 1.11.20

NODES
  /
    urdf_spawner (gazebo_ros/spawn_model)

ROS_MASTER_URI=http://localhost:11311

core service [/rosout] found
process[urdf_spawner-1]: started with pid [4276]
Connecting to controller using TCP on localhost
[WARN] YoVariable: desiredMomentumRateLinearX is getting created with a null registry
[WARN] YoVariable: desiredMomentumRateLinearY is getting created with a null registry
[WARN] YoVariable: desiredMomentumRateLinearZ is getting created with a null registry
[WARN] YoVariable: achievedMomentumRateLinearX is getting created with a null registry
[WARN] YoVariable: achievedMomentumRateLinearY is getting created with a null registry
[WARN] YoVariable: achievedMomentumRateLinearZ is getting created with a null registry
[WARN] YoVariable: residualRootJointForceX is getting created with a null registry
[WARN] YoVariable: residualRootJointForceY is getting created with a null registry
[WARN] YoVariable: residualRootJointForceZ is getting created with a null registry
[WARN] YoVariable: residualRootJointTorqueX is getting created with a null registry
[WARN] YoVariable: residualRootJointTorqueY is getting created with a null registry
[WARN] YoVariable: residualRootJointTorqueZ is getting created with a null registry
> Building 50% > :runJavaDelegatespawn_model script started
[INFO: /urdf_spawner] [0.000000]: Loading model xml from ros parameter
[INFO: /urdf_spawner] [0.000000]: Waiting for service /gazebo/spawn_urdf_model
[INFO: /urdf_spawner] [0.000000]: Calling service /gazebo/spawn_urdf_model
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[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.
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865947.553477416, 6.836000000]: [INFO] (NetworkParameters.java:38): Looking for network parameters in network parameters file at /home/jake/.ihmc/IHMCNetworkParameters.ini
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865947.553692135, 6.836000000]: [INFO] (NetworkParameters.java:42): Found Network parameters file at /home/jake/.ihmc/IHMCNetworkParameters.ini
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865947.554269042, 6.836000000]: [INFO] (NetworkParameters.java:69): Looking for network parameters in environment variables
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865947.554385030, 6.836000000]: [INFO] (NetworkParameters.java:70): Environment variables will override entries in the network parameters file.
Attaching native thread 4321 with priority 45 to JVM
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865947.771670983, 6.836000000]: Looking for forceSensorDefinition leftAnkleRoll
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865947.773211520, 6.836000000]: Looking for forceSensorDefinition rightAnkleRoll
log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar).
log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN No appenders could be found for logger (org.ros.internal.node.client.Registrar).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN Please initialize the log4j system properly.
> Building 50% > :runJavaDelegate[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865948.205358508, 6.836000000]: IMUBasedPelvisRotationalStateUpdater: More than 1 IMU sensor, using only the first one: pelvis_pelvisRearImu
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865948.252391461, 6.836000000]: PelvisIMUBasedLinearStateCalculator: More than 1 IMU sensor, using only the first one: pelvis_pelvisRearImu
Attaching native thread 4521 with priority 45 to JVM
IHMC ROS API node successfully started.
> Building 50% > :runJavaDelegate[ INFO: /gazebo] [1482865948.677776578, 6.836000000]: Camera Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/'
[ INFO: /gazebo] [1482865948.677973332, 6.836000000]: Camera Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/'
[ INFO: /gazebo] [1482865948.682476052, 6.836000000]: Camera Plugin (ns = /)  <tf_prefix_>, set to ""
[ INFO: /gazebo] [1482865948.683115515, 6.836000000]: Camera Plugin (ns = /)  <tf_prefix_>, set to ""
[ INFO: /gazebo] [1482865948.719340926, 6.836000000]: Laser Plugin (robotNamespace = /), Info: Using the 'robotNamespace' param: '/'
[ INFO: /gazebo] [1482865948.719685513, 6.836000000]: Starting GazeboRosLaser Plugin (ns = /)!
[ INFO: /gazebo] [1482865948.723016807, 6.836000000]: GPU Laser Plugin (ns = /) <tf_prefix_>, set to ""
[ INFO: /gazebo] [1482865948.724296713, 6.836000000]: LoadThread function completed
[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: /urdf_spawner] [6.836000]: Spawn status: SpawnModel: Successfully spawned model
[Wrn] [ColladaLoader.cc:1461] Polylist input semantic: 'COLOR' is currently not supported
[urdf_spawner-1] process has finished cleanly
log file: /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/urdf_spawner-1*.log
all processes on machine have died, roslaunch will exit
[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: /gazebo] [1482865949.065431432, 6.836000000]: SharedMemoryInterfacePlugin: Loading
2016-12-27 13:12:29 localhost ncl_cpp: [WARN    ] [gov.nasa.SharedMemorySimInterfacePlugin.findUrdfSensors] Possibly missing an api or node tag from one or more imu sensors
2016-12-27 13:12:29 localhost ncl_cpp: [WARN    ] [gov.nasa.SharedMemorySimInterfacePlugin.findUrdfSensors] Imu sensor head_imu_sensor doesn't have <imuTransform> tag. It is likely that the data you receive from this sensor will be incorrect.
[ INFO: /gazebo] [1482865949.137087024, 6.836000000]: SharedMemorySimInterfacePlugin: Loading complete!
shutting down processing monitor...
... shutting down processing monitor complete
done
[urdf_spawner_ubuntu_SER3040_3055_6944250832883580208-8] process has finished cleanly
log file: /home/jake/.ros/log/62a9c11a-cc68-11e6-8c1a-0cc47a6ee6d6/urdf_spawner_ubuntu_SER3040_3055_6944250832883580208-8*.log
[ INFO: /gazebo] [1482865949.558348411, 6.836000000]: imu plugin missing <frameName>, defaults to <bodyName>
[ INFO: /gazebo] [1482865949.558443136, 6.836000000]: imu plugin missing <frameName>, defaults to <bodyName>
[ INFO: /gazebo] [1482865949.558563156, 6.836000000]: imu plugin missing <frameName>, defaults to <bodyName>
[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: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865950.053302547, 6.972000000]: [INFO] (LogSessionBroadcaster.java:66): Announcing logging session on: name:lo (lo)
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865950.075576043, 6.979000000]: [INFO] (LogSessionBroadcaster.java:307): Trying port 56544
[INFO] (KryoObjectClient.java:130): Success! Connected KryoClient to SCS at ip localhost/127.0.0.1 on port 4895
> Building 50% > :runJavaDelegate[ INFO: /multisense_points2_color_relay] [1482865953.681744741, 7.865000000]: advertised as /multisense/image_points2_color

[ INFO: /multisense_points2_relay] [1482865953.682579567, 7.865000000]: advertised as /multisense/image_points2

Attaching native thread 6275 with priority 40 to JVM
[ INFO: /controller_manager_ubuntu_SER3040_4059_8410037243123490693] [1482865955.368200310, 8.287000000]: [INFO] (ValkyrieRosControlController.java:307): Running with blocking synchronous execution between estimator and controller
[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [8.335000]: Controller Spawner: Loaded controllers: ihmc_valkyrie_control_java_bridge
[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [8.435000]: Started controllers: ihmc_valkyrie_control_java_bridge
INIT: Lower harness
publishing and latching message for 3.0 seconds
INIT: Wait 5s (ROS time) to be lowered
INIT: Switch to high level control
publishing and latching message for 3.0 seconds
INIT: Wait 2s (ROS time) for control to be switched
INIT: Detach from harness
INIT: Start walking
publishing and latching message for 3.0 seconds
[INFO: /ihmc_walk_test] [24.393000]: waiting for subsciber...

Here I sent a SIGINT because the robot had already collapsed.

#!
^C[multisense_points2_color_relay-15] killing on exit
[multisense_points2_relay-14] killing on exit
[multisense/camera/stereo_proc-13] killing on exit
[startup_robot-12] killing on exit
[IHMCValkyrieROSAPI-10] killing on exit
[controller_spawner_ubuntu_SER3040_3055_1372834138709541353-11] killing on exit
[robot_state_publisher-9] killing on exit
[gazebo_gui-7] killing on exit
[gazebo-6] killing on exit
[controller_manager_ubuntu_SER3040_3055_4201712645798236583-5] killing on exit
[INFO: /controller_spawner_ubuntu_SER3040_3055_1372834138709541353] [27.174000]: Shutting down spawner. Stopping and unloading controllers...
[control_py_ubuntu_SER3040_3055_7921696170919686115-3] killing on exit
[controller_manager_ubuntu_SER3040_4059_8410037243123490693-1] killing on exit
INIT: Done
[smtcore_ubuntu_SER3040_3055_5280512276805407083-2] killing on exit
2016-12-27 13:13:57 localhost ncl_cpp: [FATAL   ] [gov.nasa.ControllerExec.ORO_main] Controller manager has stopped running! Stopping controller exec.
terminate called after throwing an instance of 'boost::exception_detail::clone_impl<boost::exception_detail::error_info_injector<boost::lock_error> >'
  what():  boost: mutex lock failed in pthread_mutex_lock: Invalid argument
shutting down processing monitor...
... shutting down processing monitor complete
done
[controller_spawner_ubuntu_SER3040_3055_1372834138709541353-11] escalating to SIGTERM
[gazebo-6] escalating to SIGTERM
[controller_spawner_ubuntu_SER3040_3055_1372834138709541353-11] escalating to SIGKILL
[rosout-1] killing on exit
[master] killing on exit
Shutdown errors:
 * process[controller_spawner_ubuntu_SER3040_3055_1372834138709541353-11, pid 3127]: required SIGKILL. May still be running.
shutting down processing monitor...
... shutting down processing monitor complete
done