Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[DO NOT MERGE] debugging SITL CI poll timeouts #13371

Closed
wants to merge 2 commits into from
Closed

[DO NOT MERGE] debugging SITL CI poll timeouts #13371

wants to merge 2 commits into from

Conversation

bkueng
Copy link
Member

@bkueng bkueng commented Nov 4, 2019

I've seen occational SITL tests time out, like:

[2019-10-29T10:31:31.452Z] + px4-px4_sitl_default-v1.10.0-beta4-99-g668d335e88/px4/test/rostest_px4_run.sh mavros_posix_tests_offboard_attctl.test mission:= vehicle:=iris

[2019-10-29T10:31:31.708Z] GAZEBO_PLUGIN_PATH :/tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/px4-px4_sitl_default-v1.10.0-beta4-99-g668d335e88/px4/test/../build/px4_sitl_default/build_gazebo

[2019-10-29T10:31:31.708Z] GAZEBO_MODEL_PATH :/tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/px4-px4_sitl_default-v1.10.0-beta4-99-g668d335e88/px4/test/../Tools/sitl_gazebo/models

[2019-10-29T10:31:31.708Z] LD_LIBRARY_PATH /opt/ros/melodic/lib:/tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/px4-px4_sitl_default-v1.10.0-beta4-99-g668d335e88/px4/test/../build/px4_sitl_default/build_gazebo

[2019-10-29T10:31:32.636Z] /opt/ros/melodic/lib/python2.7/dist-packages/roslaunch/loader.py:412: YAMLLoadWarning: calling yaml.load() without Loader=... is deprecated, as the default Loader is unsafe. Please read https://msg.pyyaml.org/load for full details.

[2019-10-29T10:31:32.636Z]   data = yaml.load(text)

[2019-10-29T10:31:33.204Z]   SYS_AUTOSTART: curr: 0 -> new: 10016

[2019-10-29T10:31:33.204Z]   BAT_N_CELLS: curr: 0 -> new: 3

[2019-10-29T10:31:33.204Z]   CAL_ACC0_ID: curr: 0 -> new: 1311244

[2019-10-29T10:31:33.204Z]   CAL_ACC_PRIME: curr: 0 -> new: 1311244

[2019-10-29T10:31:33.204Z]   CAL_GYRO0_ID: curr: 0 -> new: 2294028

[2019-10-29T10:31:33.204Z]   CAL_GYRO_PRIME: curr: 0 -> new: 2294028

[2019-10-29T10:31:33.204Z]   CAL_MAG0_ID: curr: 0 -> new: 197388

[2019-10-29T10:31:33.204Z]   CAL_MAG_PRIME: curr: 0 -> new: 197388

[2019-10-29T10:31:33.204Z]   CAL_BARO_PRIME: curr: 0 -> new: 6620172

[2019-10-29T10:31:33.204Z]   COM_DISARM_LAND: curr: 2.0000 -> new: 0.1000

[2019-10-29T10:31:33.204Z]   COM_OBL_ACT: curr: 0 -> new: 2

[2019-10-29T10:31:33.204Z]   COM_OF_LOSS_T: curr: 0.0000 -> new: 5.0000

[2019-10-29T10:31:33.204Z]   COM_RC_IN_MODE: curr: 0 -> new: 1

[2019-10-29T10:31:33.204Z]   EKF2_ANGERR_INIT: curr: 0.1000 -> new: 0.0100

[2019-10-29T10:31:33.204Z]   EKF2_GBIAS_INIT: curr: 0.1000 -> new: 0.0100

[2019-10-29T10:31:33.204Z]   EKF2_REQ_GPS_H: curr: 10.0000 -> new: 0.5000

[2019-10-29T10:31:33.204Z]   MC_PITCH_P: curr: 6.5000 -> new: 6.0000

[2019-10-29T10:31:33.204Z]   MC_PITCHRATE_P: curr: 0.1500 -> new: 0.2000

[2019-10-29T10:31:33.204Z]   MC_ROLL_P: curr: 6.5000 -> new: 6.0000

[2019-10-29T10:31:33.204Z]   MC_ROLLRATE_P: curr: 0.1500 -> new: 0.2000

[2019-10-29T10:31:33.204Z]   MPC_HOLD_MAX_Z: curr: 0.6000 -> new: 2.0000

[2019-10-29T10:31:33.204Z]   MPC_Z_VEL_I: curr: 0.1000 -> new: 0.1500

[2019-10-29T10:31:33.204Z]   MPC_Z_VEL_P: curr: 0.2000 -> new: 0.6000

[2019-10-29T10:31:33.204Z]   MPC_XY_P: curr: 0.9500 -> new: 0.8000

[2019-10-29T10:31:33.204Z]   MPC_XY_VEL_P: curr: 0.0900 -> new: 0.2000

[2019-10-29T10:31:33.204Z]   MPC_XY_VEL_D: curr: 0.0100 -> new: 0.0160

[2019-10-29T10:31:33.204Z]   MPC_JERK_MIN: curr: 8.0000 -> new: 10.0000

[2019-10-29T10:31:33.204Z]   MPC_ACC_HOR_MAX: curr: 5.0000 -> new: 3.0000

[2019-10-29T10:31:33.204Z]   NAV_ACC_RAD: curr: 10.0000 -> new: 2.0000

[2019-10-29T10:31:33.204Z]   NAV_DLL_ACT: curr: 0 -> new: 2

[2019-10-29T10:31:33.204Z]   RTL_DESCEND_ALT: curr: 30.0000 -> new: 5.0000

[2019-10-29T10:31:33.204Z]   RTL_LAND_DELAY: curr: -1.0000 -> new: 5.0000

[2019-10-29T10:31:33.204Z]   RTL_RETURN_ALT: curr: 60.0000 -> new: 30.0000

[2019-10-29T10:31:33.204Z]   SDLOG_MODE: curr: 0 -> new: 1

[2019-10-29T10:31:33.204Z]   SDLOG_PROFILE: curr: 3 -> new: 131

[2019-10-29T10:31:33.204Z]   SDLOG_DIRS_MAX: curr: 0 -> new: 7

[2019-10-29T10:31:33.204Z]   SENS_BOARD_X_OFF: curr: 0.0000 -> new: 0.0000

[2019-10-29T10:31:33.204Z]   SENS_DPRES_OFF: curr: 0.0000 -> new: 0.0010

[2019-10-29T10:31:33.204Z]   TRIG_INTERFACE: curr: 4 -> new: 3

[2019-10-29T10:31:33.204Z] * RTL_DESCEND_ALT: curr: 5.0000 -> new: 10.0000

[2019-10-29T10:31:33.204Z] * RTL_LAND_DELAY: curr: 5.0000 -> new: 0.0000

[2019-10-29T10:31:33.204Z]   PWM_MAX: curr: 2000 -> new: 1950

[2019-10-29T10:31:33.204Z]   PWM_MIN: curr: 1000 -> new: 1075

[2019-10-29T10:31:34.609Z] INFO  [init] Mixer: etc/mixers/quad_w.main.mix on /dev/pwm_output0

[2019-10-29T10:31:35.189Z] Gazebo multi-robot simulator, version 9.11.0

[2019-10-29T10:31:35.189Z] Copyright (C) 2012 Open Source Robotics Foundation.

[2019-10-29T10:31:35.189Z] Released under the Apache 2 License.

[2019-10-29T10:31:35.189Z] http://gazebosim.org

[2019-10-29T10:31:35.189Z] 

[2019-10-29T10:31:35.189Z] INFO  [mavlink] MAVLink only on localhost (set param MAV_BROADCAST = 1 to enable network)

[2019-10-29T10:31:35.753Z] the rosdep view is empty: call 'sudo rosdep init' and 'rosdep update'

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.199276259]: FCU URL: udp://:14540@localhost:14557

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.201763263]: udp0: Bind address: 0.0.0.0:14540

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.202962124]: udp0: Remote address: 127.0.0.1:14557

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.203452058]: GCS bridge disabled

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.210678383]: udp0: Remote address: 127.0.0.1:14580

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.219505981]: Plugin 3dr_radio loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.220976455]: Plugin 3dr_radio initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.221089949]: Plugin actuator_control loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.224672717]: Plugin actuator_control initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.229904463]: Plugin adsb loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.233754305]: Plugin adsb initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.233895767]: Plugin altitude loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.234900397]: Plugin altitude initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.235027330]: Plugin cam_imu_sync loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.235557695]: Plugin cam_imu_sync initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.238266469]: Plugin command loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.251055497]: Plugin command initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.251643210]: Plugin companion_process_status loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.256266023]: Plugin companion_process_status initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.256574864]: Plugin debug_value loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.268008449]: Plugin debug_value initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.268039337]: Plugin distance_sensor blacklisted

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.268138336]: Plugin fake_gps loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.296355292]: Plugin fake_gps initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.296494416]: Plugin ftp loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.310510951]: Plugin ftp initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.310653801]: Plugin global_position loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.345532586]: Plugin global_position initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.345651129]: Plugin gps_rtk loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.350977115]: Plugin gps_rtk initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.351097389]: Plugin hil loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.378601278]: Plugin hil initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.378721785]: Plugin home_position loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.395026768]: Plugin home_position initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.395256835]: Plugin imu loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.418657539]: Plugin imu initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.418773974]: Plugin landing_target loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.465380728]: Plugin landing_target initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.465513787]: Plugin local_position loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.485709078]: Plugin local_position initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.485826624]: Plugin log_transfer loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.494131399]: Plugin log_transfer initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.494283487]: Plugin manual_control loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.503527679]: Plugin manual_control initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.503655288]: Plugin mocap_pose_estimate loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.515017537]: Plugin mocap_pose_estimate initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.515133953]: Plugin mount_control loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.524132460]: Plugin mount_control initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.524236261]: Plugin obstacle_distance loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.530814844]: Plugin obstacle_distance initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.530903973]: Plugin odom loaded

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.545459217]: Plugin odom initialized

[2019-10-29T10:31:35.753Z] [ INFO] [1572345095.545572266]: Plugin onboard_computer_status loaded

[2019-10-29T10:31:35.754Z] [ INFO] [1572345095.552950419]: Plugin onboard_computer_status initialized

[2019-10-29T10:31:35.754Z] [ INFO] [1572345095.553059551]: Plugin param loaded

[2019-10-29T10:31:35.754Z] [ INFO] [1572345095.560248108]: Plugin param initialized

[2019-10-29T10:31:35.754Z] [ INFO] [1572345095.560353435]: Plugin px4flow loaded

[2019-10-29T10:31:35.754Z] [ INFO] [1572345095.574345377]: Plugin px4flow initialized

[2019-10-29T10:31:35.754Z] [ INFO] [1572345095.574391484]: Plugin rangefinder blacklisted

[2019-10-29T10:31:38.296Z] [ INFO] [157234509[INFO] [1572345096.188306, 0.000000]: Loading model XML from file /tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/px4-px4_sitl_default-v1.10.0-beta4-99-g668d335e88/px4/Tools/sitl_gazebo/models/iris/iris.sdf

[2019-10-29T10:31:38.296Z] [INFO] [1572345096.213696, 0.000000]: Waiting for service /gazebo/spawn_sdf_model

[2019-10-29T10:31:38.296Z] [INFO] [1572345097.431446, 0.000000]: Calling service /gazebo/spawn_sdf_model

[2019-10-29T10:31:38.296Z] [INFO] [1572345097.867131, 0.000000]: Spawn status: SpawnModel: Successfully spawned entity

[2019-10-29T10:31:38.296Z] [ INFO] [1572345095.211640338]: Finished loading Gazebo ROS API Plugin.

[2019-10-29T10:31:38.296Z] [Msg] Waiting for master.

[2019-10-29T10:31:38.296Z] [Msg] Connected to gazebo master @ http://127.0.0.1:11345

[2019-10-29T10:31:38.296Z] [Msg] Publicized address: 172.17.0.2

[2019-10-29T10:31:38.296Z] [ INFO] [1572345095.225180469]: waitForService: Service [/gazebo/set_physics_properties] has not been advertised, waiting...

[2019-10-29T10:31:38.296Z] [ INFO] [1572345097.491365712, 0.024000000]: waitForService: Service [/gazebo/set_physics_properties] is now available.

[2019-10-29T10:31:38.296Z] [ INFO] [1572345097.879847538, 0.080000000]: Physics dynamic reconfigure ready.

[2019-10-29T10:31:38.296Z] [Wrn] [gazebo_barometer_plugin.cpp:66] [gazebo_barometer_plugin] Using default home altitude of 488 m

[2019-10-29T10:31:38.296Z] [Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[0] no joint control will be performed for this channel.

[2019-10-29T10:31:38.296Z] [Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[1] no joint control will be performed for this channel.

[2019-10-29T10:31:38.296Z] [Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[2] no joint control will be performed for this channel.

[2019-10-29T10:31:38.296Z] [Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[3] no joint control will be performed for this channel.

[2019-10-29T10:31:38.296Z] [Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::propeller_joint] not found for channel[4] no joint control for this channel.

[2019-10-29T10:31:38.296Z] [Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::flap_left_joint] not found for channel[5] no joint control for this channel.

[2019-10-29T10:31:38.296Z] [Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::flap_right_joint] not found for channel[6] no joint control for this channel.

[2019-10-29T10:31:38.552Z] the rosdep view is empty: call 'sudo rosdep init' and 'rosdep update'

[2019-10-29T10:31:39.483Z] [Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[7] no joint control will be performed for this channel.

[2019-10-29T10:31:39.483Z] [Msg] Connecting to PX4 SITL using TCP

[2019-10-29T10:31:39.483Z] [Msg] Lockstep is enabled

[2019-10-29T10:31:39.483Z] [Msg] Speed factor set to: 1

[2019-10-29T10:31:39.483Z] [Msg] Using MAVLink protocol v2.0

[2019-10-29T10:31:39.483Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:40.410Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:41.347Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:42.274Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:43.654Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:44.588Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:45.515Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:46.442Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:47.372Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:48.300Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:49.707Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:50.639Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:51.567Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:52.502Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:53.430Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:54.357Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:55.284Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:56.654Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:57.580Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:58.508Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:31:59.436Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:00.369Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:01.304Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:02.682Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:03.616Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:04.545Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:05.473Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:06.471Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:07.398Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:08.327Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:09.695Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:10.622Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:11.551Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:12.480Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:13.409Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:14.344Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:15.712Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:16.644Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:17.575Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:18.542Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:19.471Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:20.398Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:21.325Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:22.696Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:23.625Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:24.558Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:25.491Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:26.421Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:27.349Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:28.715Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:29.643Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:30.572Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:31.501Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:32.711Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:33.652Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:34.642Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:35.594Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:36.522Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:37.451Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:38.388Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:46.366Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:46.366Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:46.366Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:46.366Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:48.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:48.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:48.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:48.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:48.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:48.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:49.430Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:50.364Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:51.729Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:52.672Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:53.602Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:54.530Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:55.461Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:56.418Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:57.367Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:58.751Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:32:59.680Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:00.608Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:01.535Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:02.462Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:03.390Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:04.755Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:05.683Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:06.634Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:07.569Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:08.497Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:09.431Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:10.358Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:11.723Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:12.649Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:13.576Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:14.503Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:15.430Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:16.358Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:17.723Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:18.650Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:19.580Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:20.514Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:21.446Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:22.381Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:23.747Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:24.674Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:25.608Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:26.538Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:27.467Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:28.394Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:29.759Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:30.691Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:31.620Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:32.546Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:33.474Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:34.401Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:35.768Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:36.695Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:37.685Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:38.614Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:39.546Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:40.480Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:41.408Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:42.778Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:43.705Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:44.634Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:45.561Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:46.489Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:47.415Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:48.779Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:49.710Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:50.637Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:51.565Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:52.493Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:53.420Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:54.786Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:55.717Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:56.644Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:57.570Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:58.497Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:33:59.424Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:00.802Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:01.731Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:02.669Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:03.598Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:04.525Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:05.453Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:06.818Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:07.745Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:08.674Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:09.603Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:10.530Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:11.463Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:12.829Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:13.758Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:14.686Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:15.613Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:16.540Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:17.467Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:18.832Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:19.759Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:20.687Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:21.615Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:22.541Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:23.469Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:24.834Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:25.762Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:26.689Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:27.616Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:28.543Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:29.497Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:30.425Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:31.789Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:32.727Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:33.663Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:34.591Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:35.557Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:36.484Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:37.850Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:38.777Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:39.710Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:40.639Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:41.566Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:42.494Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:43.859Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:44.788Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:45.718Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:46.648Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:47.576Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:48.515Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:49.447Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:50.818Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:51.750Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:52.759Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:53.689Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:54.618Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:55.546Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:56.474Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:57.842Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:58.769Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:34:59.697Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:00.629Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:01.558Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:02.701Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:03.669Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:04.597Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:05.525Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:06.454Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:07.820Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:08.748Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:09.679Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:10.612Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:11.540Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:12.467Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:13.841Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:14.767Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:15.692Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:16.617Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:17.544Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:18.498Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:19.862Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:20.788Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:21.714Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:22.641Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:23.596Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:24.522Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:25.888Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:26.816Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:27.744Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:28.672Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:29.600Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:30.528Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:31.894Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:32.822Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:33.751Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:34.678Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:35.642Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:36.572Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:37.499Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:38.865Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:39.793Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:40.723Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:41.693Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:42.624Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:43.552Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:44.479Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:46.893Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:46.893Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:47.824Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:48.751Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:49.681Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:50.609Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:51.584Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:52.513Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:53.878Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:54.807Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:55.735Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:56.662Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:57.590Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:58.518Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:35:59.882Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:00.809Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:01.743Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:02.686Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:03.614Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:04.546Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:05.929Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:06.858Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:07.787Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:08.715Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:09.653Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:10.587Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:11.515Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:12.880Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:13.808Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:14.734Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:15.662Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:16.591Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:17.520Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:18.884Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:19.811Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:20.761Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:21.689Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:22.617Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:23.543Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:24.907Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:25.835Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:26.762Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:27.689Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:28.617Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:29.544Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:30.910Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:31.840Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:32.767Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:33.733Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:34.661Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:35.588Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:36.515Z] INFO  [px4] Creating symlink /tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/px4-px4_sitl_default-v1.10.0-beta4-99-g668d335e88/px4/ROMFS/px4fmu_common -> /tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/.ros/etc

[2019-10-29T10:36:36.515Z] 

[2019-10-29T10:36:36.515Z] ______  __   __    ___ 

[2019-10-29T10:36:36.515Z] | ___ \ \ \ / /   /   |

[2019-10-29T10:36:36.515Z] | |_/ /  \ V /   / /| |

[2019-10-29T10:36:36.515Z] |  __/   /   \  / /_| |

[2019-10-29T10:36:36.515Z] | |     / /^\ \ \___  |

[2019-10-29T10:36:36.515Z] \_|     \/   \/     |_/

[2019-10-29T10:36:36.515Z] 

[2019-10-29T10:36:36.515Z] px4 starting.

[2019-10-29T10:36:36.515Z] 

[2019-10-29T10:36:36.515Z] INFO  [px4] Calling startup script: /bin/sh etc/init.d-posix/rcS 0

[2019-10-29T10:36:36.515Z] 0 WARNING: setRealtimeSched failed (not run as root?)

[2019-10-29T10:36:36.515Z] INFO  [dataman] Unknown restart, data manager file './dataman' size is 11798680 bytes

[2019-10-29T10:36:36.515Z] INFO  [simulator] Waiting for simulator to connect on TCP port 4560

[2019-10-29T10:36:36.515Z] INFO  [mavlink] mode: Normal, data rate: 4000000 B/s on udp port 14570 remote port 14550

[2019-10-29T10:36:36.515Z] INFO  [mavlink] mode: Onboard, data rate: 4000000 B/s on udp port 14580 remote port 14540

[2019-10-29T10:36:36.515Z] INFO  [logger] logger started (mode=all)

[2019-10-29T10:36:36.515Z] INFO  [logger] Start file log (type: full)

[2019-10-29T10:36:36.515Z] INFO  [logger] Opened full log file: ./log/2019-10-29/10_31_34.ulg

[2019-10-29T10:36:36.515Z] INFO  [px4] Startup script returned successfully

[2019-10-29T10:36:36.515Z] INFO  [mavlink] partner IP: 127.0.0.1

[2019-10-29T10:36:36.515Z] INFO  [simulator] Simulator connected on TCP port 4560.

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 12 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] WARN  [mavlink] [timesync] RTT too high for timesync: 16 ms

[2019-10-29T10:36:36.515Z] 

[2019-10-29T10:36:36.515Z] Exiting...

[2019-10-29T10:36:36.771Z] [Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

[2019-10-29T10:36:37.027Z] 5.574482530]: Plugin rc_io loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.581239372]: Plugin rc_io initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.581280786]: Plugin safety_area blacklisted

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.581380891]: Plugin setpoint_accel loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.588156390]: Plugin setpoint_accel initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.588305441]: Plugin setpoint_attitude loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.612724026]: Plugin setpoint_attitude initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.612856207]: Plugin setpoint_position loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.686801972]: Plugin setpoint_position initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.686932981]: Plugin setpoint_raw loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.721495452]: Plugin setpoint_raw initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.721621536]: Plugin setpoint_velocity loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.738659143]: Plugin setpoint_velocity initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.738806352]: Plugin sys_status loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.766893243]: Plugin sys_status initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.767021684]: Plugin sys_time loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.785467882]: TM: Timesync mode: MAVLINK

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.789550454]: Plugin sys_time initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.789671462]: Plugin trajectory loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.806818425]: Plugin trajectory initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.806942705]: Plugin vfr_hud loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.808613770]: Plugin vfr_hud initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.808651487]: Plugin vibration blacklisted

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.808745035]: Plugin vision_pose_estimate loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.821328749]: Plugin vision_pose_estimate initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.821456972]: Plugin vision_speed_estimate loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.825663996]: Plugin vision_speed_estimate initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.825774532]: Plugin waypoint loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.830635293]: Plugin waypoint initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.830677582]: Plugin wheel_odometry blacklisted

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.830767272]: Plugin wind_estimation loaded

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.831433807]: Plugin wind_estimation initialized

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.831476410]: Autostarting mavlink via USB on PX4

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.831511226]: Built-in SIMD instructions: SSE, SSE2

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.831527340]: Built-in MAVLink package version: 2019.10.10

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.831551185]: Known MAVLink dialects: common ardupilotmega ASLUAV autoquad icarous matrixpilot paparazzi slugs standard uAvionix ualberta

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.831568354]: MAVROS started. MY ID 1.240, TARGET ID 1.1

[2019-10-29T10:36:37.027Z] [ INFO] [1572345095.832120172]: CON: Got HEARTBEAT, connected. FCU: PX4 Autopilot

[2019-10-29T10:36:53.263Z] ... logging to /tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/.ros/ros_logs/rostest-3f1cdc9ae774-78.log

[2019-10-29T10:36:53.263Z] [ROSUNIT] Outputting test results to /tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/.ros/test_results/px4/rostest-test_mavros_posix_tests_offboard_attctl.xml

[2019-10-29T10:36:53.263Z] [Testcase: testmavros_offboard_attctl_test] ... ERROR!

[2019-10-29T10:36:53.263Z] ERROR: max time [300.0s] allotted for test [mavros_offboard_attctl_test] of type [px4/mavros_offboard_attctl_test.py]

[2019-10-29T10:36:53.263Z]   File "/usr/lib/python2.7/unittest/case.py", line 329, in run

[2019-10-29T10:36:53.263Z]     testMethod()

[2019-10-29T10:36:53.263Z]   File "/opt/ros/melodic/lib/python2.7/dist-packages/rostest/runner.py", line 148, in fn

[2019-10-29T10:36:53.263Z]     self.test_parent.run_test(test)

[2019-10-29T10:36:53.263Z]   File "/opt/ros/melodic/lib/python2.7/dist-packages/rostest/rostest_parent.py", line 132, in run_test

[2019-10-29T10:36:53.263Z]     return self.runner.run_test(test)

[2019-10-29T10:36:53.263Z]   File "/opt/ros/melodic/lib/python2.7/dist-packages/roslaunch/launch.py", line 689, in run_test

[2019-10-29T10:36:53.263Z]     (test.time_limit, test.test_name, test.package, test.type))

[2019-10-29T10:36:53.263Z] --------------------------------------------------------------------------------

[2019-10-29T10:36:53.263Z] 

[2019-10-29T10:36:53.263Z] [ROSTEST]-----------------------------------------------------------------------

[2019-10-29T10:36:53.263Z] 

[2019-10-29T10:36:53.263Z] 

[2019-10-29T10:36:53.263Z] SUMMARY

[2019-10-29T10:36:53.263Z]  * RESULT: FAIL

[2019-10-29T10:36:53.263Z]  * TESTS: 0

[2019-10-29T10:36:53.263Z]  * ERRORS: 1

[2019-10-29T10:36:53.263Z]  * FAILURES: 0

[2019-10-29T10:36:53.263Z] 

[2019-10-29T10:36:53.263Z] rostest log file is in /tmp/jenkins/workspace/isc_Firmware-SITL_tests_PR-13298/.ros/ros_logs/rostest-3f1cdc9ae774-78.log

This just adds some instrumentation for debugging, since I cannot reproduce locally.

@dagar
Copy link
Member

dagar commented Nov 4, 2019 •
edited
Loading

Yes this one is getting quite annoying and I also haven't had it reproduce locally. Unless we stumble across the root cause soon I was considering adding something crude on Jenkins to generate a core if we hit a certain number of consecutive timeouts.

The other one I've seen is a mix of poll timeout and complaining about 2 missing parameters (MPC_XY_CRUISE and MPC_COL_PREV_D). I'll post any logs I come across.

image

@dagar
Copy link
Member

dagar commented Nov 4, 2019

Another possible clue is that the poll timeout failure rate seemed to increase in the mc_rate_control PR. #12650

@dagar
Copy link
Member

dagar commented Nov 4, 2019

A fresh one - http://ci.px4.io:8080/blue/organizations/jenkins/PX4_misc%2FFirmware-SITL_tests/detail/PR-12650/57/pipeline

image

@julianoes julianoes mentioned this pull request Nov 5, 2019
Merged
@dagar dagar closed this in #13390 Nov 5, 2019
@julianoes julianoes reopened this Nov 6, 2019
@julianoes julianoes force-pushed the debug_gazebo_poll_timeouts branch from a0c92aa to 26f34da Compare November 6, 2019 08:44
@julianoes
Copy link
Contributor

Re-opened because the poll timeout thing still seems to be happening.

@julianoes julianoes force-pushed the debug_gazebo_poll_timeouts branch from 26f34da to 22ebafe Compare November 6, 2019 10:15
@julianoes julianoes force-pushed the debug_gazebo_poll_timeouts branch from 22ebafe to efa5c0d Compare November 6, 2019 11:10
@julianoes
Copy link
Contributor

I can reproduce this on Ubuntu 18.04 in VirtualBox with 2 cores an running stress -c 2 at the same time.

The output when it happens is:

[ INFO] [1573051198.013158828]: MAVROS started. MY ID 1.240, TARGET ID 1.1
[ INFO] [1573051198.083051416]: Finished loading Gazebo ROS API Plugin.
[Msg] Waiting for master.
[ INFO] [1573051198.085810845]: 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.0.2.15
clear all registered callbacks
INFO  [vehicle_angular_velocity] selected sensor changed 0 -> 0
not available
INFO  [commander] Mission #3 loaded, 6 WPs, curr: 0
sending actuator outputs: 0
INFO  [init] Mixer: etc/mixers/quad_w.main.mix on /dev/pwm_output0
INFO  [mavlink] mode: Normal, data rate: 4000000 B/s on udp port 14570 remote port 14550
[INFO] [1573051198.882866, 0.000000]: Loading model XML from file /home/julianoes/src/Firmware/Tools/sitl_gazebo/models/iris/iris.sdf
[INFO] [1573051198.894432, 0.000000]: Waiting for service /gazebo/spawn_sdf_model
INFO  [mavlink] mode: Onboard, data rate: 4000000 B/s on udp port 14580 remote port 14540
INFO  [logger] logger started (mode=all)
INFO  [logger] Start file log (type: full)
INFO  [logger] Opened full log file: ./log/2019-11-06/14_39_59.ulg
[ INFO] [1573051199.127718275, 0.024000000]: waitForService: Service [/gazebo/set_physics_properties] is now available.
INFO  [mavlink] MAVLink only on localhost (set param MAV_BROADCAST = 1 to enable network)
INFO  [px4] Startup script returned successfully
[ INFO] [1573051199.156284467]: udp0: Remote address: 127.0.0.1:14580
[ INFO] [1573051199.178984310]: FCU: [logger] file: ./log/2019-11-06/14_39_59.ulg
[ INFO] [1573051199.179190045]: CON: Got HEARTBEAT, connected. FCU: PX4 Autopilot
[ INFO] [1573051199.188304497, 0.064000000]: Physics dynamic reconfigure ready.
INFO  [mavlink] partner IP: 127.0.0.1
[INFO] [1573051199.219409, 0.080000]: Calling service /gazebo/spawn_sdf_model
[INFO] [1573051199.529862, 0.216000]: Spawn status: SpawnModel: Successfully spawned entity
[Wrn] [gazebo_barometer_plugin.cpp:66] [gazebo_barometer_plugin] Using default home altitude of 488 m
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[0] no joint control will be performed for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[1] no joint control will be performed for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[2] no joint control will be performed for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[3] no joint control will be performed for this channel.
[Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::propeller_joint] not found for channel[4] no joint control for this channel.
[Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::flap_left_joint] not found for channel[5] no joint control for this channel.
[Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::flap_right_joint] not found for channel[6] no joint control for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[7] no joint control will be performed for this channel.
[Msg] Connecting to PX4 SITL using TCP
[Msg] Lockstep is enabled
[Msg] Speed factor set to: 1
[Msg] Using MAVLink protocol v2.0
INFO  [simulator] Simulator connected on TCP port 4560.
px4_timestart_monotonic=220000  ---------------------------------------
received HIL sensors 0 220000
INFO  [simulator] HIL_SENSOR: imu time_usec: 220000, time_usec: 0, diff: 0, step: 0.00
DEBUG 0          All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 4000 224000
DEBUG 4000       All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 8000 228000
DEBUG 8000       All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
not available
received HIL sensors 12000 232000
DEBUG 12000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
published fallback at 12000
angular velocity update 0
received HIL sensors 16000 236000
DEBUG 16000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 20000 240000
DEBUG 20000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
not available
received HIL sensors 24000 244000
DEBUG 24000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
published fallback at 24000
not available
published fallback at 24000
angular velocity update 1
sending actuator outputs: 1
DEBUG 24000      sending controls t=24000 (244000)
received HIL sensors 28000 248000
DEBUG 28000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 32000 252000
DEBUG 32000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
[ INFO] [1573051200.404933373, 0.252000000]: IMU: High resolution IMU detected!
SensorCorrectionsUpdate initialized
clear all registered callbacks
INFO  [vehicle_angular_velocity] selected sensor (control) changed 0 -> 0
available: 32000
update not ok: 32000
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

This tells me that we're doing fallback gyro publications which trigger actuator publications here:

https://github.com/PX4/Firmware/blob/02271a471d7cd202fae39af99f20956b650caca9/src/modules/sensors/vehicle_angular_velocity/VehicleAngularVelocity.cpp#L241-L266

@julianoes
Copy link
Contributor 

[Msg] Waiting for master.
[Msg] Connected to gazebo master @ http://127.0.0.1:11345
[Msg] Publicized address: 10.0.2.15
clear all registered callbacks: _selected_sensor: 0, corrections.selected_gyro_instance: 0
INFO  [vehicle_angular_velocity] selected sensor changed 0 -> 0
INFO  [commander] Mission #3 loaded, 6 WPs, curr: 0
not available
sending actuator outputs: 0
INFO  [init] Mixer: etc/mixers/quad_w.main.mix on /dev/pwm_output0
INFO  [mavlink] mode: Normal, data rate: 4000000 B/s on udp port 14570 remote port 14550
[INFO] [1573053706.065176, 0.000000]: Loading model XML from file /home/julianoes/src/Firmware/Tools/sitl_gazebo/models/iris/iris.sdf
[INFO] [1573053706.071883, 0.000000]: Waiting for service /gazebo/spawn_sdf_model
INFO  [mavlink] mode: Onboard, data rate: 4000000 B/s on udp port 14580 remote port 14540
INFO  [logger] logger started (mode=all)
INFO  [mavlink] MAVLink only on localhost (set param MAV_BROADCAST = 1 to enable network)
[ INFO] [1573053706.225771840]: udp0: Remote address: 127.0.0.1:14580
INFO  [mavlink] partner IP: 127.0.0.1
INFO  [px4] Startup script returned successfully
[ INFO] [1573053706.243969605]: CON: Got HEARTBEAT, connected. FCU: PX4 Autopilot
INFO  [logger] Start file log (type: full)
INFO  [logger] Opened full log file: ./log/2019-11-06/15_21_46.ulg
[ INFO] [1573053706.259724674]: FCU: [logger] file: ./log/2019-11-06/15_21_46.ulg
[ INFO] [1573053706.276610686, 0.032000000]: waitForService: Service [/gazebo/set_physics_properties] is now available.
[ INFO] [1573053706.329663569, 0.068000000]: Physics dynamic reconfigure ready.
[INFO] [1573053706.417740, 0.112000]: Calling service /gazebo/spawn_sdf_model
[INFO] [1573053706.609445, 0.164000]: Spawn status: SpawnModel: Successfully spawned entity
[Wrn] [gazebo_barometer_plugin.cpp:66] [gazebo_barometer_plugin] Using default home altitude of 488 m
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[0] no joint control will be performed for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[1] no joint control will be performed for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[2] no joint control will be performed for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[3] no joint control will be performed for this channel.
[Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::propeller_joint] not found for channel[4] no joint control for this channel.
[Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::flap_left_joint] not found for channel[5] no joint control for this channel.
[Wrn] [gazebo_mavlink_interface.cpp:124] joint [zephyr_delta_wing::flap_right_joint] not found for channel[6] no joint control for this channel.
[Dbg] [gazebo_mavlink_interface.cpp:135] <joint_name> not found for channel[7] no joint control will be performed for this channel.
[Msg] Connecting to PX4 SITL using TCP
[Msg] Lockstep is enabled
[Msg] Speed factor set to: 1
INFO  [simulator] Simulator connected on TCP port 4560.
[Msg] Using MAVLink protocol v2.0
px4_timestart_monotonic=168000  ---------------------------------------
received HIL sensors 0 168000
INFO  [simulator] HIL_SENSOR: imu time_usec: 168000, time_usec: 0, diff: 0, step: 0.00
DEBUG 0          All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 4000 172000
DEBUG 4000       All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 8000 176000
DEBUG 8000       All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
not available
published fallback at 12000
angular velocity update 0
received HIL sensors 12000 180000
DEBUG 12000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 16000 184000
DEBUG 16000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
not available
received HIL sensors 20000 188000
DEBUG 20000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
published fallback at 20000
not available
published fallback at 20000
angular velocity update 1
received HIL sensors 24000 192000
DEBUG 24000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 28000 196000
DEBUG 28000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 32000 200000
DEBUG 32000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
sending actuator outputs: 1
received HIL sensors 36000 204000
DEBUG 36000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
DEBUG 36000      sending controls t=32000 (204000)
received HIL sensors 40000 208000
DEBUG 40000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
received HIL sensors 44000 212000
DEBUG 44000      All sensor fields in mavlink HIL_SENSOR packet not updated.  Got 00000fff
SensorCorrectionsUpdate initialized
clear all registered callbacks: _selected_sensor: 0, corrections.selected_gyro_instance: 0
report.device_id: 2294028, _selected_sensor_device_id: 2294028, i: 0
INFO  [vehicle_angular_velocity] selected sensor (control) changed 0 -> 0
available: 44000
update not ok: 44000
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout
[Err] [gazebo_mavlink_interface.cpp:1155] poll timeout

@dagar
Copy link
Member

dagar commented Nov 18, 2019

Fixed!

@dagar dagar closed this Nov 18, 2019
@dagar dagar deleted the debug_gazebo_poll_timeouts branch November 18, 2019 16:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@bkueng @dagar @julianoes