Teleop_xbox360.launch fails on Firmware 2020.02

[jasuchard]

I'm having a problem where everything works fine using the older crazyflie firmware, 2019.09, but when I update my firmware to 2020.02, I get this error:
[ INFO] [1583189498.507758262]: Requesting Logging variables...

[ INFO] [1583189498.524256520]: Found variables in cache.

terminate called after throwing an instance of 'std::runtime_error'
what(): Could not find acc.z in log toc!`

[INFO] [1583189498.580075]: found update_params service

[INFO] [1583189498.582367]: waiting for emergency service

[INFO] [1583189498.589355]: found emergency service

[crazyflie_server-2] process has died [pid 1797, exit code -6, cmd /home/jordansuchard/ros_ws/devel/lib/crazyflie_driver/crazyflie_server __name:=crazyflie_server __log:=/home/jordansuchard/.ros/log/5f698af4-5cd8-11ea-ba4b-d07e353b7469/crazyflie_server-2.log].
log file: /home/jordansuchard/.ros/log/5f698af4-5cd8-11ea-ba4b-d07e353b7469/crazyflie_server-2*.log

I've narrowed the issue down to the new firmware (I think), but I'm not sure how to fix it. Is the new firmware not supported yet?

[whoenig]

I just checked and the latest firmware does still have "acc.z" as a logging variable. Try deleting the cache files ("~/.ros/params*.csv"). Also, make sure that you are on the latest version - there was a fix in crazyflie_cpp last year that is necessary to handle more than 255 variables.

[jasuchard]

Yeah, I've scanned the TOC using the new firmware and saw that acc.z was still in the logging system. Just tried deleting all the params*.csv and running with a fresh copy of crazyflie_ros and the official 2020.02 build and it still throws the same error.

[whoenig]

Could you share the newly created params*.csv file?

[jasuchard]

params*.csv:

0,8,1,imu_sensors,BMP388
1,8,1,imu_sensors,HMC5883L
2,8,1,imu_sensors,MS5611
3,8,1,imu_tests,MPU6500
4,8,1,imu_tests,HMC5883L
5,8,1,imu_tests,MS5611
6,8,1,imu_sensors,BMP388
7,9,1,cpu,flash
8,10,1,cpu,id0
9,10,1,cpu,id1
10,10,1,cpu,id2
11,0,0,system,selftestPassed
12,8,0,sound,effect
13,10,1,sound,neffect
14,9,0,sound,freq
15,8,0,sound,ratio
16,8,0,system,taskDump
17,8,0,memTst,resetW
18,8,0,commander,enHighLevel
19,8,0,flightmode,althold
20,8,0,flightmode,poshold
21,8,0,flightmode,posSet
22,8,0,flightmode,yawMode
23,8,0,flightmode,yawRst
24,8,0,flightmode,stabModeRoll
25,8,0,flightmode,stabModePitch
26,8,0,flightmode,stabModeYaw
27,6,0,cmdrCPPM,rateRoll
28,6,0,cmdrCPPM,ratePitch
29,6,0,cmdrCPPM,rateYaw
30,6,0,cmdrCPPM,angRoll
31,6,0,cmdrCPPM,angPitch
32,8,0,locSrv,enRangeStreamFP32
33,6,0,locSrv,extPosStdDev
34,6,0,locSrv,extQuatStdDev
35,6,0,pid_attitude,roll_kp
36,6,0,pid_attitude,roll_ki
37,6,0,pid_attitude,roll_kd
38,6,0,pid_attitude,pitch_kp
39,6,0,pid_attitude,pitch_ki
40,6,0,pid_attitude,pitch_kd
41,6,0,pid_attitude,yaw_kp
42,6,0,pid_attitude,yaw_ki
43,6,0,pid_attitude,yaw_kd
44,6,0,pid_rate,roll_kp
45,6,0,pid_rate,roll_ki
46,6,0,pid_rate,roll_kd
47,6,0,pid_rate,pitch_kp
48,6,0,pid_rate,pitch_ki
49,6,0,pid_rate,pitch_kd
50,6,0,pid_rate,yaw_kp
51,6,0,pid_rate,yaw_ki
52,6,0,pid_rate,yaw_kd
53,6,0,sensfusion6,kp
54,6,0,sensfusion6,ki
55,6,0,sensfusion6,baseZacc
56,8,0,health,startPropTest
57,8,0,stabilizer,estimator
58,8,0,stabilizer,controller
59,8,0,stabilizer,stop
60,6,0,posEstAlt,estAlphaAsl
61,6,0,posEstAlt,estAlphaZr
62,6,0,posEstAlt,velFactor
63,6,0,posEstAlt,velZAlpha
64,6,0,posEstAlt,vAccDeadband
65,6,0,posCtlPid,xKp
66,6,0,posCtlPid,xKi
67,6,0,posCtlPid,xKd
68,6,0,posCtlPid,yKp
69,6,0,posCtlPid,yKi
70,6,0,posCtlPid,yKd
71,6,0,posCtlPid,zKp
72,6,0,posCtlPid,zKi
73,6,0,posCtlPid,zKd
74,9,0,posCtlPid,thrustBase
75,9,0,posCtlPid,thrustMin
76,6,0,posCtlPid,rpLimit
77,6,0,posCtlPid,xyVelMax
78,6,0,posCtlPid,zVelMax
79,6,0,velCtlPid,vxKp
80,6,0,velCtlPid,vxKi
81,6,0,velCtlPid,vxKd
82,6,0,velCtlPid,vyKp
83,6,0,velCtlPid,vyKi
84,6,0,velCtlPid,vyKd
85,6,0,velCtlPid,vzKp
86,6,0,velCtlPid,vzKi
87,6,0,velCtlPid,vzKd
88,8,0,controller,tiltComp
89,6,0,ctrlMel,kp_xy
90,6,0,ctrlMel,kd_xy
91,6,0,ctrlMel,ki_xy
92,6,0,ctrlMel,i_range_xy
93,6,0,ctrlMel,kp_z
94,6,0,ctrlMel,kd_z
95,6,0,ctrlMel,ki_z
96,6,0,ctrlMel,i_range_z
97,6,0,ctrlMel,mass
98,6,0,ctrlMel,massThrust
99,6,0,ctrlMel,kR_xy
100,6,0,ctrlMel,kR_z
101,6,0,ctrlMel,kw_xy
102,6,0,ctrlMel,kw_z
103,6,0,ctrlMel,ki_m_xy
104,6,0,ctrlMel,ki_m_z
105,6,0,ctrlMel,kd_omega_rp
106,6,0,ctrlMel,i_range_m_xy
107,6,0,ctrlMel,i_range_m_z
108,6,0,ctrlINDI,thrust_threshold
109,6,0,ctrlINDI,bound_ctrl_input
110,6,0,ctrlINDI,roll_kp
111,6,0,ctrlINDI,pitch_kp
112,6,0,ctrlINDI,yaw_kp
113,6,0,ctrlINDI,g1_p
114,6,0,ctrlINDI,g1_q
115,6,0,ctrlINDI,g1_r
116,6,0,ctrlINDI,g2
117,6,0,ctrlINDI,ref_err_p
118,6,0,ctrlINDI,ref_err_q
119,6,0,ctrlINDI,ref_err_r
120,6,0,ctrlINDI,ref_rate_p
121,6,0,ctrlINDI,ref_rate_q
122,6,0,ctrlINDI,ref_rate_r
123,6,0,ctrlINDI,act_dyn_p
124,6,0,ctrlINDI,act_dyn_q
125,6,0,ctrlINDI,act_dyn_r
126,6,0,ctrlINDI,filt_cutoff
127,6,0,ctrlINDI,filt_cutoff_r
128,8,0,motorPowerSet,enable
129,9,0,motorPowerSet,m1
130,9,0,motorPowerSet,m2
131,9,0,motorPowerSet,m3
132,9,0,motorPowerSet,m4
133,8,0,kalman,resetEstimation
134,8,0,kalman,quadIsFlying
135,6,0,kalman,pNAcc_xy
136,6,0,kalman,pNAcc_z
137,6,0,kalman,pNVel
138,6,0,kalman,pNPos
139,6,0,kalman,pNAtt
140,6,0,kalman,mNBaro
141,6,0,kalman,mNGyro_rollpitch
142,6,0,kalman,mNGyro_yaw
143,6,0,kalman,initialX
144,6,0,kalman,initialY
145,6,0,kalman,initialZ
146,6,0,kalman,initialYaw
147,6,0,kalman,maxPos
148,6,0,kalman,maxVel
149,8,1,deck,bcLedRing
150,8,0,ring,effect
151,10,1,ring,neffect
152,8,0,ring,solidRed
153,8,0,ring,solidGreen
154,8,0,ring,solidBlue
155,8,0,ring,headlightEnable
156,6,0,ring,glowstep
157,6,0,ring,emptyCharge
158,6,0,ring,fullCharge
159,10,0,ring,fadeColor
160,6,0,ring,fadeTime
161,8,1,deck,bcBuzzer
162,8,1,deck,bcGTGPS
163,8,1,deck,bcCPPM
164,8,1,deck,bcUSD
165,8,0,usd,logging
166,8,1,deck,bcZRanger
167,8,1,deck,bcZRanger2
168,8,1,deck,bcDWM1000
169,8,0,loco,mode
170,8,0,tdoa3,logId
171,8,0,tdoa3,logOthrId
172,8,1,deck,bcFlow
173,8,1,deck,bcFlow2
174,8,0,motion,disable
175,8,1,deck,bcOA
176,8,1,deck,bcMultiranger
177,8,1,deck,bdLighthouse4
178,8,0,activeMarker,front
179,8,0,activeMarker,back
180,8,0,activeMarker,left
181,8,0,activeMarker,right
182,8,0,activeMarker,mode
183,8,0,activeMarker,poll
184,10,1,firmware,revision0
185,9,1,firmware,revision1
186,8,1,firmware,modified```

[whoenig]

This looks fine. I mixed up params and logging though:-/ There should be also files "log.csv", which actually take care of the caching of logging-related variable names?

I'll be out for 9 days and can take a look afterwards (around March 16). My best guess is that there is some problem that surfaced that has to do with retrieval of the logging variable names.

[jasuchard]

I've been attempting to get a clean log*.csv for you, but after rebooting my computer, I'm now unable to recreate the issue as it was showing before :/ Now the crazyflie_add finishes cleanly, but the acc.z logging value is always 0. This suggests to me that this is another symptom of the same issue.

Additionally, when switching back to the 2019.09, the crazyflie_add now complains about not being able to find the battery voltage in to TOC. Perhaps there's a bug in the TOC caching that only appears when the TOC changes significantly?

[whoenig]

I found and fixed a bug related to the parameter subsystem (see 83d1fcf). I didn't find anything related to the logging. Perhaps you can share the (newly created) cache files? Once I am back in the office, I can also try to reproduce with the firmware versions that you mentioned.

TOC caching relies on a unique CRC (a number that is computed in the firmware). So if the 2 firmwares have the same CRC, but different TOCs, there could be issues. You can disable caching by either deleting those temporary files, or by calling the functions (in crazyflie_server.cpp) with the appropriate flag, see https://github.com/whoenig/crazyflie_cpp/blob/master/include/crazyflie_cpp/Crazyflie.h#L193-L195.

[jasuchard]

Ok, I've identified the direct source of the error, but not what upstream is causing it. Some of the log*.csv files are ordered as we'd expect:

id,type,group,name
0,5,gyro,xRaw
1,5,gyro,yRaw
2,5,gyro,zRaw
3,7,gyro,xVariance
4,7,gyro,yVariance
5,7,gyro,zVariance
6,3,pwm,m1_pwm
7,3,pwm,m2_pwm
8,3,pwm,m3_pwm
9,3,pwm,m4_pwm
10,2,crtp,rxRate
11,2,crtp,txRate
12,7,pm,vbat
13,2,pm,vbatMV
14,7,pm,extVbat
15,2,pm,extVbatMV
16,7,pm,extCurr
17,7,pm,chargeCurrent

etc.

but some are out of order for a still unknown reason:

id,type,group,name
0,5,gyro,xRaw
1,5,gyro,yRaw
2,5,gyro,zRaw
3,7,gyro,xVariance
4,7,kalman_states,vx
5,7,gyro,zVariance
6,3,pwm,m1_pwm
7,3,pwm,m2_pwm
8,7,kalman_pred,measNX
9,7,kalman_pred,measNY
10,6,outlierf,lhWin
11,7,ring,fadeTime
12,6,gps,lat
13,6,gps,lon
14,7,gps,hMSL
15,7,gps,hAcc
16,6,gps,nsat
17,7,pm,chargeCurrent

I haven't yet tracked down where the function that records these caches is, or whether its the crazyflie firmware or the ros package that is jumbling things.

[whoenig]

It's probably a safelink bug then, try disabling safelink at https://github.com/whoenig/crazyflie_cpp/blob/master/include/crazyflie_cpp/Crazyflie.h#L15 (and catkin_make afterwards).

Background: Safelink is a communication mode that is supposed to guarantee no packet loss, and packets being exchanged in-order. Without safelink there might be a few more packets exchanged, but crazyflie_cpp ensures that there is no packet loss (rather than the comm stack of the radio/firmware).

[jasuchard]

Well, it turns out I completely misdiagnosed the bug before. I now think the bug is triggered by using the optical flow deck at the same time as the multi-ranger deck. Originally, I thought I had ruled these out as the cause, but now I've found a reliable way of reproducing the error.

After each reboot of the computer running crazyflie_ros, the error returns but the variable that it is unable to find in the log toc varies. I can get the error to go away by deleting all log*.csv files in ~/.ros and running teleop_xbox360.launch without any decks installed on the cf. After that run, subsequent runs are successful with the decks installed. This continues to work until the system running crazyflie_ros is rebooted.

EDIT: Actually that doesn't work at all for reproducing the bug. I guess testing continues...