search

UniversalRobots / Universal_Robots_ROS_Driver

Universal Robots ROS driver supporting CB3 and e-Series
Apache License 2.0
741 stars 398 forks source link

Delay between the message "Sent program to robot" and "Robot ready to receive control commands" #260

Closed sharpe-developer closed 4 years ago

sharpe-developer commented 4 years ago

Summary

I am experiencing an 8 to 10 second delay between the message "Sent program to robot" and "Robot ready to receive control commands".

I am running an Ubuntu PC as the ROS machine. Real time patch is installed. The UR3 control box is connected directly via Ethernet to the Ubuntu PC (no switches, etc.).

When I launch all goes well. I am using remote control mode and a python script that powers on the robot, loads the external control program, and runs it. This all works great but then I have to add a 15 second delay in my script before moving the robot since it is not ready to receive commands. As long as I add a delay before moving the robot then I can move the robot repeatedly without any issues. The delay seems excessive so I suspect something is going wrong.

My firewall is disabled as discussed in #8. I also tried updating to the newer external control urcap (v1.0.4). I looked at #1 and #237 but didn't see anything that stood out.

Questions:

  1. Is this delay normal or is something causing a problem?
  2. Is there a programmatic way to detect when the robot is ready to receive commands rather than using an arbitrary delay?

Versions

Issue details

Here is my log output. As you can see by the timestamps at the end it took approximately 8 seconds between sent program and ready to receive commands. The delay seems to be random in the range of 8 and 10 seconds.

... logging to /home/user/.ros/log/030633dc-f2c6-11ea-953e-98e7f4f4a84e/roslaunch-UR-ROS-5030.log
Checking log directory for disk usage. This may take a while.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.

xacro: in-order processing became default in ROS Melodic. You can drop the option.
started roslaunch server http://UR-ROS:44351/

SUMMARY
========

PARAMETERS
 * /controller_stopper/consistent_controllers: ['joint_state_con...
 * /force_torque_sensor_controller/publish_rate: 500
 * /force_torque_sensor_controller/type: force_torque_sens...
 * /hardware_control_loop/loop_hz: 500
 * /joint_group_vel_controller/joints: ['shoulder_pan_jo...
 * /joint_group_vel_controller/type: velocity_controll...
 * /joint_state_controller/publish_rate: 500
 * /joint_state_controller/type: joint_state_contr...
 * /move_group/allow_trajectory_execution: True
 * /move_group/capabilities: move_group/MoveGr...
 * /move_group/controller_list: [{'action_ns': 'f...
 * /move_group/endeffector/planner_configs: ['SBLkConfigDefau...
 * /move_group/jiggle_fraction: 0.05
 * /move_group/manipulator/default_planner_config: RRTConnectkConfig...
 * /move_group/manipulator/longest_valid_segment_fraction: 0.01
 * /move_group/manipulator/planner_configs: ['SBLkConfigDefau...
 * /move_group/max_range: 5.0
 * /move_group/max_safe_path_cost: 1
 * /move_group/moveit_controller_manager: moveit_simple_con...
 * /move_group/moveit_manage_controllers: True
 * /move_group/octomap_resolution: 0.025
 * /move_group/planner_configs/BKPIECEkConfigDefault/border_fraction: 0.9
 * /move_group/planner_configs/BKPIECEkConfigDefault/failed_expansion_score_factor: 0.5
 * /move_group/planner_configs/BKPIECEkConfigDefault/min_valid_path_fraction: 0.5
 * /move_group/planner_configs/BKPIECEkConfigDefault/range: 0.0
 * /move_group/planner_configs/BKPIECEkConfigDefault/type: geometric::BKPIECE
 * /move_group/planner_configs/ESTkConfigDefault/goal_bias: 0.05
 * /move_group/planner_configs/ESTkConfigDefault/range: 0.0
 * /move_group/planner_configs/ESTkConfigDefault/type: geometric::EST
 * /move_group/planner_configs/KPIECEkConfigDefault/border_fraction: 0.9
 * /move_group/planner_configs/KPIECEkConfigDefault/failed_expansion_score_factor: 0.5
 * /move_group/planner_configs/KPIECEkConfigDefault/goal_bias: 0.05
 * /move_group/planner_configs/KPIECEkConfigDefault/min_valid_path_fraction: 0.5
 * /move_group/planner_configs/KPIECEkConfigDefault/range: 0.0
 * /move_group/planner_configs/KPIECEkConfigDefault/type: geometric::KPIECE
 * /move_group/planner_configs/LBKPIECEkConfigDefault/border_fraction: 0.9
 * /move_group/planner_configs/LBKPIECEkConfigDefault/min_valid_path_fraction: 0.5
 * /move_group/planner_configs/LBKPIECEkConfigDefault/range: 0.0
 * /move_group/planner_configs/LBKPIECEkConfigDefault/type: geometric::LBKPIECE
 * /move_group/planner_configs/PRMkConfigDefault/max_nearest_neighbors: 10
 * /move_group/planner_configs/PRMkConfigDefault/type: geometric::PRM
 * /move_group/planner_configs/PRMstarkConfigDefault/type: geometric::PRMstar
 * /move_group/planner_configs/RRTConnectkConfigDefault/range: 0.0
 * /move_group/planner_configs/RRTConnectkConfigDefault/type: geometric::RRTCon...
 * /move_group/planner_configs/RRTkConfigDefault/goal_bias: 0.05
 * /move_group/planner_configs/RRTkConfigDefault/range: 0.0
 * /move_group/planner_configs/RRTkConfigDefault/type: geometric::RRT
 * /move_group/planner_configs/RRTstarkConfigDefault/delay_collision_checking: 1
 * /move_group/planner_configs/RRTstarkConfigDefault/goal_bias: 0.05
 * /move_group/planner_configs/RRTstarkConfigDefault/range: 0.0
 * /move_group/planner_configs/RRTstarkConfigDefault/type: geometric::RRTstar
 * /move_group/planner_configs/SBLkConfigDefault/range: 0.0
 * /move_group/planner_configs/SBLkConfigDefault/type: geometric::SBL
 * /move_group/planner_configs/TRRTkConfigDefault/frountierNodeRatio: 0.1
 * /move_group/planner_configs/TRRTkConfigDefault/frountier_threshold: 0.0
 * /move_group/planner_configs/TRRTkConfigDefault/goal_bias: 0.05
 * /move_group/planner_configs/TRRTkConfigDefault/init_temperature: 10e-6
 * /move_group/planner_configs/TRRTkConfigDefault/k_constant: 0.0
 * /move_group/planner_configs/TRRTkConfigDefault/max_states_failed: 10
 * /move_group/planner_configs/TRRTkConfigDefault/min_temperature: 10e-10
 * /move_group/planner_configs/TRRTkConfigDefault/range: 0.0
 * /move_group/planner_configs/TRRTkConfigDefault/temp_change_factor: 2.0
 * /move_group/planner_configs/TRRTkConfigDefault/type: geometric::TRRT
 * /move_group/planning_plugin: ompl_interface/OM...
 * /move_group/planning_scene_monitor/publish_geometry_updates: True
 * /move_group/planning_scene_monitor/publish_planning_scene: True
 * /move_group/planning_scene_monitor/publish_state_updates: True
 * /move_group/planning_scene_monitor/publish_transforms_updates: True
 * /move_group/request_adapters: default_planner_r...
 * /move_group/start_state_max_bounds_error: 0.1
 * /move_group/trajectory_execution/allowed_execution_duration_scaling: 1.2
 * /move_group/trajectory_execution/allowed_goal_duration_margin: 0.5
 * /move_group/trajectory_execution/execution_duration_monitoring: False
 * /move_group/use_controller_manager: False
 * /pos_joint_traj_controller/action_monitor_rate: 20
 * /pos_joint_traj_controller/constraints/elbow_joint/goal: 0.1
 * /pos_joint_traj_controller/constraints/elbow_joint/trajectory: 0.2
 * /pos_joint_traj_controller/constraints/goal_time: 0.6
 * /pos_joint_traj_controller/constraints/shoulder_lift_joint/goal: 0.1
 * /pos_joint_traj_controller/constraints/shoulder_lift_joint/trajectory: 0.2
 * /pos_joint_traj_controller/constraints/shoulder_pan_joint/goal: 0.1
 * /pos_joint_traj_controller/constraints/shoulder_pan_joint/trajectory: 0.2
 * /pos_joint_traj_controller/constraints/stopped_velocity_tolerance: 0.05
 * /pos_joint_traj_controller/constraints/wrist_1_joint/goal: 0.1
 * /pos_joint_traj_controller/constraints/wrist_1_joint/trajectory: 0.2
 * /pos_joint_traj_controller/constraints/wrist_2_joint/goal: 0.1
 * /pos_joint_traj_controller/constraints/wrist_2_joint/trajectory: 0.2
 * /pos_joint_traj_controller/constraints/wrist_3_joint/goal: 0.1
 * /pos_joint_traj_controller/constraints/wrist_3_joint/trajectory: 0.2
 * /pos_joint_traj_controller/joints: ['shoulder_pan_jo...
 * /pos_joint_traj_controller/state_publish_rate: 500
 * /pos_joint_traj_controller/stop_trajectory_duration: 0.5
 * /pos_joint_traj_controller/type: position_controll...
 * /robot_description: <?xml version="1....
 * /robot_description_kinematics/manipulator/kinematics_solver: lma_kinematics_pl...
 * /robot_description_kinematics/manipulator/kinematics_solver_search_resolution: 0.005
 * /robot_description_kinematics/manipulator/kinematics_solver_timeout: 0.005
 * /robot_description_planning/joint_limits/elbow_joint/has_acceleration_limits: True
 * /robot_description_planning/joint_limits/elbow_joint/has_velocity_limits: True
 * /robot_description_planning/joint_limits/elbow_joint/max_acceleration: 3.14
 * /robot_description_planning/joint_limits/elbow_joint/max_velocity: 3.14
 * /robot_description_planning/joint_limits/shoulder_lift_joint/has_acceleration_limits: True
 * /robot_description_planning/joint_limits/shoulder_lift_joint/has_velocity_limits: True
 * /robot_description_planning/joint_limits/shoulder_lift_joint/max_acceleration: 3.14
 * /robot_description_planning/joint_limits/shoulder_lift_joint/max_velocity: 3.14
 * /robot_description_planning/joint_limits/shoulder_pan_joint/has_acceleration_limits: True
 * /robot_description_planning/joint_limits/shoulder_pan_joint/has_velocity_limits: True
 * /robot_description_planning/joint_limits/shoulder_pan_joint/max_acceleration: 3.14
 * /robot_description_planning/joint_limits/shoulder_pan_joint/max_velocity: 3.14
 * /robot_description_planning/joint_limits/wrist_1_joint/has_acceleration_limits: True
 * /robot_description_planning/joint_limits/wrist_1_joint/has_velocity_limits: True
 * /robot_description_planning/joint_limits/wrist_1_joint/max_acceleration: 3.14
 * /robot_description_planning/joint_limits/wrist_1_joint/max_velocity: 6.28
 * /robot_description_planning/joint_limits/wrist_2_joint/has_acceleration_limits: True
 * /robot_description_planning/joint_limits/wrist_2_joint/has_velocity_limits: True
 * /robot_description_planning/joint_limits/wrist_2_joint/max_acceleration: 3.14
 * /robot_description_planning/joint_limits/wrist_2_joint/max_velocity: 6.28
 * /robot_description_planning/joint_limits/wrist_3_joint/has_acceleration_limits: True
 * /robot_description_planning/joint_limits/wrist_3_joint/has_velocity_limits: True
 * /robot_description_planning/joint_limits/wrist_3_joint/max_acceleration: 3.14
 * /robot_description_planning/joint_limits/wrist_3_joint/max_velocity: 6.28
 * /robot_description_semantic: <?xml version="1....
 * /robot_status_controller/handle_name: industrial_robot_...
 * /robot_status_controller/publish_rate: 10
 * /robot_status_controller/type: industrial_robot_...
 * /rosdistro: melodic
 * /rosversion: 1.14.9
 * /scaled_pos_joint_traj_controller/action_monitor_rate: 20
 * /scaled_pos_joint_traj_controller/constraints/elbow_joint/goal: 0.1
 * /scaled_pos_joint_traj_controller/constraints/elbow_joint/trajectory: 0.2
 * /scaled_pos_joint_traj_controller/constraints/goal_time: 0.6
 * /scaled_pos_joint_traj_controller/constraints/shoulder_lift_joint/goal: 0.1
 * /scaled_pos_joint_traj_controller/constraints/shoulder_lift_joint/trajectory: 0.2
 * /scaled_pos_joint_traj_controller/constraints/shoulder_pan_joint/goal: 0.1
 * /scaled_pos_joint_traj_controller/constraints/shoulder_pan_joint/trajectory: 0.2
 * /scaled_pos_joint_traj_controller/constraints/stopped_velocity_tolerance: 0.05
 * /scaled_pos_joint_traj_controller/constraints/wrist_1_joint/goal: 0.1
 * /scaled_pos_joint_traj_controller/constraints/wrist_1_joint/trajectory: 0.2
 * /scaled_pos_joint_traj_controller/constraints/wrist_2_joint/goal: 0.1
 * /scaled_pos_joint_traj_controller/constraints/wrist_2_joint/trajectory: 0.2
 * /scaled_pos_joint_traj_controller/constraints/wrist_3_joint/goal: 0.1
 * /scaled_pos_joint_traj_controller/constraints/wrist_3_joint/trajectory: 0.2
 * /scaled_pos_joint_traj_controller/joints: ['shoulder_pan_jo...
 * /scaled_pos_joint_traj_controller/state_publish_rate: 500
 * /scaled_pos_joint_traj_controller/stop_trajectory_duration: 0.5
 * /scaled_pos_joint_traj_controller/type: position_controll...
 * /scaled_vel_joint_traj_controller/action_monitor_rate: 20
 * /scaled_vel_joint_traj_controller/constraints/elbow_joint/goal: 0.1
 * /scaled_vel_joint_traj_controller/constraints/elbow_joint/trajectory: 0.1
 * /scaled_vel_joint_traj_controller/constraints/goal_time: 0.6
 * /scaled_vel_joint_traj_controller/constraints/shoulder_lift_joint/goal: 0.1
 * /scaled_vel_joint_traj_controller/constraints/shoulder_lift_joint/trajectory: 0.1
 * /scaled_vel_joint_traj_controller/constraints/shoulder_pan_joint/goal: 0.1
 * /scaled_vel_joint_traj_controller/constraints/shoulder_pan_joint/trajectory: 0.1
 * /scaled_vel_joint_traj_controller/constraints/stopped_velocity_tolerance: 0.05
 * /scaled_vel_joint_traj_controller/constraints/wrist_1_joint/goal: 0.1
 * /scaled_vel_joint_traj_controller/constraints/wrist_1_joint/trajectory: 0.1
 * /scaled_vel_joint_traj_controller/constraints/wrist_2_joint/goal: 0.1
 * /scaled_vel_joint_traj_controller/constraints/wrist_2_joint/trajectory: 0.1
 * /scaled_vel_joint_traj_controller/constraints/wrist_3_joint/goal: 0.1
 * /scaled_vel_joint_traj_controller/constraints/wrist_3_joint/trajectory: 0.1
 * /scaled_vel_joint_traj_controller/gains/elbow_joint/d: 0.1
 * /scaled_vel_joint_traj_controller/gains/elbow_joint/i: 0.05
 * /scaled_vel_joint_traj_controller/gains/elbow_joint/i_clamp: 1
 * /scaled_vel_joint_traj_controller/gains/elbow_joint/p: 5.0
 * /scaled_vel_joint_traj_controller/gains/shoulder_lift_joint/d: 0.1
 * /scaled_vel_joint_traj_controller/gains/shoulder_lift_joint/i: 0.05
 * /scaled_vel_joint_traj_controller/gains/shoulder_lift_joint/i_clamp: 1
 * /scaled_vel_joint_traj_controller/gains/shoulder_lift_joint/p: 5.0
 * /scaled_vel_joint_traj_controller/gains/shoulder_pan_joint/d: 0.1
 * /scaled_vel_joint_traj_controller/gains/shoulder_pan_joint/i: 0.05
 * /scaled_vel_joint_traj_controller/gains/shoulder_pan_joint/i_clamp: 1
 * /scaled_vel_joint_traj_controller/gains/shoulder_pan_joint/p: 5.0
 * /scaled_vel_joint_traj_controller/gains/wrist_1_joint/d: 0.1
 * /scaled_vel_joint_traj_controller/gains/wrist_1_joint/i: 0.05
 * /scaled_vel_joint_traj_controller/gains/wrist_1_joint/i_clamp: 1
 * /scaled_vel_joint_traj_controller/gains/wrist_1_joint/p: 5.0
 * /scaled_vel_joint_traj_controller/gains/wrist_2_joint/d: 0.1
 * /scaled_vel_joint_traj_controller/gains/wrist_2_joint/i: 0.05
 * /scaled_vel_joint_traj_controller/gains/wrist_2_joint/i_clamp: 1
 * /scaled_vel_joint_traj_controller/gains/wrist_2_joint/p: 5.0
 * /scaled_vel_joint_traj_controller/gains/wrist_3_joint/d: 0.1
 * /scaled_vel_joint_traj_controller/gains/wrist_3_joint/i: 0.05
 * /scaled_vel_joint_traj_controller/gains/wrist_3_joint/i_clamp: 1
 * /scaled_vel_joint_traj_controller/gains/wrist_3_joint/p: 5.0
 * /scaled_vel_joint_traj_controller/joints: ['shoulder_pan_jo...
 * /scaled_vel_joint_traj_controller/state_publish_rate: 500
 * /scaled_vel_joint_traj_controller/stop_trajectory_duration: 0.5
 * /scaled_vel_joint_traj_controller/type: velocity_controll...
 * /scaled_vel_joint_traj_controller/velocity_ff/elbow_joint: 1.0
 * /scaled_vel_joint_traj_controller/velocity_ff/shoulder_lift_joint: 1.0
 * /scaled_vel_joint_traj_controller/velocity_ff/shoulder_pan_joint: 1.0
 * /scaled_vel_joint_traj_controller/velocity_ff/wrist_1_joint: 1.0
 * /scaled_vel_joint_traj_controller/velocity_ff/wrist_2_joint: 1.0
 * /scaled_vel_joint_traj_controller/velocity_ff/wrist_3_joint: 1.0
 * /speed_scaling_state_controller/publish_rate: 500
 * /speed_scaling_state_controller/type: ur_controllers/Sp...
 * /ur_hardware_interface/headless_mode: False
 * /ur_hardware_interface/input_recipe_file: /home/user/ros_wo...
 * /ur_hardware_interface/joints: ['shoulder_pan_jo...
 * /ur_hardware_interface/kinematics/forearm/pitch: 3.14142455267
 * /ur_hardware_interface/kinematics/forearm/roll: 3.1407728539
 * /ur_hardware_interface/kinematics/forearm/x: -0.243803436397
 * /ur_hardware_interface/kinematics/forearm/y: 0
 * /ur_hardware_interface/kinematics/forearm/yaw: -3.14159249739
 * /ur_hardware_interface/kinematics/forearm/z: 0
 * /ur_hardware_interface/kinematics/hash: calib_10997584419...
 * /ur_hardware_interface/kinematics/shoulder/pitch: 0
 * /ur_hardware_interface/kinematics/shoulder/roll: 0
 * /ur_hardware_interface/kinematics/shoulder/x: 0
 * /ur_hardware_interface/kinematics/shoulder/y: 0
 * /ur_hardware_interface/kinematics/shoulder/yaw: -2.92268474839e-08
 * /ur_hardware_interface/kinematics/shoulder/z: 0.151985923575
 * /ur_hardware_interface/kinematics/upper_arm/pitch: 0
 * /ur_hardware_interface/kinematics/upper_arm/roll: 1.57100176175
 * /ur_hardware_interface/kinematics/upper_arm/x: -5.96361092741e-05
 * /ur_hardware_interface/kinematics/upper_arm/y: 0
 * /ur_hardware_interface/kinematics/upper_arm/yaw: 1.14948047081e-06
 * /ur_hardware_interface/kinematics/upper_arm/z: 0
 * /ur_hardware_interface/kinematics/wrist_1/pitch: 3.14142864419
 * /ur_hardware_interface/kinematics/wrist_1/roll: 3.14153030939
 * /ur_hardware_interface/kinematics/wrist_1/x: -0.213456035615
 * /ur_hardware_interface/kinematics/wrist_1/y: 8.16081186355e-06
 * /ur_hardware_interface/kinematics/wrist_1/yaw: 3.14159080797
 * /ur_hardware_interface/kinematics/wrist_1/z: 0.130899303985
 * /ur_hardware_interface/kinematics/wrist_2/pitch: 0
 * /ur_hardware_interface/kinematics/wrist_2/roll: 1.57220222882
 * /ur_hardware_interface/kinematics/wrist_2/x: 4.01379402534e-05
 * /ur_hardware_interface/kinematics/wrist_2/y: -0.0854049393065
 * /ur_hardware_interface/kinematics/wrist_2/yaw: -1.39846833547e-06
 * /ur_hardware_interface/kinematics/wrist_2/z: -0.000120071056162
 * /ur_hardware_interface/kinematics/wrist_3/pitch: 3.14159265359
 * /ur_hardware_interface/kinematics/wrist_3/roll: 1.56979295391
 * /ur_hardware_interface/kinematics/wrist_3/x: -0.00012631485121
 * /ur_hardware_interface/kinematics/wrist_3/y: 0.0922446316048
 * /ur_hardware_interface/kinematics/wrist_3/yaw: -3.14159260246
 * /ur_hardware_interface/kinematics/wrist_3/z: -9.25557936101e-05
 * /ur_hardware_interface/output_recipe_file: /home/user/ros_wo...
 * /ur_hardware_interface/reverse_port: 29999
 * /ur_hardware_interface/robot_ip: 192.168.100.1
 * /ur_hardware_interface/script_file: /home/user/ros_wo...
 * /ur_hardware_interface/script_sender_port: 50002
 * /ur_hardware_interface/tf_prefix: 
 * /ur_hardware_interface/tool_baud_rate: 115200
 * /ur_hardware_interface/tool_parity: 0
 * /ur_hardware_interface/tool_rx_idle_chars: 1.5
 * /ur_hardware_interface/tool_stop_bits: 1
 * /ur_hardware_interface/tool_tx_idle_chars: 3.5
 * /ur_hardware_interface/tool_voltage: 0
 * /ur_hardware_interface/use_tool_communication: False
 * /vel_joint_traj_controller/action_monitor_rate: 20
 * /vel_joint_traj_controller/constraints/elbow_joint/goal: 0.1
 * /vel_joint_traj_controller/constraints/elbow_joint/trajectory: 0.1
 * /vel_joint_traj_controller/constraints/goal_time: 0.6
 * /vel_joint_traj_controller/constraints/shoulder_lift_joint/goal: 0.1
 * /vel_joint_traj_controller/constraints/shoulder_lift_joint/trajectory: 0.1
 * /vel_joint_traj_controller/constraints/shoulder_pan_joint/goal: 0.1
 * /vel_joint_traj_controller/constraints/shoulder_pan_joint/trajectory: 0.1
 * /vel_joint_traj_controller/constraints/stopped_velocity_tolerance: 0.05
 * /vel_joint_traj_controller/constraints/wrist_1_joint/goal: 0.1
 * /vel_joint_traj_controller/constraints/wrist_1_joint/trajectory: 0.1
 * /vel_joint_traj_controller/constraints/wrist_2_joint/goal: 0.1
 * /vel_joint_traj_controller/constraints/wrist_2_joint/trajectory: 0.1
 * /vel_joint_traj_controller/constraints/wrist_3_joint/goal: 0.1
 * /vel_joint_traj_controller/constraints/wrist_3_joint/trajectory: 0.1
 * /vel_joint_traj_controller/gains/elbow_joint/d: 0.1
 * /vel_joint_traj_controller/gains/elbow_joint/i: 0.05
 * /vel_joint_traj_controller/gains/elbow_joint/i_clamp: 1
 * /vel_joint_traj_controller/gains/elbow_joint/p: 5.0
 * /vel_joint_traj_controller/gains/shoulder_lift_joint/d: 0.1
 * /vel_joint_traj_controller/gains/shoulder_lift_joint/i: 0.05
 * /vel_joint_traj_controller/gains/shoulder_lift_joint/i_clamp: 1
 * /vel_joint_traj_controller/gains/shoulder_lift_joint/p: 5.0
 * /vel_joint_traj_controller/gains/shoulder_pan_joint/d: 0.1
 * /vel_joint_traj_controller/gains/shoulder_pan_joint/i: 0.05
 * /vel_joint_traj_controller/gains/shoulder_pan_joint/i_clamp: 1
 * /vel_joint_traj_controller/gains/shoulder_pan_joint/p: 5.0
 * /vel_joint_traj_controller/gains/wrist_1_joint/d: 0.1
 * /vel_joint_traj_controller/gains/wrist_1_joint/i: 0.05
 * /vel_joint_traj_controller/gains/wrist_1_joint/i_clamp: 1
 * /vel_joint_traj_controller/gains/wrist_1_joint/p: 5.0
 * /vel_joint_traj_controller/gains/wrist_2_joint/d: 0.1
 * /vel_joint_traj_controller/gains/wrist_2_joint/i: 0.05
 * /vel_joint_traj_controller/gains/wrist_2_joint/i_clamp: 1
 * /vel_joint_traj_controller/gains/wrist_2_joint/p: 5.0
 * /vel_joint_traj_controller/gains/wrist_3_joint/d: 0.1
 * /vel_joint_traj_controller/gains/wrist_3_joint/i: 0.05
 * /vel_joint_traj_controller/gains/wrist_3_joint/i_clamp: 1
 * /vel_joint_traj_controller/gains/wrist_3_joint/p: 5.0
 * /vel_joint_traj_controller/joints: ['shoulder_pan_jo...
 * /vel_joint_traj_controller/state_publish_rate: 500
 * /vel_joint_traj_controller/stop_trajectory_duration: 0.5
 * /vel_joint_traj_controller/type: velocity_controll...
 * /vel_joint_traj_controller/velocity_ff/elbow_joint: 1.0
 * /vel_joint_traj_controller/velocity_ff/shoulder_lift_joint: 1.0
 * /vel_joint_traj_controller/velocity_ff/shoulder_pan_joint: 1.0
 * /vel_joint_traj_controller/velocity_ff/wrist_1_joint: 1.0
 * /vel_joint_traj_controller/velocity_ff/wrist_2_joint: 1.0
 * /vel_joint_traj_controller/velocity_ff/wrist_3_joint: 1.0

NODES
  /
    controller_stopper (controller_stopper/node)
    move_group (moveit_ros_move_group/move_group)
    robot_state_publisher (robot_state_publisher/robot_state_publisher)
    ros_control_controller_spawner (controller_manager/spawner)
    ros_control_stopped_spawner (controller_manager/spawner)
    ur_hardware_interface (ur_robot_driver/ur_robot_driver_node)
  /ur_hardware_interface/
    ur_robot_state_helper (ur_robot_driver/robot_state_helper)

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

setting /run_id to 030633dc-f2c6-11ea-953e-98e7f4f4a84e
process[rosout-1]: started with pid [5054]
started core service [/rosout]
process[robot_state_publisher-2]: started with pid [5061]
process[ur_hardware_interface-3]: started with pid [5062]
process[ros_control_controller_spawner-4]: started with pid [5067]
process[ros_control_stopped_spawner-5]: started with pid [5070]
[ INFO] [1599674287.113879978]: Main thread: SCHED_FIFO OK
[ INFO] [1599674287.115464925]: Main thread priority is 99
process[controller_stopper-6]: started with pid [5074]
[ INFO] [1599674287.124047788]: Initializing dashboard client
[ INFO] [1599674287.125801623]: Connected: Universal Robots Dashboard Server

process[ur_hardware_interface/ur_robot_state_helper-7]: started with pid [5079]
process[move_group-8]: started with pid [5083]
[ INFO] [1599674287.169676666]: Initializing urdriver
[ INFO] [1599674287.170039971]: Checking if calibration data matches connected robot.
[ INFO] [1599674287.170419047]: Producer thread: SCHED_FIFO OK
[ INFO] [1599674287.170457426]: Thread priority is 99
[ INFO] [1599674287.186088573]: Waiting for controller manager service to come up on /controller_manager/switch_controller
[ INFO] [1599674287.188701269]: waitForService: Service [/controller_manager/switch_controller] has not been advertised, waiting...
[ INFO] [1599674287.218728466]: Loading robot model 'ur3e'...
[ WARN] [1599674287.219473957]: Skipping virtual joint 'fixed_base' because its child frame 'base_link' does not match the URDF frame 'world'
[ INFO] [1599674287.219589117]: No root/virtual joint specified in SRDF. Assuming fixed joint
[ INFO] [1599674287.326868545]: Calibration checked successfully.
[ INFO] [1599674287.346211116]: Publishing maintained planning scene on 'monitored_planning_scene'
[ INFO] [1599674287.349063743]: MoveGroup debug mode is OFF
Starting planning scene monitors...
[ INFO] [1599674287.349138514]: Starting planning scene monitor
[ INFO] [1599674287.351683241]: Listening to '/planning_scene'
[ INFO] [1599674287.351825454]: Starting world geometry update monitor for collision objects, attached objects, octomap updates.
[ INFO] [1599674287.355857650]: Listening to '/collision_object'
[ INFO] [1599674287.360278363]: Listening to '/planning_scene_world' for planning scene world geometry
[ERROR] [1599674287.361099766]: Failed to find 3D sensor plugin parameters for octomap generation
[ INFO] [1599674287.373858423]: Listening to '/attached_collision_object' for attached collision objects
Planning scene monitors started.
[ INFO] [1599674287.412539479]: Initializing OMPL interface using ROS parameters
[ INFO] [1599674287.436633523]: Using planning interface 'OMPL'
[ INFO] [1599674287.439829576]: Param 'default_workspace_bounds' was not set. Using default value: 10
[ INFO] [1599674287.440282951]: Param 'start_state_max_bounds_error' was set to 0.1
[ INFO] [1599674287.440568076]: Param 'start_state_max_dt' was not set. Using default value: 0.5
[ INFO] [1599674287.440900191]: Param 'start_state_max_dt' was not set. Using default value: 0.5
[ INFO] [1599674287.441217731]: Param 'jiggle_fraction' was set to 0.05
[ INFO] [1599674287.442145331]: Param 'max_sampling_attempts' was not set. Using default value: 100
[ INFO] [1599674287.442215384]: Using planning request adapter 'Add Time Parameterization'
[ INFO] [1599674287.442242592]: Using planning request adapter 'Fix Workspace Bounds'
[ INFO] [1599674287.442272196]: Using planning request adapter 'Fix Start State Bounds'
[ INFO] [1599674287.442298103]: Using planning request adapter 'Fix Start State In Collision'
[ INFO] [1599674287.442321031]: Using planning request adapter 'Fix Start State Path Constraints'
[INFO] [1599674287.522905]: Controller Spawner: Waiting for service controller_manager/load_controller
[INFO] [1599674287.566925]: Controller Spawner: Waiting for service controller_manager/load_controller
[ INFO] [1599674288.235093184]: Producer thread: SCHED_FIFO OK
[ INFO] [1599674288.235172778]: Thread priority is 99
[ INFO] [1599674288.811105612]: Negotiated RTDE protocol version to 2.
[ INFO] [1599674288.811605092]: Setting up RTDE communication with frequency 500.000000
[ INFO] [1599674289.823972044]: Producer thread: SCHED_FIFO OK
[ INFO] [1599674289.824014074]: Thread priority is 99
[ INFO] [1599674289.824101241]: Loaded ur_robot_driver hardware_interface
[ INFO] [1599674289.888117377]: waitForService: Service [/controller_manager/switch_controller] is now available.
[ INFO] [1599674289.888154768]: Service available.
[ INFO] [1599674289.888175874]: Waiting for controller list service to come up on /controller_manager/list_controllers
[ INFO] [1599674289.888934779]: Service available.
[INFO] [1599674289.943304]: Controller Spawner: Waiting for service controller_manager/switch_controller
[INFO] [1599674289.945758]: Controller Spawner: Waiting for service controller_manager/unload_controller
[INFO] [1599674289.948697]: Loading controller: joint_state_controller
[INFO] [1599674289.956135]: Loading controller: scaled_pos_joint_traj_controller
[INFO] [1599674289.983870]: Controller Spawner: Waiting for service controller_manager/switch_controller
[INFO] [1599674289.986573]: Controller Spawner: Waiting for service controller_manager/unload_controller
[INFO] [1599674289.989459]: Loading controller: pos_joint_traj_controller
[INFO] [1599674289.996288]: Loading controller: speed_scaling_state_controller
[INFO] [1599674290.024139]: Loading controller: joint_group_vel_controller
[INFO] [1599674290.028344]: Loading controller: force_torque_sensor_controller
[INFO] [1599674290.034243]: Controller Spawner: Loaded controllers: pos_joint_traj_controller, joint_group_vel_controller
[INFO] [1599674290.038022]: Controller Spawner: Loaded controllers: joint_state_controller, scaled_pos_joint_traj_controller, speed_scaling_state_controller, force_torque_sensor_controller
[INFO] [1599674290.042361]: Started controllers: joint_state_controller, scaled_pos_joint_traj_controller, speed_scaling_state_controller, force_torque_sensor_controller
[ INFO] [1599674290.074677012]: Robot mode is now RUNNING
[ INFO] [1599674290.076226477]: Robot's safety mode is now NORMAL
[ INFO] [1599674290.277193063]: Added FollowJointTrajectory controller for 
[ INFO] [1599674290.277317418]: Returned 1 controllers in list
[ INFO] [1599674290.287980955]: Trajectory execution is managing controllers
Loading 'move_group/ApplyPlanningSceneService'...
Loading 'move_group/ClearOctomapService'...
Loading 'move_group/MoveGroupCartesianPathService'...
Loading 'move_group/MoveGroupExecuteTrajectoryAction'...
Loading 'move_group/MoveGroupGetPlanningSceneService'...
Loading 'move_group/MoveGroupKinematicsService'...
Loading 'move_group/MoveGroupMoveAction'...
Loading 'move_group/MoveGroupPickPlaceAction'...
Loading 'move_group/MoveGroupPlanService'...
Loading 'move_group/MoveGroupQueryPlannersService'...
Loading 'move_group/MoveGroupStateValidationService'...
[ INFO] [1599674290.348322061]: 

********************************************************
* MoveGroup using: 
*     - ApplyPlanningSceneService
*     - ClearOctomapService
*     - CartesianPathService
*     - ExecuteTrajectoryAction
*     - GetPlanningSceneService
*     - KinematicsService
*     - MoveAction
*     - PickPlaceAction
*     - MotionPlanService
*     - QueryPlannersService
*     - StateValidationService
********************************************************

[ INFO] [1599674290.348422130]: MoveGroup context using planning plugin ompl_interface/OMPLPlanner
[ INFO] [1599674290.348452654]: MoveGroup context initialization complete

You can start planning now!

[ INFO] [1599674316.691043347]: Robot requested program
[ INFO] [1599674316.691116911]: Sent program to robot
[ INFO] [1599674324.877954725]: Robot ready to receive control commands.
fmauch commented 4 years ago
  • Is this delay normal or is something causing a problem?

No, this should not be the case. It is normal that it is not coming instantly, as the program is being compiled when started, but it shouldn't take that long.

  • Is there a programmatic way to detect when the robot is ready to receive commands rather than using an arbitrary delay?

You can listen to the robot_program_running topic. But in that situation described I would consider this a workaround rather than a solution.

Are there any other URCaps involved? Does your program contain anything else than the ExternalControl? The program is fetched from the host machine during the start of the program. This is when you will see the Sent program to robot output. As soon as the program enters the ExternalControl program node.

sharpe-developer commented 4 years ago

I performed a Wireshark capture of the interface and didn't see anything unusual. There is a steady stream of packets going back and forth during period between the message "Sent program to robot" and "Robot ready to receive control commands". I have attached the capture for reference if it is helpful. wireshark.zip

sharpe-developer commented 4 years ago

There are other urcaps installed on the teach pendant

However, none of the urcaps are actively being used except external control. I can try removing them from the teach pendant to see if it changes anything.

The program only contains the external control unit. There is nothing else in the program.

sharpe-developer commented 4 years ago

I removed all the other urcaps and found it was the Robotiq urcap that was causing the problem. I had version Robotiq Grippers 1.6.0.4 installed. Removing the robotiq urcap brought the time between sent program and robot ready messages down to around 50 milliseconds.

I tried updating to Robotiq Grippers 1.8.4.4844 and the time between sent and ready was still milliseconds. It must have been something with the older version installed on the robot.

However, I noticed a new problem. When the robot is rebooted and this setup is executed the dashboard server disconnects. If I re-launch the nodes on the ROS side (don't change anything on the robot) then everything works fine. So it is only the initial launch after restarting the robot that has an issue. If I remove the Robotiq urcap and restart the robot there are no problems on the initial launch. So the new Robotiq urcap does not have the delay but does not work perfectly either. Here is the log output when this error occurs>

You can start planning now!

[ INFO] [1599685906.093207380]: Robot mode is now POWER_ON
[ INFO] [1599685908.360545374]: Robot mode is now BOOTING
[ INFO] [1599685915.583168000]: Robot mode is now POWER_ON
[ INFO] [1599685916.116860271]: Robot mode is now IDLE
[ INFO] [1599685918.972324485]: Robot mode is now RUNNING
[ INFO] [1599685920.697553900]: Disconnecting from Dashboard server on 192.168.100.1:29999
[ERROR] [1599685920.697901565]: Exception thrown while processing service call: Did not receive answer from dashboard server in time. Disconnecting from dashboard server.(Configured timeout: 1 sec)
[ERROR] [1599685920.710130045]: Attempt to write on a non-connected socket
[ERROR] [1599685920.710239055]: Exception thrown while processing service call: Failed to send request to dashboard server. Are you connected to the Dashboard Server?
[ INFO] [1599685921.372080406]: Robot requested program
[ INFO] [1599685921.372174363]: Sent program to robot
[ INFO] [1599685921.566657241]: Robot ready to receive control commands.

I am curious. Why would having a urcap installed on the robot cause this when the urcap is not in use. Is having the urcap loaded on the robot enough to change how the robot operates?

gavanderhoorn commented 4 years ago

Is having the urcap loaded on the robot enough to change how the robot operates?

In general: no, but there are a lot of URCaps which, as part of their initialisation routine, either start or run or use additional processes and/or threads, which can do whatever. And URCaps can also contribute pieces of code to the initialisation section of every program run / created on the controller. This is all done without you "using" the URCap.

As there is some isolation between URCaps, but not total (how could there be), there is certainly room for one URCap to influence the behaviour of others -- even if it doesn't do this intentionally.

However, I noticed a new problem.

To increase visibility of that problem, perhaps opening a new issue is in order?

sharpe-developer commented 4 years ago

To increase visibility of that problem, perhaps opening a new issue is in order?

Indeed. I have opened issue #262