AP_Logger: write formats out as required rather than at start of log

[peterbarker]

We may need to resurrect the push_log_blocks stuff here to try to make more room?

pbarker@fx:~/rc/ardupilot(pr/logger-formats-when-required)$ mavlogdump.py logs/00000001.BIN  | head
2024-06-14 22:52:00.55: FMT {Type : 128, Length : 89, Name : FMT, Format : BBnNZ, Columns : Type,Length,Name,Format,Columns}
2024-06-14 22:52:00.55: FMT {Type : 59, Length : 75, Name : MSG, Format : QZ, Columns : TimeUS,Message}
2024-06-14 22:51:51.96: MSG {TimeUS : 37148468, Message : Arming motors}
2024-06-14 22:51:51.96: FMT {Type : 3, Length : 16, Name : D32, Format : QBi, Columns : TimeUS,Id,Value}
2024-06-14 22:51:51.96: D32 {TimeUS : 37148468, Id : 9, Value : 35570}
2024-06-14 22:51:51.96: FMT {Type : 71, Length : 24, Name : ORGN, Format : QBLLe, Columns : TimeUS,Type,Lat,Lng,Alt}
2024-06-14 22:51:51.96: ORGN {TimeUS : 37148468, Type : 0, Lat : -35.3632621, Lng : 149.1652374, Alt : 584.09}
2024-06-14 22:51:51.96: ORGN {TimeUS : 37148468, Type : 1, Lat : -35.3632621, Lng : 149.1652374, Alt : 584.09}
2024-06-14 22:51:51.96: FMT {Type : 119, Length : 14, Name : MODE, Format : QMBB, Columns : TimeUS,Mode,ModeNum,Rsn}
2024-06-14 22:51:51.96: MODE {TimeUS : 37148468, Mode : 0, ModeNum : 0, Rsn : 1}
2024-06-14 22:51:51.96: FMT {Type : 77, Length : 48, Name : MAVC, Format : QBBBBBHffffiifBB, Columns : TimeUS,TS,TC,SS,SC,Fr,Cmd,P1,P2,P3,P4,X,Y,Z,Res,WL}
2024-06-14 22:51:51.96: MAVC {TimeUS : 37148468, TS : 1, TC : 1, SS : 255, SC : 230, Fr : 3, Cmd : 400, P1 : 1.0, P2 : 0.0, P3 : 0.0, P4 : 0.0, X : 0, Y : 0, Z : 0.0, Res : 0, WL : 1}
2024-06-14 22:51:51.96: FMT {Type : 116, Length : 76, Name : UNIT, Format : QbZ, Columns : TimeUS,Id,Label}
2024-06-14 22:51:51.96: FMT {Type : 115, Length : 44, Name : FMTU, Format : QBNN, Columns : TimeUS,FmtType,UnitIds,MultIds}
2024-06-14 22:51:51.96: FMT {Type : 117, Length : 20, Name : MULT, Format : Qbd, Columns : TimeUS,Id,Mult}
2024-06-14 22:51:51.96: FMT {Type : 32, Length : 35, Name : PARM, Format : QNff, Columns : TimeUS,Name,Value,Default}
2024-06-14 22:51:51.96: FMT {Type : 91, Length : 51, Name : GPS, Format : QBBIHBcLLeffffB, Columns : TimeUS,I,Status,GMS,GWk,NSats,HDop,Lat,Lng,Alt,Spd,GCrs,VZ,Yaw,U}
2024-06-14 22:51:51.96: FMT {Type : 92, Length : 39, Name : GPA, Format : QBCCCCfBIHfHH, Columns : TimeUS,I,VDop,HAcc,VAcc,SAcc,YAcc,VV,SMS,Delta,Und,RTCMFU,RTCMFD}
2024-06-14 22:51:51.96: FMT {Type : 96, Length : 22, Name : UBX1, Format : QBHBBHI, Columns : TimeUS,Instance,noisePerMS,jamInd,aPower,agcCnt,config}
2024-06-14 22:51:51.96: FMT {Type : 97, Length : 16, Name : UBX2, Format : QBbBbB, Columns : TimeUS,Instance,ofsI,magI,ofsQ,magQ}
2024-06-14 22:51:51.96: FMT {Type : 93, Length : 42, Name : GRAW, Format : QIHBBddfBbB, Columns : TimeUS,WkMS,Week,numSV,sv,cpMes,prMes,doMes,mesQI,cno,lli}
2024-06-14 22:51:51.96: FMT {Type : 94, Length : 24, Name : GRXH, Format : QdHbBB, Columns : TimeUS,rcvTime,week,leapS,numMeas,recStat}
2024-06-14 22:51:51.96: FMT {Type : 95, Length : 41, Name : GRXS, Format : QddfBBBHBBBBB, Columns : TimeUS,prMes,cpMes,doMes,gnss,sv,freq,lock,cno,prD,cpD,doD,trk}
2024-06-14 22:51:51.96: FMT {Type : 98, Length : 23, Name : SBPH, Format : QIII, Columns : TimeUS,CrcError,LastInject,IARhyp}
2024-06-14 22:51:51.96: FMT {Type : 99, Length : 67, Name : SBRH, Format : QQQQQQQQ, Columns : TimeUS,msg_flag,1,2,3,4,5,6}
2024-06-14 22:51:51.96: FMT {Type : 100, Length : 123, Name : SBRM, Format : QQQQQQQQQQQQQQQ, Columns : TimeUS,msg_flag,1,2,3,4,5,6,7,8,9,10,11,12,13}
2024-06-14 22:51:51.96: FMT {Type : 101, Length : 23, Name : SBRE, Format : QHIiBB, Columns : TimeUS,GWk,GMS,ns_residual,level,quality}
2024-06-14 22:51:51.96: FMT {Type : 60, Length : 39, Name : RCIN, Format : QHHHHHHHHHHHHHH, Columns : TimeUS,C1,C2,C3,C4,C5,C6,C7,C8,C9,C10,C11,C12,C13,C14}
2024-06-14 22:51:51.96: FMT {Type : 61, Length : 18, Name : RCI2, Format : QHHHB, Columns : TimeUS,C15,C16,OMask,Flags}
2024-06-14 22:51:51.96: FMT {Type : 62, Length : 39, Name : RCOU, Format : QHHHHHHHHHHHHHH, Columns : TimeUS,C1,C2,C3,C4,C5,C6,C7,C8,C9,C10,C11,C12,C13,C14}
2024-06-14 22:51:51.96: FMT {Type : 202, Length : 19, Name : RCO2, Format : QHHHH, Columns : TimeUS,C15,C16,C17,C18}

This might stop us dropping any messages at the start of a log...

[andyp1per]

I like where this is going!

[IamPete1]

I would be worth testing with various log parsers, but I think we should be OK so long as were guaranteed to get the format for the message before the message. Certainly the js parser will loose any message before its format.

[peterbarker]

Tested:

• MissionPlanner
• mavlogdump
• MAVExplorer
• dronekit-la
• Replay (autotest)
• UAV Log Viewer
• PID Review Tool
• Stream Stats

.... I think that shows we're OK. Given that WriteStreaming can pop up its head at any point and write out a FMT message, I think the tools already need to cope.

[IamPete1]

Given that WriteStreaming can pop up its head at any point and write out a FMT message, I think the tools already need to cope.

Of course, I hadn't thought abut it like that. As you say it should be fine.

[peterbarker]

Tested on a bench CubeOrange.

1970-01-01 10:00:20.42: FMT {Type : 128, Length : 89, Name : FMT, Format : BBnNZ, Columns : Type,Length,Name,Format,Columns}
1970-01-01 10:00:20.42: FMT {Type : 70, Length : 28, Name : ATT, Format : QccccCCCCB, Columns : TimeUS,DesRoll,Roll,DesPitch,Pitch,DesYaw,Yaw,ErrRP,ErrYaw,AEKF}
1970-01-01 10:00:05.33: ATT {TimeUS : 5331055, DesRoll : 4.48, Roll : 4.48, DesPitch : -9.26, Pitch : -9.26, DesYaw : 0.0, Yaw : 0.0, ErrRP : 1.0, ErrYaw : 1.0, AEKF : 0}
1970-01-01 10:00:05.33: FMT {Type : 73, Length : 63, Name : RATE, Format : Qfffffffffffff, Columns : TimeUS,RDes,R,ROut,PDes,P,POut,YDes,Y,YOut,ADes,A,AOut,AOutSlew}
1970-01-01 10:00:05.33: RATE {TimeUS : 5331114, RDes : -2.7643282413482666, R : -0.13874031603336334, ROut : -0.012949077412486076, PDes : -2.756877899169922, P : 0.05271271988749504, POut : -0.011305995285511017, YDes : -0.5874097347259521, Y : 0.07125250995159149, YOut : -0.0012596065644174814, ADes : 0.0, A : -2.735424041748047, AOut : 0.0, AOutSlew : 0.0}
1970-01-01 10:00:05.33: FMT {Type : 116, Length : 76, Name : UNIT, Format : QbZ, Columns : TimeUS,Id,Label}
1970-01-01 10:00:05.33: FMT {Type : 115, Length : 44, Name : FMTU, Format : QBNN, Columns : TimeUS,FmtType,UnitIds,MultIds}
1970-01-01 10:00:05.33: FMT {Type : 117, Length : 20, Name : MULT, Format : Qbd, Columns : TimeUS,Id,Mult}
1970-01-01 10:00:05.33: FMT {Type : 32, Length : 35, Name : PARM, Format : QNff, Columns : TimeUS,Name,Value,Default}
1970-01-01 10:00:05.33: FMT {Type : 91, Length : 51, Name : GPS, Format : QBBIHBcLLeffffB, Columns : TimeUS,I,Status,GMS,GWk,NSats,HDop,Lat,Lng,Alt,Spd,GCrs,VZ,Yaw,U}

[peterbarker]

I've now tested this with a dataflash backend (revo-mini)

The interleaving is much more pronounced here:

1970-01-01 11:59:42.64: FMT {Type : 128, Length : 89, Name : FMT, Format : BBnNZ, Columns : Type,Length,Name,Format,Columns}
1970-01-01 11:59:42.64: FMT {Type : 32, Length : 35, Name : PARM, Format : QNff, Columns : TimeUS,Name,Value,Default}
1970-01-01 11:59:37.60: PARM {TimeUS : 7177607245, Name : LOG_DISARMED, Value : 1.0, Default : qnan}
1970-01-01 11:59:37.60: FMT {Type : 66, Length : 24, Name : POWR, Format : QffHHB, Columns : TimeUS,Vcc,VServo,Flags,AccFlags,Safety}
1970-01-01 11:59:37.61: POWR {TimeUS : 7177613113, Vcc : 3.2975828647613525, VServo : qnan, Flags : 0, AccFlags : 0, Safety : 2}
1970-01-01 11:59:37.61: FMT {Type : 69, Length : 19, Name : AOA, Format : Qff, Columns : TimeUS,AOA,SSA}
1970-01-01 11:59:37.61: AOA {TimeUS : 7177613199, AOA : 0.0, SSA : 0.0}
1970-01-01 11:59:37.61: FMT {Type : 70, Length : 28, Name : ATT, Format : QccccCCCCB, Columns : TimeUS,DesRoll,Roll,DesPitch,Pitch,DesYaw,Yaw,ErrRP,ErrYaw,AEKF}
1970-01-01 11:59:37.61: ATT {TimeUS : 7177613257, DesRoll : 18.95, Roll : 18.95, DesPitch : 57.52, Pitch : 57.52, DesYaw : 0.0, Yaw : 271.17, ErrRP : 0.0, ErrYaw : 0.0, AEKF : 0}
1970-01-01 11:59:37.61: FMT {Type : 102, Length : 52, Name : PIDR, Format : QffffffffffB, Columns : TimeUS,Tar,Act,Err,P,I,D,FF,DFF,Dmod,SRate,Flags}
1970-01-01 11:59:37.61: PIDR {TimeUS : 7177613327, Tar : 0.0, Act : 0.0, Err : 0.0, P : 0.0, I : 0.0, D : 0.0, FF : 0.0, DFF : 0.0, Dmod : 0.0, SRate : 0.0, Flags : 0}
1970-01-01 11:59:37.61: FMT {Type : 103, Length : 52, Name : PIDP, Format : QffffffffffB, Columns : TimeUS,Tar,Act,Err,P,I,D,FF,DFF,Dmod,SRate,Flags}
1970-01-01 11:59:37.61: PIDP {TimeUS : 7177613374, Tar : 0.0, Act : 0.0, Err : 0.0, P : 0.0, I : 0.0, D : 0.0, FF : 0.0, DFF : 0.0, Dmod : 0.0, SRate : 0.0, Flags : 0}
1970-01-01 11:59:37.61: FMT {Type : 47, Length : 44, Name : XKF4, Format : QBcccccfffHBIHb, Columns : TimeUS,C,SV,SP,SH,SM,SVT,errRP,OFN,OFE,FS,TS,SS,GPS,PI}
1970-01-01 11:59:37.60: XKF4 {TimeUS : 7177605379, C : 0, SV : 0.0, SP : 0.0, SH : 0.0, SM : 0.0, SVT : 0.0, errRP : 0.0, OFN : 0.0, OFE : 0.0, FS : 128, TS : 0, SS : 0, GPS : 0, PI : 0}
1970-01-01 11:59:37.60: FMT {Type : 44, Length : 56, Name : XKF1, Format : QBccCfffffffccce, Columns : TimeUS,C,Roll,Pitch,Yaw,VN,VE,VD,dPD,PN,PE,PD,GX,GY,GZ,OH}
1970-01-01 11:59:37.60: XKF1 {TimeUS : 7177605379, C : 0, Roll : 0.0, Pitch : 0.0, Yaw : 0.0, VN : 0.0, VE : 0.0, VD : 0.0, dPD : 0.0, PN : 0.0, PE : 0.0, PD : 0.0, GX : 0.0, GY : 0.0, GZ : 0.0, OH : 0.0}
1970-01-01 11:59:37.60: FMT {Type : 45, Length : 46, Name : XKF2, Format : QBccccchhhhhhfff, Columns : TimeUS,C,AX,AY,AZ,VWN,VWE,MN,ME,MD,MX,MY,MZ,IDX,IDY,IS}
1970-01-01 11:59:37.60: XKF2 {TimeUS : 7177605379, C : 0, AX : 0.0, AY : 0.0, AZ : 0.0, VWN : 0.0, VWE : 0.0, MN : 0, ME : 0, MD : 0, MX : 0, MY : 0, MZ : 0, IDX : 0.0, IDY : 0.0, IS : 0.0}
1970-01-01 11:59:37.60: FMT {Type : 46, Length : 42, Name : XKF3, Format : QBcccccchhhccff, Columns : TimeUS,C,IVN,IVE,IVD,IPN,IPE,IPD,IMX,IMY,IMZ,IYAW,IVT,RErr,ErSc}
1970-01-01 11:59:37.60: XKF3 {TimeUS : 7177605379, C : 0, IVN : 0.0, IVE : 0.0, IVD : 0.0, IPN : 0.0, IPE : 0.0, IPD : 0.0, IMX : 0, IMY : 0, IMZ : 0, IYAW : 0.0, IVT : 0.0, RErr : 0.0, ErSc : 0.0}
1970-01-01 11:59:37.60: FMT {Type : 48, Length : 41, Name : XKF5, Format : QBBhhhcccCCfff, Columns : TimeUS,C,NI,FIX,FIY,AFI,HAGL,offset,RI,rng,Herr,eAng,eVel,ePos}
1970-01-01 11:59:37.60: XKF5 {TimeUS : 7177605379, C : 0, NI : 0, FIX : 0, FIY : 0, AFI : 0, HAGL : 0.0, offset : 0.0, RI : 0.0, rng : 0.0, Herr : 0.0, eAng : 0.0, eVel : 0.0, ePos : 0.0}
1970-01-01 11:59:37.60: FMT {Type : 51, Length : 19, Name : XKFS, Format : QBBBBBBBB, Columns : TimeUS,C,MI,BI,GI,AI,SS,GPS_GTA,GPS_CHK_WAIT}

[peterbarker]

Also works with mavlink backend:

2024-06-16 23:40:13.24: FMT {Type : 128, Length : 89, Name : FMT, Format : BBnNZ, Columns : Type,Length,Name,Format,Columns}
2024-06-16 23:40:13.24: FMT {Type : 32, Length : 35, Name : PARM, Format : QNff, Columns : TimeUS,Name,Value,Default}
2024-06-16 23:40:03.58: PARM {TimeUS : 72784208, Name : LOG_DISARMED, Value : 1.0, Default : qnan}
2024-06-16 23:40:03.58: FMT {Type : 116, Length : 76, Name : UNIT, Format : QbZ, Columns : TimeUS,Id,Label}
2024-06-16 23:40:03.58: FMT {Type : 115, Length : 44, Name : FMTU, Format : QBNN, Columns : TimeUS,FmtType,UnitIds,MultIds}
2024-06-16 23:40:03.58: FMT {Type : 117, Length : 20, Name : MULT, Format : Qbd, Columns : TimeUS,Id,Mult}
2024-06-16 23:40:03.58: FMT {Type : 91, Length : 51, Name : GPS, Format : QBBIHBcLLeffffB, Columns : TimeUS,I,Status,GMS,GWk,NSats,HDop,Lat,Lng,Alt,Spd,GCrs,VZ,Yaw,U}

[peterbarker]

Flew this on one of my Bixlers, replay and log-disarmed, 0 packets lost.

[tridge]

might as well make a variable for num_types()