PX4-Autopilot 🚀 - intermittent SITL test failures

2020-05-05T13:56:15.2536746Z ==> Running tests for standard_vtol
2020-05-05T13:56:15.2537022Z --> Test case 1 of 2: 'Takeoff and Land' running ...
2020-05-05T13:56:15.2537168Z [px4         ] INFO  [param] selected parameter default file eeprom/parameters_1040
2020-05-05T13:56:15.2537323Z [px4         ] [param] parameter file not found, creating eeprom/parameters_1040
2020-05-05T13:56:15.2538028Z [px4         ]   SYS_AUTOCONFIG: curr: 0 -> new: 1
2020-05-05T13:56:15.2538465Z [px4         ] * SYS_AUTOSTART: curr: 0 -> new: 1040
2020-05-05T13:56:15.2538767Z [px4         ]   BAT_N_CELLS: curr: 0 -> new: 3
2020-05-05T13:56:15.2539047Z [px4         ]   CAL_ACC0_ID: curr: 0 -> new: 1311244
2020-05-05T13:56:15.2539340Z [px4         ]   CAL_ACC_PRIME: curr: 0 -> new: 1311244
2020-05-05T13:56:15.2539628Z [px4         ]   CAL_GYRO0_ID: curr: 0 -> new: 2294028
2020-05-05T13:56:15.2539917Z [px4         ]   CAL_GYRO_PRIME: curr: 0 -> new: 2294028
2020-05-05T13:56:15.2540199Z [px4         ]   CAL_MAG0_ID: curr: 0 -> new: 197388
2020-05-05T13:56:15.2540484Z [px4         ]   CAL_MAG_PRIME: curr: 0 -> new: 197388
2020-05-05T13:56:15.2540764Z [px4         ]   COM_DISARM_LAND: curr: 2.0000 -> new: 0.5000
2020-05-05T13:56:15.2541039Z [px4         ]   COM_OBL_ACT: curr: 0 -> new: 2
2020-05-05T13:56:15.2541314Z [px4         ]   COM_RC_IN_MODE: curr: 0 -> new: 1
2020-05-05T13:56:15.2541607Z [px4         ]   EKF2_ANGERR_INIT: curr: 0.1000 -> new: 0.0100
2020-05-05T13:56:15.2541909Z [px4         ]   EKF2_GBIAS_INIT: curr: 0.1000 -> new: 0.0100
2020-05-05T13:56:15.2542202Z [px4         ]   COM_ARM_EKF_AB: curr: 0.0017 -> new: 0.0050
2020-05-05T13:56:15.2542497Z [px4         ]   EKF2_REQ_GPS_H: curr: 10.0000 -> new: 0.5000
2020-05-05T13:56:15.2542875Z [px4         ]   MC_PITCH_P: curr: 6.5000 -> new: 6.0000
2020-05-05T13:56:15.2543170Z [px4         ]   MC_PITCHRATE_P: curr: 0.1500 -> new: 0.2000
2020-05-05T13:56:15.2543456Z [px4         ]   MC_ROLL_P: curr: 6.5000 -> new: 6.0000
2020-05-05T13:56:15.2543748Z [px4         ]   MC_ROLLRATE_P: curr: 0.1500 -> new: 0.2000
2020-05-05T13:56:15.2544042Z [px4         ]   MPC_HOLD_MAX_Z: curr: 0.6000 -> new: 2.0000
2020-05-05T13:56:15.2544333Z [px4         ]   MPC_Z_VEL_I: curr: 0.1000 -> new: 0.1500
2020-05-05T13:56:15.2544623Z [px4         ]   MPC_Z_VEL_P: curr: 0.2000 -> new: 0.6000
2020-05-05T13:56:15.2544894Z [px4         ]   MPC_XY_P: curr: 0.9500 -> new: 0.8000
2020-05-05T13:56:15.2545185Z [px4         ]   MPC_XY_VEL_P: curr: 0.0900 -> new: 0.2000
2020-05-05T13:56:15.2545480Z [px4         ]   MPC_XY_VEL_D: curr: 0.0100 -> new: 0.0160
2020-05-05T13:56:15.2545777Z [px4         ]   MPC_SPOOLUP_TIME: curr: 1.0000 -> new: 0.5000
2020-05-05T13:56:15.2546075Z [px4         ]   MPC_TKO_RAMP_T: curr: 3.0000 -> new: 1.0000
2020-05-05T13:56:15.2546365Z [px4         ]   NAV_ACC_RAD: curr: 10.0000 -> new: 2.0000
2020-05-05T13:56:15.2546640Z [px4         ]   NAV_DLL_ACT: curr: 0 -> new: 2
2020-05-05T13:56:15.2546932Z [px4         ]   RTL_DESCEND_ALT: curr: 30.0000 -> new: 5.0000
2020-05-05T13:56:15.2547228Z [px4         ]   RTL_LAND_DELAY: curr: -1.0000 -> new: 5.0000
2020-05-05T13:56:15.2547524Z [px4         ]   RTL_RETURN_ALT: curr: 60.0000 -> new: 30.0000
2020-05-05T13:56:15.2547800Z [px4         ]   SDLOG_MODE: curr: 0 -> new: 1
2020-05-05T13:56:15.2548078Z [px4         ]   SDLOG_PROFILE: curr: 3 -> new: 131
2020-05-05T13:56:15.2548356Z [px4         ]   SDLOG_DIRS_MAX: curr: 0 -> new: 7
2020-05-05T13:56:15.2548649Z [px4         ]   SENS_BOARD_X_OFF: curr: 0.0000 -> new: 0.0000
2020-05-05T13:56:15.2548933Z [px4         ]   SENS_DPRES_OFF: curr: 0.0000 -> new: 0.0010
2020-05-05T13:56:15.2549212Z [px4         ]   TRIG_INTERFACE: curr: 4 -> new: 3
2020-05-05T13:56:15.2549509Z [px4         ]   COM_CPU_MAX: curr: 90.0000 -> new: -1.0000
2020-05-05T13:56:15.2549643Z [px4         ] COM_DL_LOSS_T set to 200
2020-05-05T13:56:15.2549922Z [px4         ]   COM_DL_LOSS_T: curr: 10 -> new: 200
2020-05-05T13:56:15.2550054Z [px4         ] COM_RC_LOSS_T set to 10.0
2020-05-05T13:56:15.2550343Z [px4         ]   COM_RC_LOSS_T: curr: 0.5000 -> new: 10.0000
2020-05-05T13:56:15.2550474Z [px4         ] COM_OF_LOSS_T set to 10.0
2020-05-05T13:56:15.2550760Z [px4         ]   COM_OF_LOSS_T: curr: 0.5000 -> new: 10.0000
2020-05-05T13:56:15.2551044Z [px4         ]   IMU_GYRO_RATEMAX: curr: 0 -> new: 400
2020-05-05T13:56:15.2551339Z [px4         ]   MIS_TAKEOFF_ALT: curr: 2.5000 -> new: 20.0000
2020-05-05T13:56:15.2551632Z [px4         ]   MIS_YAW_TMT: curr: -1.0000 -> new: 10.0000
2020-05-05T13:56:15.2552000Z [px4         ]   MPC_ACC_HOR_MAX: curr: 5.0000 -> new: 2.0000
2020-05-05T13:56:15.2552292Z [px4         ]   MPC_TKO_SPEED: curr: 1.5000 -> new: 1.0000
2020-05-05T13:56:15.2552591Z [px4         ]   MPC_VEL_MANUAL: curr: 10.0000 -> new: 3.0000
2020-05-05T13:56:15.2552883Z [px4         ]   MPC_XY_CRUISE: curr: 5.0000 -> new: 3.0000
2020-05-05T13:56:15.2553179Z [px4         ]   MPC_XY_VEL_MAX: curr: 12.0000 -> new: 4.0000
2020-05-05T13:56:15.2553473Z [px4         ]   MPC_Z_VEL_MAX_DN: curr: 1.0000 -> new: 1.5000
2020-05-05T13:56:15.2553766Z [px4         ]   MPC_JERK_MAX: curr: 8.0000 -> new: 4.5000
2020-05-05T13:56:15.2554055Z [px4         ] * NAV_ACC_RAD: curr: 2.0000 -> new: 3.0000
2020-05-05T13:56:15.2554349Z [px4         ] * RTL_LAND_DELAY: curr: 5.0000 -> new: 0.0000
2020-05-05T13:56:15.2554623Z [px4         ]   RTL_TYPE: curr: 0 -> new: 1
2020-05-05T13:56:15.2554891Z [px4         ]   WV_EN: curr: 0 -> new: 1
2020-05-05T13:56:15.2555179Z [px4         ]   FW_AIRSPD_MAX: curr: 20.0000 -> new: 25.0000
2020-05-05T13:56:15.2555474Z [px4         ]   FW_AIRSPD_MIN: curr: 10.0000 -> new: 14.0000
2020-05-05T13:56:15.2555770Z [px4         ]   FW_AIRSPD_TRIM: curr: 15.0000 -> new: 16.0000
2020-05-05T13:56:15.2556140Z [px4         ]   FW_L1_PERIOD: curr: 20.0000 -> new: 12.0000
2020-05-05T13:56:15.2556417Z [px4         ] * MC_ROLLRATE_P: curr: 0.2000 -> new: 0.3000
2020-05-05T13:56:15.2556716Z [px4         ]   MIS_LTRMIN_ALT: curr: -1.0000 -> new: 10.0000
2020-05-05T13:56:15.2557012Z [px4         ] * MIS_TAKEOFF_ALT: curr: 20.0000 -> new: 10.0000
2020-05-05T13:56:15.2557304Z [px4         ]   MPC_THR_MIN: curr: 0.1200 -> new: 0.1000
2020-05-05T13:56:15.2557595Z [px4         ] * MPC_XY_VEL_D: curr: 0.0160 -> new: 0.0050
2020-05-05T13:56:15.2557884Z [px4         ]   MPC_XY_VEL_I: curr: 0.0200 -> new: 0.2000
2020-05-05T13:56:15.2558171Z [px4         ] * MPC_XY_VEL_P: curr: 0.2000 -> new: 0.1500
2020-05-05T13:56:15.2558567Z [px4         ] * NAV_ACC_RAD: curr: 3.0000 -> new: 5.0000
2020-05-05T13:56:15.2558850Z [px4         ]   NAV_LOITER_RAD: curr: 50.0000 -> new: 80.0000
2020-05-05T13:56:15.2559306Z [px4         ]   VT_F_TRANS_THR: curr: 1.0000 -> new: 0.7500
2020-05-05T13:56:15.2559599Z [px4         ]   VT_ARSP_TRANS: curr: 10.0000 -> new: 16.0000
2020-05-05T13:56:15.2559891Z [px4         ]   VT_MOT_ID: curr: 0 -> new: 1234
2020-05-05T13:56:15.2560174Z [px4         ]   VT_FW_MOT_OFFID: curr: 0 -> new: 1234
2020-05-05T13:56:15.2560446Z [px4         ]   VT_TYPE: curr: 0 -> new: 2
2020-05-05T13:56:15.2560718Z [px4         ]   VT_B_TRANS_DUR: curr: 4.0000 -> new: 8.0000
2020-05-05T13:56:15.2561000Z [px4         ] * SYS_AUTOCONFIG: curr: 1 -> new: 0
2020-05-05T13:56:15.2561290Z [gzserver    ] Gazebo multi-robot simulator, version 9.12.0
2020-05-05T13:56:15.2561430Z [gzserver    ] Copyright (C) 2012 Open Source Robotics Foundation.
2020-05-05T13:56:15.2561565Z [gzserver    ] Released under the Apache 2 License.
2020-05-05T13:56:15.2561748Z [gzserver    ] http://gazebosim.org
2020-05-05T13:56:15.2562070Z [gzserver    ] [1;32m[Msg] [0m[1;32mWaiting for master.[0m[1;32m
2020-05-05T13:56:15.2562492Z [gzserver    ] [0m[1;32m[0m[1;32m[Msg] [0m[1;32mConnected to gazebo master @ [0m[1;32mhttp://127.0.0.1:11345[0m[1;32m
2020-05-05T13:56:15.2562899Z [gzserver    ] [0m[1;32m[0m[1;32m[Msg] [0m[1;32mPublicized address: [0m[1;32m172.18.0.2[0m[1;32m
2020-05-05T13:56:15.2563288Z [gzserver    ] [0m[1;32m[0m[1;31m[Err] [RenderEngine.cc:738] [0m[1;31mCan't open display: [0m[1;31m:99[0m[1;31m
2020-05-05T13:56:15.2563664Z [gzserver    ] [0m[1;33m[Wrn] [RenderEngine.cc:87] [0m[1;33mUnable to create X window. Rendering will be disabled
2020-05-05T13:56:15.2564147Z [gzserver    ] [0m[1;33m[Wrn] [RenderEngine.cc:287] [0m[1;33mCannot initialize render engine since [0m[1;33mrender path type is NONE. Ignore this warning if[0m[1;33mrendering has been turned off on purpose.
2020-05-05T13:56:15.2564315Z [mavsdk_tests] Filters: Takeoff and Land
2020-05-05T13:56:15.2564712Z [mavsdk_tests] [34m[01:55:46|Info ] [0mMAVSDK version: 0.24.0 (mavsdk_impl.cpp:25)
2020-05-05T13:56:15.2564866Z [mavsdk_tests] Waiting for system connect
2020-05-05T13:56:15.2565239Z [gzserver    ] [0m[1;31m[Err] [liftdrag_plugin.cpp:158] [0m[1;31m[gazebo_wind_plugin] Please specify a robotNamespace.
2020-05-05T13:56:15.2565621Z [gzserver    ] [0m[1;31m[Err] [liftdrag_plugin.cpp:158] [0m[1;31m[gazebo_wind_plugin] Please specify a robotNamespace.
2020-05-05T13:56:15.2565987Z [gzserver    ] [0m[1;31m[Err] [liftdrag_plugin.cpp:158] [0m[1;31m[gazebo_wind_plugin] Please specify a robotNamespace.
2020-05-05T13:56:15.2566358Z [gzserver    ] [0m[1;31m[Err] [liftdrag_plugin.cpp:158] [0m[1;31m[gazebo_wind_plugin] Please specify a robotNamespace.
2020-05-05T13:56:15.2566714Z [gzserver    ] [0m[1;32m[Msg] [0m[1;32mConnecting to PX4 SITL using [0m[1;32mTCP[0m[1;32m
2020-05-05T13:56:15.2567049Z [gzserver    ] [0m[1;32m[Msg] [0m[1;32mLockstep is [0m[1;32menabled[0m[1;32m
2020-05-05T13:56:15.2567390Z [gzserver    ] [0m[1;32m[Msg] [0m[1;32mSpeed factor set to: [0m[1;32m20[0m[1;32m
2020-05-05T13:56:15.2567708Z [gzserver    ] [0m[1;32m[Msg] [0m[1;32mUsing MAVLink protocol v2.0
2020-05-05T13:56:15.2568251Z [gzserver    ] [0m[1;33m[Wrn] [Publisher.cc:135] [0m[1;33mQueue limit reached for topic [0m[1;33m/gazebo/default/standard_vtol/imu[0m[1;33m, deleting message. [0m[1;33mThis warning is printed only once.[0m[1;33m
2020-05-05T13:56:15.2568779Z [gzserver    ] [0m[1;33m[0m[1;33m[Wrn] [Publisher.cc:135] [0m[1;33mQueue limit reached for topic [0m[1;33m/gazebo/default/standard_vtol/groundtruth[0m[1;33m, deleting message. [0m[1;33mThis warning is printed only once.[0m[1;33m
2020-05-05T13:56:15.2569305Z [gzserver    ] [0m[1;33m[0m[1;33m[Wrn] [Publisher.cc:135] [0m[1;33mQueue limit reached for topic [0m[1;33m/gazebo/default/standard_vtol/mag[0m[1;33m, deleting message. [0m[1;33mThis warning is printed only once.[0m[1;33m
2020-05-05T13:56:15.2569819Z [gzserver    ] [0m[1;33m[0m[1;33m[Wrn] [Publisher.cc:135] [0m[1;33mQueue limit reached for topic [0m[1;33m/gazebo/default/physics/contacts[0m[1;33m, deleting message. [0m[1;33mThis warning is printed only once.[0m[1;33m
2020-05-05T13:56:15.2570327Z [gzserver    ] [0m[1;33m[0m[1;33m[Wrn] [Publisher.cc:135] [0m[1;33mQueue limit reached for topic [0m[1;33m/gazebo/default/standard_vtol/baro[0m[1;33m, deleting message. [0m[1;33mThis warning is printed only once.[0m[1;33m
2020-05-05T13:56:15.2570828Z [gzserver    ] [0m[1;33m[0m[1;33m[Wrn] [Publisher.cc:135] [0m[1;33mQueue limit reached for topic [0m[1;33m/gazebo/default/standard_vtol/gps[0m[1;33m, deleting message. [0m[1;33mThis warning is printed only once.[0m[1;33m
2020-05-05T13:56:15.2571266Z [gzserver    ] [0m[1;33m[0m[1;31m[Err] [gazebo_mavlink_interface.cpp:826] [0m[1;31mSkipped [0m[1;31m1586[0m[1;31m IMU samples (presumably CPU usage is too high)
2020-05-05T13:56:15.2571637Z [gzserver    ] [0m[mavsdk_tests] ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2020-05-05T13:56:15.2571792Z [mavsdk_tests] mavsdk_tests is a Catch v2.9.2 host application.
2020-05-05T13:56:15.2572058Z [mavsdk_tests] Run with -? for options
2020-05-05T13:56:15.2572496Z [mavsdk_tests] -------------------------------------------------------------------------------
2020-05-05T13:56:15.2572628Z [mavsdk_tests] Takeoff and Land
2020-05-05T13:56:15.2572924Z [mavsdk_tests] -------------------------------------------------------------------------------
2020-05-05T13:56:15.2573068Z [mavsdk_tests] /__w/Firmware/Firmware/test/mavsdk_tests/test_multicopter_mission.cpp:42
2020-05-05T13:56:15.2573209Z [mavsdk_tests] ...............................................................................
2020-05-05T13:56:15.2573348Z [mavsdk_tests] /__w/Firmware/Firmware/test/mavsdk_tests/autopilot_tester.cpp:47: FAILED:
2020-05-05T13:56:15.2573659Z [mavsdk_tests]   REQUIRE( poll_condition_with_timeout( [this]() { return _mavsdk.is_connected(); }, std::chrono::seconds(25)) )
2020-05-05T13:56:15.2573873Z [mavsdk_tests] with expansion:
2020-05-05T13:56:15.2573992Z [mavsdk_tests]   false
2020-05-05T13:56:15.2574120Z [mavsdk_tests] ===============================================================================
2020-05-05T13:56:15.2574237Z [mavsdk_tests] test cases: 1 | 1 failed
2020-05-05T13:56:15.2574359Z [mavsdk_tests] assertions: 2 | 1 passed | 1 failed
2020-05-05T13:56:15.2574439Z 
2020-05-05T13:56:15.2574547Z Logfiles: 
2020-05-05T13:56:15.2574852Z   - logs/2020-05-05T13-48-18Z/standard_vtol/Takeoff_and_Land/log-combined.log
2020-05-05T13:56:15.2575145Z   - logs/2020-05-05T13-48-18Z/standard_vtol/Takeoff_and_Land/log-px4.log
2020-05-05T13:56:15.2575441Z   - logs/2020-05-05T13-48-18Z/standard_vtol/Takeoff_and_Land/log-gzserver.log
2020-05-05T13:56:15.2575743Z   - logs/2020-05-05T13-48-18Z/standard_vtol/Takeoff_and_Land/log-gzmodelspawn.log
2020-05-05T13:56:15.2576031Z   - logs/2020-05-05T13-48-18Z/standard_vtol/Takeoff_and_Land/log-mavsdk_tests.log
2020-05-05T13:56:15.2576299Z --- Test case 1 of 2: 'Takeoff and Land' failed.
2020-05-05T13:56:15.2576419Z Aborting early
2020-05-05T13:56:15.2576488Z 
2020-05-05T13:56:15.2576598Z Results:
2020-05-05T13:56:15.2576877Z   - iris:
2020-05-05T13:56:15.2577106Z      - 'Offboard takeoff and land': succeeded
2020-05-05T13:56:15.2577553Z      - 'Offboard position control': succeeded
2020-05-05T13:56:15.2577810Z      - 'Takeoff and Land': succeeded
2020-05-05T13:56:15.2578066Z      - 'Fly square Multicopter Missions': succeeded
2020-05-05T13:56:15.2578297Z   - iris_opt_flow_mockup:
2020-05-05T13:56:15.2578542Z      - 'Offboard takeoff and land': succeeded
2020-05-05T13:56:15.2578787Z      - 'Offboard position control': succeeded
2020-05-05T13:56:15.2579019Z   - iris_vision_velocity:
2020-05-05T13:56:15.2579264Z      - 'Offboard takeoff and land': succeeded
2020-05-05T13:56:15.2579508Z      - 'Offboard position control': succeeded
2020-05-05T13:56:15.2579726Z   - iris_vision:
2020-05-05T13:56:15.2579972Z      - 'Offboard takeoff and land': succeeded
2020-05-05T13:56:15.2580207Z      - 'Offboard position control': succeeded
2020-05-05T13:56:15.2580433Z   - standard_vtol:
2020-05-05T13:56:15.2580669Z      - 'Takeoff and Land': failed
2020-05-05T13:56:15.2580926Z      - 'Fly square Multicopter Missions': cancelled
2020-05-05T13:56:15.2581046Z Overall result: FAIL

julianoes on 5 May 2020

https://github.com/PX4/Firmware/pull/14836/checks?check_run_id=646686108

dagar on 5 May 2020

https://github.com/PX4/Firmware/runs/649658989

dagar on 6 May 2020

https://github.com/PX4/Firmware/pull/14846/checks?check_run_id=649765804

dagar on 6 May 2020

https://github.com/PX4/Firmware/runs/649760590

dagar on 6 May 2020

https://github.com/PX4/Firmware/runs/650254506

dagar on 6 May 2020

Environment permission issues?

Home directory not accessible: Permission denied
Screenshot from 2020-05-06 13-52-23

https://github.com/PX4/Firmware/pull/14825/checks?check_run_id=650245030

dagar on 6 May 2020

https://github.com/PX4/Firmware/pull/14755/checks?check_run_id=645956081

dagar on 6 May 2020

Screenshot from 2020-05-06 15-12-35
https://github.com/PX4/Firmware/pull/14850/checks?check_run_id=650628730

dagar on 6 May 2020

Screenshot from 2020-05-06 16-58-14

https://github.com/PX4/Firmware/pull/14504/checks?check_run_id=650483012

dagar on 6 May 2020

Screenshot from 2020-05-06 21-11-41
https://github.com/PX4/Firmware/pull/14853/checks?check_run_id=651461557

dagar on 7 May 2020

Screenshot from 2020-05-07 01-34-52

https://github.com/PX4/Firmware/runs/651891362

dagar on 7 May 2020

Screenshot from 2020-05-07 14-09-39
https://github.com/PX4/Firmware/pull/14844/checks?check_run_id=652124079

dagar on 7 May 2020

Screenshot from 2020-05-07 15-00-13
https://github.com/PX4/Firmware/pull/14844/checks?check_run_id=654078516

dagar on 7 May 2020

https://github.com/PX4/Firmware/pull/14871/checks?check_run_id=656614110

dagar on 8 May 2020

https://github.com/PX4/Firmware/runs/656856709

dagar on 8 May 2020

https://github.com/PX4/Firmware/pull/14883/checks?check_run_id=661319771

dagar on 10 May 2020

https://github.com/PX4/Firmware/pull/14884/checks?check_run_id=661426027

dagar on 10 May 2020

https://github.com/PX4/Firmware/pull/14885/checks?check_run_id=661428233

dagar on 10 May 2020

FYI @kamilritz here are some CI failures collected.

julianoes on 14 May 2020

I can now reproduce the "connection" problem locally in docker. It has something to do with px4 not terminating properly, or not cleaning up the lock file properly. The problem persists until I remove it by rm /tmp/px4_lock-0.

julianoes on 19 May 2020

👍1

That is awesome. I also experience this sometimes locally. And it seems like the px4 process is still running after the termination of the test.

kamilritz on 19 May 2020

If px4 is still running then it would ignore SIGKILL which is quite unlikely :astonished:

Edit: I'm going to keep debugging this today.

julianoes on 20 May 2020

@kamilritz it might be the case that the current CI failures are actual failures. I also see them locally, and in the log the ground truth seem to be quite a bit off.

https://logs.px4.io/plot_app?log=6e903edc-d396-4a6f-9971-2b20a93ee7ce

julianoes on 20 May 2020

@julianoes But this is not always the case. It is just not repeatable, right?

kamilritz on 20 May 2020

@kamilritz not always but sometimes. It happens to me when I run it locally for 10+ times. The test needs to be repeatable, otherwise we'll just have to disable it again :disappointed: .

julianoes on 25 May 2020

@julianoes Is it always the same test case? Which one/s?

kamilritz on 25 May 2020

I believe the vision or vision velocity one. Let me run the test again and see.

julianoes on 25 May 2020

Ok, I can have a look this evening. It could be that by speeding up the tests, the robustness decreased.

kamilritz on 25 May 2020

👍1

@kamilritz I just ran 30 tries at 20x and it never failed :thinking:

julianoes on 25 May 2020

Here is an example where the estimation goes wild:

However, this still fails sometimes locally, here is an example where the estimation is bonkers:
https://logs.px4.io/plot_app?log=af8d98b8-3042-4e1d-bf43-ca97a5cf9bd0

julianoes on 26 May 2020

Here is another strange failure:
https://logs.px4.io/plot_app?log=1ffedfd0-812c-4cb0-8b26-a2e6b2e698fd

This one actually flips and crashes!

--> Test case 4 of 4: 'Fly square Multicopter Missions' running ...
creating log directory: logs/2020-05-26T15-01-02Z/02/iris/Fly_square_Multicopter_Missions
Running: /home/julianoes/src/Firmware/build/px4_sitl_default/bin/px4 /home/julianoes/src/Firmware/ROMFS/px4fmu_common -s etc/init.d-posix/rcS -t /home/julianoes/src/Firmware/test_data -d
Logging to logs/2020-05-26T15-01-02Z/02/iris/Fly_square_Multicopter_Missions/log-px4.log
Running: gzserver --verbose /home/julianoes/src/Firmware/Tools/sitl_gazebo/worlds/empty.world
Logging to logs/2020-05-26T15-01-02Z/02/iris/Fly_square_Multicopter_Missions/log-gzserver.log
Running: gz model --spawn-file /home/julianoes/src/Firmware/Tools/sitl_gazebo/models/iris/iris.sdf --model-name iris -x 1.01 -y 0.98 -z 0.83
Logging to logs/2020-05-26T15-01-02Z/02/iris/Fly_square_Multicopter_Missions/log-gzmodelspawn.log
Running: /home/julianoes/src/Firmware/build/px4_sitl_default/mavsdk_tests/mavsdk_tests --url udp://:14540 Fly square Multicopter Missions
Logging to logs/2020-05-26T15-01-02Z/02/iris/Fly_square_Multicopter_Missions/log-mavsdk_tests.log
[px4         ] INFO  [px4] Creating symlink /home/julianoes/src/Firmware/ROMFS/px4fmu_common -> /home/julianoes/src/Firmware/build/px4_sitl_default/tmp/rootfs/etc
[px4         ] ______  __   __    ___ 
[px4         ] | ___ \ \ \ / /   /   |
[px4         ] | |_/ /  \ V /   / /| |
[px4         ] |  __/   /   \  / /_| |
[px4         ] | |     / /^\ \ \___  |
[px4         ] \_|     \/   \/     |_/
[px4         ] px4 starting.
[px4         ] INFO  [px4] Calling startup script: /bin/sh etc/init.d-posix/rcS 0
[px4         ] INFO  [param] selected parameter default file eeprom/parameters_10016
[px4         ] [param] Loaded: eeprom/parameters_10016
[px4         ] COM_DL_LOSS_T set to 100
[px4         ] COM_RC_LOSS_T set to 5.0
[px4         ] COM_OF_LOSS_T set to 5.0
[px4         ] INFO  [dataman] Unknown restart, data manager file './dataman' size is 11798680 bytes
[px4         ] INFO  [simulator] Waiting for simulator to accept connection on TCP port 4560
[px4         ] INFO  [simulator] Simulator connected on TCP port 4560.
[px4         ] INFO  [commander] LED: open /dev/led0 failed (22)
[px4         ] INFO  [commander] Mission #2 loaded, 3 WPs, curr: 0
[px4         ] INFO  [init] Mixer: etc/mixers/quad_w.main.mix on /dev/pwm_output0
[px4         ] INFO  [mavlink] mode: Normal, data rate: 4000000 B/s on udp port 18570 remote port 14550
[px4         ] INFO  [mavlink] mode: Onboard, data rate: 4000000 B/s on udp port 14580 remote port 14540
[px4         ] INFO  [mavlink] mode: Onboard, data rate: 4000 B/s on udp port 14280 remote port 14030
[px4         ] INFO  [logger] logger started (mode=all)
[px4         ] INFO  [logger] Start file log (type: full)
[px4         ] INFO  [logger] [logger] ./log/2020-05-26/13_06_11.ulg
[px4         ] INFO  [logger] Opened full log file: ./log/2020-05-26/13_06_11.ulg
[px4         ] INFO  [mavlink] MAVLink only on localhost (set param MAV_BROADCAST = 1 to enable network)
[px4         ] INFO  [px4] Startup script returned successfully
[px4         ] INFO  [ecl/EKF] 808000: GPS checks passed
[px4         ] INFO  [ecl/EKF] 1844000: EKF aligned, (baro hgt, IMU buf: 18, OBS buf: 14)
[px4         ] INFO  [ecl/EKF] 1844000: reset position to last known position
[px4         ] INFO  [ecl/EKF] 1844000: reset velocity to zero
[px4         ] INFO  [ecl/EKF] 5396000: reset position to GPS
[px4         ] INFO  [ecl/EKF] 5396000: reset velocity to GPS
[px4         ] INFO  [ecl/EKF] 5396000: starting GPS fusion
[px4         ] INFO  [mavlink] partner IP: 127.0.0.1
[gzserver    ] Gazebo multi-robot simulator, version 9.13.0
[gzserver    ] Copyright (C) 2012 Open Source Robotics Foundation.
[gzserver    ] Released under the Apache 2 License.
[gzserver    ] http://gazebosim.org
[mavsdk_tests] Filters: Fly square Multicopter Missions
[mavsdk_tests] [03:06:12|Info ] MAVSDK version: 0.24.0 (mavsdk_impl.cpp:25)
[mavsdk_tests] Waiting for system connect
[mavsdk_tests] [03:06:12|Info ] New system on: 127.0.0.1:14580 (udp_connection.cpp:264)
[mavsdk_tests] [03:06:12|Debug] New: System ID: 1 Comp ID: 1 (mavsdk_impl.cpp:401)
[mavsdk_tests] [03:06:12|Debug] Component Autopilot (1) added. (system_impl.cpp:386)
[mavsdk_tests] [03:06:12|Debug] Discovered 1 component(s) (UUID: 5283920058631409231) (system_impl.cpp:556)
[mavsdk_tests] Waiting for system to be ready
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4252 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3652 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3052 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2452 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1852 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1252 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 652 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 52 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4116 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3516 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2916 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2316 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1716 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1116 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 516 ms
[mavsdk_tests] [03:06:16|Debug] Send mission item 0 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:16|Debug] Send mission item 1 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:16|Debug] Send mission item 2 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:16|Debug] Send mission item 3 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:16|Info ] Mission accepted (mission_impl.cpp:171)
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 40 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4164 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3564 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2964 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2364 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1764 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1164 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 564 ms
[px4         ] INFO  [commander] ARMED by Arm/Disarm component command
[px4         ] INFO  [navigator] Takeoff to 10.0 meters above home.
[px4         ] INFO  [commander] Takeoff detected
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4208 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3608 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3008 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2408 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1808 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1208 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 608 ms
[mavsdk_tests] [03:06:17|Debug] MAVLink: info: ARMED by Arm/Disarm component command (system_impl.cpp:292)
[mavsdk_tests] [03:06:17|Debug] MAVLink: info: Takeoff to 10.0 meters above home. (system_impl.cpp:292)
[mavsdk_tests] [03:06:17|Debug] MAVLink: info: Takeoff detected (system_impl.cpp:292)
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3984 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3384 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2784 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2184 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1584 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 984 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 384 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4231 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3631 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3031 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2431 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1831 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1231 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 631 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 31 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4116 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3516 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2916 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2316 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1716 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1116 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 516 ms
[px4         ] INFO  [commander] Returning to launch
[px4         ] INFO  [navigator] RTL HOME activated
[px4         ] INFO  [navigator] RTL: landing at home position.
[px4         ] INFO  [navigator] RTL: climb to 30 m (30 m above destination)
[mavsdk_tests] [03:06:22|Debug] MAVLink: info: Returning to launch (system_impl.cpp:292)
[mavsdk_tests] [03:06:22|Debug] MAVLink: info: RTL HOME activated (system_impl.cpp:292)
[mavsdk_tests] [03:06:22|Debug] MAVLink: info: RTL: landing at home position. (system_impl.cpp:292)
[mavsdk_tests] [03:06:22|Debug] MAVLink: info: RTL: climb to 30 m (30 m above destination) (system_impl.cpp:292)
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] INFO  [navigator] RTL: return at 30 m (30 m above destination)
[px4         ] INFO  [navigator] RTL: land at destination
[mavsdk_tests] [03:06:23|Debug] MAVLink: info: RTL: return at 30 m (30 m above destination) (system_impl.cpp:292)
[mavsdk_tests] [03:06:23|Debug] MAVLink: info: RTL: land at destination (system_impl.cpp:292)
[px4         ] INFO  [commander] Landing detected
[px4         ] INFO  [commander] DISARMED by Auto disarm initiated
[px4         ] INFO  [logger] closed logfile, bytes written: 6975455
[mavsdk_tests] [03:06:31|Debug] MAVLink: info: Landing detected (system_impl.cpp:292)
[mavsdk_tests] [03:06:31|Debug] MAVLink: info: DISARMED by Auto disarm initiated (system_impl.cpp:292)
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[mavsdk_tests] [03:06:35|Info ] MAVSDK version: 0.24.0 (mavsdk_impl.cpp:25)
[mavsdk_tests] Waiting for system connect
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1208 ms
[mavsdk_tests] [03:06:35|Info ] New system on: 127.0.0.1:14580 (udp_connection.cpp:264)
[mavsdk_tests] [03:06:35|Debug] New: System ID: 1 Comp ID: 1 (mavsdk_impl.cpp:401)
[mavsdk_tests] [03:06:35|Debug] Component Autopilot (1) added. (system_impl.cpp:386)
[mavsdk_tests] [03:06:35|Debug] Discovered 1 component(s) (UUID: 5283920058631409231) (system_impl.cpp:556)
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4480 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3960 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4424 ms
[mavsdk_tests] Waiting for system to be ready
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4436 ms
[mavsdk_tests] [03:06:38|Warn ] sending again, retries to do: 3  (511). (mavlink_commands.cpp:222)
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4332 ms
[mavsdk_tests] [03:06:38|Warn ] sending again, retries to do: 2  (511). (mavlink_commands.cpp:222)
[mavsdk_tests] [03:06:38|Warn ] sending again, retries to do: 3  (CAL_GYRO0_ID). (mavlink_parameters.cpp:458)
[mavsdk_tests] [03:06:39|Debug] Send mission item 0 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:39|Debug] Send mission item 1 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:39|Debug] Send mission item 2 (mission_impl.cpp:1201)
[mavsdk_tests] [03:06:39|Info ] Mission accepted (mission_impl.cpp:171)
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] INFO  [commander] ARMED by Arm/Disarm component command
[px4         ] INFO  [logger] Start file log (type: full)
[px4         ] INFO  [logger] [logger] ./log/2020-05-26/13_06_39.ulg
[px4         ] INFO  [logger] Opened full log file: ./log/2020-05-26/13_06_39.ulg
[px4         ] INFO  [navigator] Takeoff to 10.0 meters above home.
[px4         ] INFO  [commander] Takeoff detected
[mavsdk_tests] [03:06:40|Debug] MAVLink: info: ARMED by Arm/Disarm component command (system_impl.cpp:292)
[mavsdk_tests] [03:06:40|Debug] MAVLink: info: [logger] ./log/2020-05-26/13_06_39.ulg (system_impl.cpp:292)
[mavsdk_tests] [03:06:40|Debug] MAVLink: info: Takeoff to 10.0 meters above home. (system_impl.cpp:292)
[mavsdk_tests] [03:06:40|Debug] MAVLink: info: Takeoff detected (system_impl.cpp:292)
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3764 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3164 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2564 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1964 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1364 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 764 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 164 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2848 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2248 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1648 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1048 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 448 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3856 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3256 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2656 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 2056 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 1456 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 856 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 256 ms
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[px4         ] ERROR [mavlink] [timesync] Time jump detected. Resetting time synchroniser.
[mavsdk_tests] ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[mavsdk_tests] mavsdk_tests is a Catch v2.9.2 host application.
[mavsdk_tests] Run with -? for options
[mavsdk_tests] -------------------------------------------------------------------------------
[mavsdk_tests] Fly square Multicopter Missions
[mavsdk_tests]   Mission with manual RTL
[mavsdk_tests] -------------------------------------------------------------------------------
[mavsdk_tests] /home/julianoes/src/Firmware/test/mavsdk_tests/test_multicopter_mission.cpp:70
[mavsdk_tests] ...............................................................................
[mavsdk_tests] /home/julianoes/src/Firmware/test/mavsdk_tests/autopilot_tester.cpp:180: FAILED:
[mavsdk_tests]   REQUIRE( poll_condition_with_timeout( [this]() { return _mission->mission_finished(); }, std::chrono::seconds(60)) )
[mavsdk_tests] with expansion:
[mavsdk_tests]   false
[mavsdk_tests] [03:07:46|Info ] MAVSDK version: 0.24.0 (mavsdk_impl.cpp:25)
[mavsdk_tests] Waiting for system connect
[mavsdk_tests] [03:07:46|Info ] New system on: 127.0.0.1:14580 (udp_connection.cpp:264)
[mavsdk_tests] [03:07:46|Debug] New: System ID: 1 Comp ID: 1 (mavsdk_impl.cpp:401)
[mavsdk_tests] [03:07:46|Debug] Component Autopilot (1) added. (system_impl.cpp:386)
[mavsdk_tests] [03:07:46|Debug] Discovered 1 component(s) (UUID: 5283920058631409231) (system_impl.cpp:556)
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 3472 ms
[px4         ] WARN  [mavlink] [timesync] RTT too high for timesync: 4132 ms
[mavsdk_tests] Waiting for system to be ready
[mavsdk_tests] ===============================================================================
[mavsdk_tests] test cases:  1 |  0 passed | 1 failed
[mavsdk_tests] assertions: 25 | 24 passed | 1 failed
Terminating /home/julianoes/src/Firmware/build/px4_sitl_default/bin/px4
/home/julianoes/src/Firmware/build/px4_sitl_default/bin/px4 exited with 0
Terminating gzserver
gzserver exited with -15
gz exited with 0
/home/julianoes/src/Firmware/build/px4_sitl_default/mavsdk_tests/mavsdk_tests exited with 1
[px4         ] PX4 Exiting...
[px4         ] Exiting NOW.
[gzserver    ] [Msg] Waiting for master.
[gzserver    ] [Msg] Connected to gazebo master @ http://127.0.0.1:11345
[gzserver    ] [Msg] Publicized address: 10.0.2.15
[gzserver    ] [Msg] Connecting to PX4 SITL using TCP
[gzserver    ] [Msg] Lockstep is enabled
[gzserver    ] [Msg] Speed factor set to: 10
[gzserver    ] [Msg] Using MAVLink protocol v2.0
[gzserver    ] [Err] [gazebo_mavlink_interface.cpp:1389] recvfrom error: Connection reset by peer
[gzserver    ] [Err] [gazebo_mavlink_interface.cpp:1396] Connection closed by client.

julianoes on 26 May 2020

Keeping this open to track more failures.

julianoes on 29 May 2020

Closing for now until we see it again.

julianoes on 4 Jun 2020

Px4-autopilot: intermittent SITL test failures

All 34 comments

Related issues