Help me understand a few ominous sounding entries in the event stream

[Deleted member 94047]

I had a simple flight in the morning today. I had a battery to discharge and no specific flight plan. I sent it up straight to 120m, took a few shots, tried one or two panos; recorded on the way down, and landed (manually) at battery =17%. It was not a perfect landing. The rear end of the MA missed the edge of the hard case I sometimes use as a landing pad and ended up with the front legs straddling the case and the rear on the ground with one of the front props scrapping the edge of the case. But the motors cut off pretty quickly and I did a visual inspection immediately. Everything looked good, one of the props had a very minor dent on its outer most edge, that was all. I wanted to do a quick check to see all was well and I rearmed the motors, did a manual takeoff and hand landed. All seemed well.

Later, while reviewing the flight logs, I came across these entries. The first four lines with the 672s timestamp happened while I was still in the air. I believe the later entries with the 819s timestamp occurred in the brief take off and landing I did after the first hard landing.

672.735 : {task_e}INFO:i2c3 core recovery||
672.750 : {task_e}INFO:i2c3 core recovery||
672.765 : {task_e}INFO:i2c3 core recovery||
672.765 : {task_e}INFO:smbus_read CMD_PRESENT_STATE error||
.........................
819.656 : 46066 [L-NS][comm] ext ns disconnect2
819.706 : 46069 [L-NS][AHRS] Bad sample tick measure or recapture signal: 0.010000
819.706 : 46069 [L-FDI]NS(0) FUSION(1): fault on , disconnect
819.706 : 46069 [L-FDI]ns req:fdi,1to0,reason:imu.disconnect,result:succeed
819.706 : 46069 [L-FMU/DM]Busy Device Changed. Type:imu0_local, <ID:17 idx:1-->ID:8 idx:0>, change tim
819.708 : 46069 [L-FDI][FDI][NS] remove multi atti index 1
819.816 : 46074 [L-NS][comm] ext ns connect2
819.816 : 46074 [L-NS][ext ns] too LATE! delay_idx:73 imu_local:924360 fusion:924177
819.826 : 46075 [L-FDI]NS(0) FUSION(1): fault off, disconnect
819.826 : 46075 [L-FDI]ns req:fdi,0to1,reason:normal,result:succeed
819.826 : 46075 [L-FMU/DM]Busy Device Changed. Type:imu1_ext_ns, <ID:8 idx:0-->ID:17 idx:1>, change ti
819.828 : 46075 [L-FDI][FDI][NS] add multi atti index 1
819.906 : 46079 [L-FDI]NS(0) VO(0): fault on , disconnect
819.946 : 46081 [L-FDI]NS(0) VO(0): fault off, disconnect

I will greatly appreciate any pointers as to what these mean. Thanks!

EDIT: After a search for flight records shared here containing these entries; I am more concerned and uncertain as to whether I should fly the MA again. @sar104 , @BudWalker , @Meta4 if you guys can advise, I would be most thankful.

 

[sar104]

I've seen the core recovery errors precede failure, and there is some evidence that it is, at least sometimes, related to battery communication errors.

Occasional fusion errors are quite common, as is. the bad tick sample message.

 

[Deleted member 94047]

I've seen the core recovery errors precede failure, and there is some evidence that it is, at least sometimes, related to battery communication errors.

Occasional fusion errors are quite common, as is. the bad tick sample message.

Thanks Sar; a quick follow up if you can spare a few minutes. I want to do a test flight to see if any of these reoccur. Will I have to do it outdoors with the bird in the air or will an indoors hover without GPS be enough to verify if the issue is persistent? Can I do an outdoor test without the props? The later would be the safest option but I am not sure if it will be enough to confirm the AC is fit to fly.

 

[sar104]

Thanks Sar; a quick follow up if you can spare a few minutes. I want to do a test flight to see if any of these reoccur. Will I have to do it outdoors with the bird in the air or will an indoors hover without GPS be enough to verify if the issue is persistent? Can I do an outdoor test without the props? The later would be the safest option but I am not sure if it will be enough to confirm the AC is fit to fly.

The battery errors, if that is what they were, should be the same either way.

 

[Deleted member 94047]

Update
I did two early morning test flight and reviewed the DAT files. I found these entries in one (flight was done with the same battery as yesterday's problem flight). The other flight's log looked OK.

727.254 : {task_e}INFO:i2c3 core recovery||
727.255 : {task_e}INFO:[I2C-L623]:bus_idle time out! MA:1, TFE:0
727.256 : {task_e}INFO:i2c3 Critical error in master_xfer ||
727.256 : {task_e}INFO:Critical ERROR:i2c3 i2c_queue_start fail||
727.256 : {task_e}INFO:i2c 3 sync xfer fail - 20039b68 --14 ||

The AC also seemed to have issues maintaining position while hovering. At one point, it drifted backwards as much 60m before I decided that was enough and brought it back. I will do an IMU calibration and see if that helps.

The zigzag lines below show the AC drifting, me bringing it back, and it drifting back again.

 

[Deleted member 94047]

Update:
I wanted to see if the issues were caused by the battery. So I recharged it and did another test flight. But apparently, I also had issues with the remote controller's sticks. The remote controller started beeping on start up and I had to calibrate the remote controller first. I did a test flight afterwards. AC was solid in maintaining position while hovering. And a quick review of the flight logs doesn't show any outstanding problems. So, not the battery. Was this all caused by the RC? Still puzzled.

 

[BudWalker]

@Doppler can you can provide the .DAT files? That will provide the basis for a more thorough discussion.

 

[Deleted member 94047]

@Doppler can you can provide the .DAT files? That will provide the basis for a more thorough discussion.

Here you go @BudWalker. Fly078 is the flight described in my first post. Fly085 is the first test flight I did this morning where the entries I listed in post#5 appear and where I experienced drifting of the AC. Fly089 is the last test flight I did after calibrating the RC's sticks. No drifting, and as far as I can tell, no scary entries in the log.

Thanks a million for taking a look at this

 

[BudWalker]

Here you go @BudWalker. Fly078 is the flight described in my first post. Fly085 is the first test flight I did this morning where the entries I listed in post#5 appear and where I experienced drifting of the AC. Fly089 is the last test flight I did after calibrating the RC's sticks. No drifting, and as far as I can tell, no scary entries in the log.

Thanks a million for taking a look at this

In FLY085 it does look like the elevator (black plot) was stuck in a slightly negative position - about -10%.

 

[Deleted member 94047]

That explains the constant backward drift I experienced during that flight and why the RC requested calibration afterwards. Super!

 

[Deleted member 94047]

I might as well file this under "THINGS I WILL NEVER KNOW". Did my MA have a panic attack?

2.927 : 0 [L-FAN]fan cfg synced
2.927 : 0 [L-FMU/DM]success reg dev type 31(), id:3, total num:3
2.927 : {root}INFO:lib_route_init ok||
2.927 : {root}INFO:link_host_init ok.||
2.927 : {root}INFO:link_init <0> link_host, ret(0x0)||
2.927 : {root}INFO:link_init <1> link_ofdm, ret(0x0)||
2.927 : {root}INFO:link_init <2> link_vo, ret(0x0)||
2.927 : {root}INFO:link_init <3> link_log, ret(0x0)||
2.927 : {root}INFO:link_init <4> link_zenmuse, ret(0x0)||
2.927 : {root}INFO:link_init <5> link_mag_test, ret(0x0)||
2.927 : 0 [L-SENSOR][ASR]sync host lead offset 0x11a||
2.927 : {root}INFO:[panic]:******************check fault info and trace(0) ************||
2.927 : {root}INFO:[panic]:-----fault info is null: addr(0x2007e000),flag(0x8dcc2bbf)-----||
2.927 : {root}INFO:[panic]:-----fault info is null: addr(0x2007e138),flag(0x92831197)-----||
2.928 : {root}INFO:[panic]:-----all task info is null: addr(0x2007e270),flag(0x7338f155)-----||
2.928 : {root}INFO:[panic]:******************check last trace ******************||
2.928 : {root}INFO:[panic]:-----wdg_time_info is null: addr(0x2007e4a0),flag(0x71d95feb)-----||
2.928 : {root}INFO:[link_ofdm] setup entry failed |||
2.928 : 0 [L-SYS]MATH_LIB VERSION: v1.0.0.3
2.928 : 0 [L-SENSOR] hw_ver voltage: 0
2.928 : 0 [L-SIM]read parameter successfully!
2.928 : 0 [L-SENSOR][ASR]asr host sync start
2.928 : 0 [L-SENSOR][ASR]need re sync host load_offset, freq=0x190||
2.928 : 0 [L-SENSOR][ASR]need re sync host load_offset, freq=0x190||
2.928 : 0 [L-SENSOR][ASR]need re sync host load_offset, freq=0x190||
2.928 : 0 [L-SENSOR][ASR]need re sync host load_offset, freq=0x190||
2.928 : 0 [L-FMU/MOTOR]read motor force disable flag successfully!
2.928 : 0 [L-SENSOR]imu group0 ok
2.928 : 0 [L-GYRO_ACC]imu_0 group->sensor_id:219205
2.928 : 0 [L-GYRO_ACC]gyr_acc_config.msc_require_side63) |
11.310 : 419 [L-BATTERY]bat_cfg_tbl_check, retry:9...||
11.314 : 419 [L-BATTERY][BATTERY] [FLASH] bat_cfg_tbl_state_get, ret:0, status:3||
11.325 : 420 [L-BATTERY]bat_cfg_tbl_unlock, ret:0||
11.330 : 420 [L-BATTERY][BATTERY] [FLASH] bat_cfg_tbl_state_get, ret:0, status:2||
11.338 : 421 [L-BATTERY]bat_cfg_fet_en_get, ret:0, fet_en:1||
11.340 : 421 [L-BATTERY][INFO] bat_cfg_tbl_lock step1 done!||
11.356 : 422 [L-FMU/LED]action changed. rc completely lost0)
11.627 : 435 [L-RECORDER]set timezone:30, result:0
11.627 : 435 [L-DBG1]set time by 8, 2019-9-13 9:49:15||
11.627 : 1a1b<fly-ctrl>calender_setup_time [2019-9-13]9:49:15. last_type(7),updates(1)
11.876 : 448 [L-SYS]set_real_name_info,data: 1568357355, flag: ad, len:14 14
11.934 : 451 [L-RC]rc_connect:0=>1
11.934 : 451 [L-RC]rc_resume @ [11965 ms]
11.935 : 451 [L-RC]set rc_resume_lock
11.948 : 451 [L-GEO][fmu_api_handler_update_app_db]reset recv buf|
11.948 : 451 [L-GEO][fmu_api_handler_update_app_db]add buf 0 1|
11.954 : 452 [L-FMU/LED]action changed. Normal Flash(0)
11.954 : 452 [L-FMU/LED]type:0, normal flash action:
11.954 : 452 [L-FMU/LED]c0:0,15;c1:0,3;c2:0,13;c3:2,3;c4:0,10;c5:0,3;c6:0,10;c7:0,3
11.981 : 453 [L-GEO][fmu_api_handler_update_app_db]>end of app db|
11.981 : 453 [L-GEO][update_nfz_app_db]update app db[1]|
11.981 : 453 [L-GEO][print_app_db][0] id:0 (0, 0) 10|
12.056 : 457 [L-BATTERY]battery app version: 1.73.5.9
12.369 : 472 [L-BATTERY][INFO] bat_cfg_tbl_lock step2 done!||
12.374 : 473 [L-BATTERY][BATTERY] [FLASH] bat_cfg_tbl_lock_status_recheck succeed!!!||
12.433 : 476 [L-RC]clr rc_resume_lock
12.641 : {ctrl}INFOM:cannot find the index by hash value:1792328982||
12.641 : 486 [L-CFG]PM:cannot find the index by hash value:1792328982||
12.851 : 496 [L-NS][AHRS] para: para_qg_acc_base_gain:0.040000
12.851 : 496 [L-NS][AHRS] para: para_qg_sttc_gain:0.010000
12.851 : 496 [L-NS][AHRS] para: para_qg_gnss_vxy_diff_gain:0.080000
12.851 : 496 [L-NS][AHRS] para: para_qg_vodm_vxy_diff_gain:0.500000
12.851 : 496 [L-NS][AHRS] para: para_qg_vodm_q_gain:0.080000
12.851 : 496 [L-NS][AHRS] para: para_qg_magn_yaw_base_gain:2.000000
12.851 : 496 [L-NS][AHRS] para: para_qg_sigma_gyro:0.010000
12.851 : 496 [L-NS][AHRS] para: para_qg_sigma_bias_gyro:0.000050
12.851 : 496 [L-NS][AHRS] para: para_pva_gnss_pxy_gain:0.500000
12.851 : 496 [L-NS][AHRS] para: para_pva_gnss_vxy_gain:0.100000
12.852 : 496 [L-NS][AHRS] para: para_pva_gnss_pz_base_gain:1.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_vodm_pxy_gain:100.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_vodm_vxy_gain:100.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_vodm_pz_base_gain:100.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_vodm_vz_base_gain:10.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_unsc_vz_base_gain:1.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_baro_vz_base_r_gain:5.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_baro_pz_base_r_gain_when_motor_on:5.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_sigma_acc_xy:3.000000
12.852 : 496 [L-NS][AHRS] para: para_pva_sigma_acc_z:0.500000
12.852 : 496 [L-NS][AHRS] para: para_pva_sigma_bias_acc_xy:0.001000
12.852 : 496 [L-NS][AHRS] para: para_pva_sigma_bias_acc_z:0.005000
12.852 : 496 [L-NS][AHRS] para: para_pva_max_pz_delta:0.100000
12.913 : 500 [L-GPS]<GPS INFO>GPS[0][0] ack check: all 22 miss 0
12.913 : 500 [L-GPS]<GPS INFO>gps flag [0][0] init 1 sign_support_flag 1
12.913 : 500 [L-GPS]<GPS INFO>gps init: nack:0 ack:22 || size 1472
12.913 : 500 [L-GPS]<GPS INFO>gps hw version: 0, type: 1 sat_sys 0||
12.961 : 502 [L-FDI][sensor_api_info] head(2,0,31,4).|
13.419 : 525 [L-CFG]get rc lost act. 2
13.470 : 528 [L-ESC]escm ppm test finished 200||
13.721 : 540 [L-ACTIVATION]get version
13.786 : 543 [L-ACTIVATION]idx:0 id:2 get info,sta:1,date:0-0-0,time:0-0-0, proId:0K12F8F00S1001
17.843 : 747 [L-NS][AHRS]product: FC_FUSION_NORMAL
17.843 : 747 [L-NS][AHRS]version: V5_20180626_2ecd872
17.843 : 747 [L-NS][AHRS]version code: v1.0.0.1
18.490 : 779 [L-DEV]add blockID dev:11, id_index:0 id:5000 tag:1
18.490 : 779 [L-DEV]add blockID dev:11, id_index:1 id:5001 tag:2
19.512 : 830 [L-DEV]11-[BATT] DC:2375,DV:11550,CYCLE:34,SN:2840,loader:0.0.0.1,app:1.73.5.9
19.512 : 830 [L-DEV]11-[BATT] manu:TL NVT,dev_name:JI02,bar:0K4AF8FA35034R
20.940 : 902 [L-FDI][sensor_api_info] head(2,0,31,4).|
21.304 : 920 [L-NS][AHRS]height max obv num [3/24]
21.370 : 924 [L-TAKEOFF]alti: 2175.150635 tors: -35.208740
21.406 : 925 [L-FMU/FSM]near ground
22.209 : 966 [L-FMU/FSM]not near ground
24.623 : 1087 [L-BATTERY]power state changed to wait off
24.623 : 1087 [L-ESC]escm_set_mute @ 14501 ||
24.723 : 1092 [L-ESC]waiting ... 14861 /14562 ||
24.825 : 1097 [L-ESC]waiting ... 14861 /14623 ||
24.900 : 1100 [L-BATTERY]get_cell_voltage_callback_ack failed!||
24.926 : 1102 [L-ESC]waiting ... 14861 /14684 ||
25.028 : 1107 [L-ESC]waiting ... 14861 /14745 ||
25.129 : 1112 [L-ESC]waiting ... 14861 /14806 ||
25.320 : 1122 [L-CMD]esc mute
25.320 : 1122 [L-CMD]power off by battery sender11, index0 power_type=2:0, ||
25.479 : 1130 [L-BATTERY]Power off acked: 3||
25.539 : 1133 [L-BATTERY]Power off acked: 4||

 

[sar104]

I might as well file this under "THINGS I WILL NEVER KNOW". Did my MA have a panic attack?

I don't see anything unusual in that log - were you looking at something specific?

 

[Deleted member 94047]

I don't see anything unusual in that log - were you looking at something specific?

I just didn't understand any of it is all. It looks to me like a complete system check, which I haven't seen in the logs before. The panic comment was a poor attempt at word play.

 

[sar104]

I just didn't understand any of it is all. It looks to me like a complete system check, which I haven't seen in the logs before. The panic comment was a poor attempt at word play.

Ah - okay. That is just the usual startup log sequence.