Intermittent truncated/corrupt header in Blackbox logs (INAV 2.5)

[grahamcropley]

Current Behaviour

I'm having intermittent issues with blackbox logging to SD card with INAV 2.5, anybody else experiencing this? the logs load in BBE but shows gyro values at 50,000dps and above and motors are all over 100% etc.

It seems like the header is getting truncated halfway through the 'Firmware type' field.. so BBE is interpreting the values incorrectly. If I copy/paste that top part from the previous flight, the rest of the data for the whole flight duration is read correctly in INAV Blackbox Explorer so I don't think it's a simple case of corruption there are no gaps in the logs at all. Just a problem with the header perhaps?

Steps to Reproduce

Fly a few packs, and check logs, it's intermittent. I've tried formatting the card inbetween, vs leaving files there, inconclusive. Some work, some don't.

Expected Behaviour

Every log file to have complete header so it can be read correctly. :P

Suggested Solution(s)

No idea, sorry. Maybe a buffer issue when composing the header for the file? but I'm no expert programmer :)

Additional context

Link to a broken log file - https://1drv.ms/u/s!AsYEmOjSaq2yg4dQxOSwUO6e2xdnSA?e=LlICXy
It happens in the exact same place in every file that isn't readable straight off the card... "H Firmware type:Cleanf" then it skips to later in the header. I have more examples if anybody needs them, as well as logs from the same quad/session/pack that DOES work.

CLI DUMP - https://pastebin.com/7RhB89B9

---

INAV/MATEKF722SE 2.5.0 May 26 2020 / 12:36:10 (d84bcb7)

GCC-9.2.1 20191025 (release) [ARM/arm-9-branch revision 277599]

[issue-label-bot[bot]]

Issue-Label Bot is automatically applying the label BUG to this issue, with a confidence of 0.90. Please mark this comment with 👍 or 👎 to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

[grahamcropley]

[CertainBot]

@grahamcropley did you test on 2.5.0 stable?

[grahamcropley]

Sorry, I thought this was on release - I will re-flash anyway... But just so I know, what info are you seeing that suggests it was on RC?

[grahamcropley]

Ah ok.. the date next to the version...
INAV/MATEKF722SE 2.5.0 Jun 7 2020 / 11:43:20 (6947679)
GCC-9.2.1 20191025 (release) [ARM/arm-9-branch revision 277599]

I will try again in the morning. thanks for the pointer @Mateyhv

[giacomo892]

It's likely you are using a slow sdcard.
which one are you using?

[CertainBot]

Yes it was the date next to version. Inline with what giacomo892 pointed out I have been using a fast SD card on my 722 SE and has never gave me trouble. Regarding 2.5.0 stable, if you rely on RPM telemetry I would skip it in favor of the upcoming 2.5.1 which should be released shortly.

[grahamcropley]

Samsung EVO 32GB SDHC Class 10 U1 and/or Sandisk Extreme 32GB SDHC U3 V30.
There doesn't seem to be any missing data in the blackbox logs themselves, i.e. if I replace just the readable header from a file that worked, all the data beyond that is read and displayed correctly.

I guess there's a chance they are wearing out, I'll pay more attention to the card I use when I test again.

@Mateyhv I only just wired up ESC telemetry to get RPM filters working, I'll keep an eye out for 2.5.1

[grahamcropley]

Same experience on final release version of 2.5.0, different SD card

Always in the exact same place in the header.

INAV/MATEKF722SE 2.5.0 Jun 7 2020 / 11:43:20 (6947679)
GCC-9.2.1 20191025 (release) [ARM/arm-9-branch revision 277599]

DIFF ALL - https://pastebin.com/Y7xBgc33

[breadoven]

I also get truncated headers most of the time with various bits randomly missing :

First Log of the day:

H Product:Blackbox flight data recorder by Nicholas Sherlock
H Data version:2
H I interval:32
H Field I name:loopIteration,time,axisRate[0],axisRate[1],axisRate[2],axisP[0],axisP[1],axisP[2],axisI[0],axisI[1],axisI[2],axisD[0],axisD[1],axisD[2],fwAltP,fwAltI,fwAltD,fwAltOut,fwPosP,fwPosI,fwPosD,fwPosOut,rcData[0],rcData[1],rcData[2],rcData[3],rcCommand[0],rcCommand[1],rcCommand[2],rcCommand[3],vbat,amperage,BaroAlt,rssi,gyroADC[0],gyroADC[1],gyroADC[2],accSmooth[0],accSmooth[1],accSmooth[2],attitude[0],attitude[1],attitude[2],motor[0],servo[0],servo[1],servo[2],servo[3],servo[4],servo[5],servo[6],servo[7],servo[8],servo[9],servo[10],servo[11],servo[12],servo[13],servo[14],servo[15],navState,navFlags,navEPH,navEPV,navPos[0],navPos[1],navPos[2],navVel[0],navVel[1],navVel[2],navAcc[0],navAcc[1],navAcc[2],navTgtVel[0],navTgtVel[1],navTgtVel[2],navTgtPos[0],navTgtPos[1],navTgtPos[2],navSurf[0]
H Field I signed:0,0,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,0,1,1,0,1,1,1,1,1,1,1,1,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1
H Field I predictor:0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,4,9,0,0,0,0,0,0,0,0,0,0,0,0,4,8,8,8,8,8,8,8,8,8,8,8,8,8,8,8,8,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
H Field I encoding:1,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,3,0,0,1,0,0,0,0,0,0,0,0,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
H Field P predictor:6,2,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,1,1,1,1,1,1,1,3,3,3,3,3,3,3,3,3,1,1,1,1
H Field P encoding:9,0,0,0,0,0,0,0,7,7,7,0,0,0,0,0,0,0,0,0,0,0,8,8,8,8,8,8,8,8,6,6,6,6,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
H Field H name:GPS_home[0],GPS_home[1]
H Field H signed:1,1
H Field H predictor:0,0
H Field H encoding:0,0
H Field G name:time,GPS_fixType,GPS_numSat,GPS_coord[0],GPS_coord[1],GPS_altitude,GPS_speed,GPS_ground_course,GPS_hdop,GPS_eph,GPS_epv,GPS_velned[0],GPS_velned[1],GPS_velned[2]
H Field G signed:0,0,0,1,1,1,0,0,0,0,0,1,1,1
H Field G predictor:10,0,0,7,7,0,0,0,0,0,0,0,0,0
H Field G encoding:1,1,1,0,0,0,1,1,1,1,1,0,0,0
H Field S name:flightModeFlags,stateFlags,failsafePhase,rxSignalReceived,rxFlightChannelsValid,hwHealthStatus,powerSupplyImpedance,sagCompensatedVBat,wind[0],wind[1],wind[2],IMUTemperature,baroTemperature,sens0Temp,sens1Temp,sens2Temp,sens3Temp,sens4Temp,sens5Temp,sens6Temp,sens7Temp,escRPM,escTemperature
H Field S signed:0,0,0,0,0,0,0,0,1,1,1,1,1,1,1,1,1,1,1,1,1,0,1
H Field S predictor:0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1
H Field S encoding:1,1,7,7,7,1,1,1,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0
H Firmware type:Cleanflight
H Firmware revision:INAV 2.5.1 (098a574) OMNIBUSF4V3
H Firmware date:Jun 16 2020 12:32:45
H Log start datetime:2020-07-21T18:47:42.710+00:00
H Craft name:Phoenix Glider
H P interval:1/5
H minthrottle:1150
H maxthrottle:2000
H gyro_scale:0x3f800000
H motorOutput:1150,2000
H acc_1G:2048
H vbat_scale:110
H vbatcellvoltagH gyro_lpf2_hz:0
H dynamicGyroNotchRange:1
H dynamicGyroNotchQ:120
H dynamicGyroNotchMinHz:150
H gyro_notch_hz:0,0
H gyro_notch_cutoff:1,1
H acc_lpf_hz:15
H acc_hardware:7
H baro_hardware:4
H mag_hardware:0
H serialrx_provider:7
H motor_pwm_protocol:0
H motor_pwm_rate:400
H debug_mode:0
H features:810028187
H waypoints:6,1
H acc_notch_hz:0
H acc_notch_cutoff:1
H gyro_stage2_lowpass_hz:0
H dterm_setpoint_weight: 1.000
H pidSumLimit:500
H pidSumLimitYaw:350
H axisAccelerationLimitYaw:10000
H axisAccelerationLimitRollPitch:0
H rpm_gyro_filter_enabled:0
H rpm_gyro_harmonics:1
H rpm_gyro_min_hz:100
H rpm_gyro_q:500
.
.
.
But another log on the same day after powering off and back on seems OK:

H Product:Blackbox flight data recorder by Nicholas Sherlock
H Data version:2
H I interval:32
H Field I name:loopIteration,time,axisRate[0],axisRate[1],axisRate[2],axisP[0],axisP[1],axisP[2],axisI[0],axisI[1],axisI[2],axisD[0],axisD[1],axisD[2],fwAltP,fwAltI,fwAltD,fwAltOut,fwPosP,fwPosI,fwPosD,fwPosOut,rcData[0],rcData[1],rcData[2],rcData[3],rcCommand[0],rcCommand[1],rcCommand[2],rcCommand[3],vbat,amperage,BaroAlt,rssi,gyroADC[0],gyroADC[1],gyroADC[2],accSmooth[0],accSmooth[1],accSmooth[2],attitude[0],attitude[1],attitude[2],motor[0],servo[0],servo[1],servo[2],servo[3],servo[4],servo[5],servo[6],servo[7],servo[8],servo[9],servo[10],servo[11],servo[12],servo[13],servo[14],servo[15],navState,navFlags,navEPH,navEPV,navPos[0],navPos[1],navPos[2],navVel[0],navVel[1],navVel[2],navAcc[0],navAcc[1],navAcc[2],navTgtVel[0],navTgtVel[1],navTgtVel[2],navTgtPos[0],navTgtPos[1],navTgtPos[2],navSurf[0]
H Field I signed:0,0,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,0,1,1,0,1,1,1,1,1,1,1,1,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1
H Field I predictor:0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,4,9,0,0,0,0,0,0,0,0,0,0,0,0,4,8,8,8,8,8,8,8,8,8,8,8,8,8,8,8,8,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
H Field I encoding:1,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1,3,0,0,1,0,0,0,0,0,0,0,0,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
H Field P predictor:6,2,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,3,1,1,1,1,1,1,1,3,3,3,3,3,3,3,3,3,1,1,1,1
H Field P encoding:9,0,0,0,0,0,0,0,7,7,7,0,0,0,0,0,0,0,0,0,0,0,8,8,8,8,8,8,8,8,6,6,6,6,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
H Field H name:GPS_home[0],GPS_home[1]
H Field H signed:1,1
H Field H predictor:0,0
H Field H encoding:0,0
H Field G name:time,GPS_fixType,GPS_numSat,GPS_coord[0],GPS_coord[1],GPS_altitude,GPS_speed,GPS_ground_course,GPS_hdop,GPS_eph,GPS_epv,GPS_velned[0],GPS_velned[1],GPS_velned[2]
H Field G signed:0,0,0,1,1,1,0,0,0,0,0,1,1,1
H Field G predictor:10,0,0,7,7,0,0,0,0,0,0,0,0,0
H Field G encoding:1,1,1,0,0,0,1,1,1,1,1,0,0,0
H Field S name:flightModeFlags,stateFlags,failsafePhase,rxSignalReceived,rxFlightChannelsValid,hwHealthStatus,powerSupplyImpedance,sagCompensatedVBat,wind[0],wind[1],wind[2],IMUTemperature,baroTemperature,sens0Temp,sens1Temp,sens2Temp,sens3Temp,sens4Temp,sens5Temp,sens6Temp,sens7Temp,escRPM,escTemperature
H Field S signed:0,0,0,0,0,0,0,0,1,1,1,1,1,1,1,1,1,1,1,1,1,0,1
H Field S predictor:0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,1
H Field S encoding:1,1,7,7,7,1,1,1,0,0,0,0,0,0,0,0,0,0,0,0,0,1,0
H Firmware type:Cleanflight
H Firmware revision:INAV 2.5.1 (098a574) OMNIBUSF4V3
H Firmware date:Jun 16 2020 12:32:45
H Log start datetime:2020-07-21T19:15:31.215+00:00
H Craft name:Phoenix Glider
H P interval:1/5
H minthrottle:1150
H maxthrottle:2000
H gyro_scale:0x3f800000
H motorOutput:1150,2000
H acc_1G:2048
H vbat_scale:110
H vbatcellvoltage:34,36,42
H vbatref:1253
H currentMeter:16450,390
H looptime:1000
H rc_rate:100
H rc_expo:70
H rc_yaw_expo:30
H thr_mid:50
H thr_expo:0
H tpa_rate:0
H tpa_breakpoint:1530
H rates:10,14,6
H rollPID:15,30,0
H pitchPID:20,26,0
H yawPID:20,40,0
H altPID:30,15,70
H posPID:55,5,8
H posrPID:0,0,0
H levelPID:20,5,100
H magPID:60
H velPID:0,0,0
H yaw_lpf_hz:30
H dterm_lpf_hz:40
H dterm_lpf_type:1
H dterm_lpf2_hz:0
H dterm_lpf2_type:1
H dterm_notch_hz:0
H dterm_notch_cutoff:1
H deadband:5
H yaw_deadband:5
H gyro_lpf:1
H gyro_lpf_hz:20
H gyro_lpf_type:1
H gyro_lpf2_hz:0
H dynamicGyroNotchRange:1
H dynamicGyroNotchQ:120
H dynamicGyroNotchMinHz:150
H gyro_notch_hz:0,0
H gyro_notch_cutoff:1,1
H acc_lpf_hz:15
H acc_hardware:7
H baro_hardware:4
H mag_hardware:0
H serialrx_provider:7
H motor_pwm_protocol:0
H motor_pwm_rate:400
H debug_mode:0
H features:810028187
H waypoints:0,0
H acc_notch_hz:0
H acc_notch_cutoff:1
H gyro_stage2_lowpass_hz:0
H dterm_setpoint_weight: 1.000
H pidSumLimit:500
H pidSumLimitYaw:350
H axisAccelerationLimitYaw:10000
H axisAccelerationLimitRollPitch:0
H rpm_gyro_filter_enabled:0
H rpm_gyro_harmonics:1
H rpm_gyro_min_hz:100
H rpm_gyro_q:500

Explains why I've been getting odd values for vbat in Blackbox Explorer. If vbatref is missing from the header it defaults to 4050 or so even though it's a 3S battery. It's also been happening since at least 2.2.1 looking at old logs.

[stale[bot]]

This issue / pull request has been automatically marked as stale because it has not had any activity in 60 days. The resources of the INAV team are limited, and so we are asking for your help.
This issue / pull request will be closed if no further activity occurs within two weeks.

[truglodite]

I wanted to report I'm seeing the same issue on the latest stable release (2.5.2) w/ the latest bb analyzer app. I also have a Matek F722se, with a Sandisk Ultra 16GB card, using quad X, 1/1 logging. For me, the exact place where the header gets cropped appears to be random. Copying in headers from other logs is a workaround for now, but otherwise the gyro scaling is way off without the header of course.