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

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...

Jun 14 '24 12:06 peterbarker

I like where this is going!

Jun 14 '24 14:06 andyp1per

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.

Jun 14 '24 22:06 IamPete1

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.

Jun 16 '24 08:06 peterbarker

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.

Jun 16 '24 09:06 IamPete1

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}

Jun 16 '24 10:06 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}

Jun 16 '24 13:06 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}

Jun 16 '24 13:06 peterbarker

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

Jul 01 '24 03:07 peterbarker