AP_Logger: make block logger conform to logging expectations

[andyp1per]

This PR fixes many, many bugs in the block logging code

• make block logger conform to mavlink expectations of numbering
• add support for log time to block logger
• support disarm rotation
• refactor rotation into backed. Don't start logs when erasing.
• correct log start logic
• separate read and write points so that requesting log information does not corrupt the current log
• when starting a new log stop logging first
• clear the write buffer when starting a new log
• insert utc time when requesting info for the current log
• stop logging and request formats again when starting a new log
• cope with erase happening while we are logging
• keep pushing out startup messages even when format messages are done.
• don't log to the gcs in the io thread
• don't start new logs in the io thread
• don't validate logs while erasing
• flush logs when stopping logging
• calculate size correctly by accounting for page headers
• calculate size correctly when the log is wrapped
• don't return data when asked for more data than in the log
• optimize locking and use separate semaphore to mediate ring buffer access
• stop logging when the current log has filled up the chip - otherwise the log file is useless
• added stats support
• reset dropped count when a new log is created

The change requires a logging format change for the block logger so will automatically erase existing logs. We should put this in the release notes FYI @rmackay9 @tridge

[peterbarker]

@andyp1per honestly, I have no idea why there was a mapping in the first place - and if there's no reason to have that mapping I'd be quite happy to see it go away. Your patches here show it's less code (i.e. fewer bugs) without the mapping.

[peterbarker]

-rw-r--r-- 1 pbarker pbarker 819200 May  6 09:31 00000002.BIN
-rw-r--r-- 1 pbarker pbarker 417792 May  6 09:31 00000004.BIN
-rw-r--r-- 1 pbarker pbarker      3 May  6 09:31 LASTLOG.TXT

Old:
Log 1 numLogs 1 lastLog 1 size 819200 Wed May 6 09:31:20 2020
New:
Log 4 numLogs 1 lastLog 4 size 417792 Wed May 6 09:31:49 2020

... so we're definitely doing gaps differently. Not worse, just different.

[peterbarker]

This breaks QGC.

QGC appears to be making the assumption that logs are indexed from zero. I'm not saying QGC is correct in this assumption, but in MAVProxy I'm seeing:

Log 1  numLogs 1 lastLog 1 size 0 
Log 1  numLogs 1 lastLog 1 size 0 
Log 1  numLogs 1 lastLog 1 size 0 
Log 1  numLogs 1 lastLog 1 size 0 
Log 1  numLogs 1 lastLog 1 size 0 
Log 1  numLogs 1 lastLog 1 size 0 

And a log list in MAVProxy gives me this:

MANUAL> Requesting log list
Log 4  numLogs 1 lastLog 4 size 417792 Wed May  6 09:31:49 2020

for:

-rw-r--r-- 1 pbarker pbarker 819200 May  6 09:31 00000002.BIN
-rw-r--r-- 1 pbarker pbarker 417792 May  6 09:31 00000004.BIN
-rw-r--r-- 1 pbarker pbarker      3 May  6 09:31 LASTLOG.TXT
pbarker@bluebottle:~/rc/ardupilot((HEAD detached at andyp1per/pr-flash-fix3))$ 

This shows two things:

• we need to have that mapping or we'll break QGC (I haven't tested MissionPlanner).
• we have a bug where requesting a range of logs which is out-of-range returns a non-zero number of logs

@DonLakeFlyer for visibility

[andyp1per]

Dang. Currently this means that QGC will not work with FRAM-based boards because they almost always return logs indexed from a higher number. And they are always contiguous.

[DonLakeFlyer]

Hmm, I"m not super familiar with the log download code. I don't quite get what the problem is. According to mavlink spec LOG_REQUEST_LIST.start it says first log id is 0. Is that where the problem is. If so, then how to you request the list of logs if you don't know the first id?

[andyp1per]

@DonLakeFlyer ah interesting! It also says that the last available should be tagged as 0xFFFF so I'm interested as to how you handle these since they seem like synthetic ids. Do you assume ids are contiguous?

[DonLakeFlyer]

Do you assume ids are contiguous?

Let me see if I can get Gus to help out here. I don't really know that code. Also if all of this is also caused by the mavlink spec notbeing clear on thing like (contiguous or not) that should get cleaned up as well.

[dogmaphobic]

It's been a looooong time since I last looked into that code. Yes, from what I remember, the assumption is that "0" is the first log file and it goes from there with an increment of 1 (i.e. first log file (0), second log file (1), third (2), etc.) From that perspective, it doesn't make sense to have gaps. If you have 4 log files, they will be 0, 1, 2 and 3.

[andyp1per]

@peterbarker I knew doing it this way would be harder 😄 - anyway have fixed and tested the block logger to do the same as the file logger. Works on my KakuteF7 Mini. Any other bugs around numbering are not mine as the file logger is now as it was before. I'm not sure how easy it will be to cope with gaps anyway - the block logger does not have this problem, the numbers are always contiguous.

[peterbarker]

On Wed, 6 May 2020, Don Gagne wrote: Hmm, I"m not super familiar with the log download code. I don't quite get what the problem is. According to mavlink spec LOG_REQUEST_LIST.start it says first log id is 0. Is that where the problem is. If so, then how to you request the list of logs if you don't know the first id?

Hmmm. Strange. That's not my reading of that comment, in fact: typedef struct __mavlink_log_request_list_t { uint16_t start; /*< First log id (0 for first available)*/ uint16_t end; /*< Last log id (0xffff for last available)*/ My reading of that is that 0 is *not*, in fact a valid ID. It's a magic number saying, "I probably don't know what the range of valid logs is, so please just start sending me the list from the lowest number". This is going to be the most common case. The way MAVProxy does this is it adds an entry into a hash for each log_entry message received. A log-download-all uses that hash to grab all logs. There's actually a natural race condition as we don't check that that list is complete. If I'm thinking right then we should be checking we've received a number of log_entry messages equal to LOG_ENTRY.num_logs (from any of the messages received) - but we don't.

[peterbarker]

On Wed, 6 May 2020, Andy Piper wrote: @peterbarker I knew doing it this way would be harder 😄 - anyway have fixed and tested the block logger to do the same as the file logger. Works on my KakuteF7 Mini. Any other bugs around numbering are not mine as the file logger is now as it was before. I'm not sure how easy it will be to cope with gaps anyway - the block logger does not have this problem, the numbers are always contiguous.

Until some bugger comes in and deletes one out of the middle :-) That's a known limitation. Let's put that aside.

[DonLakeFlyer]

Unless you have a sequential ID system how do you implement an item based protocol over a lossy link in a sane manner?

[peterbarker]

@DonLakeFlyer I think the LOG_ENTRY message contains sufficient information to accomplish it - each message contains the number of logs present on the system, so you can just count up the number of LOG_ENTRY responses you receive. If you don't get all of them with in femptoseconds, you must restart the LOG_LIST_REQUEST. Presumably you can specify the last log ID in your new request as the lowest log number which has a contiguous sequence up to the last_log_num present in each of the LOG_ENTRY packets... MAVProxy's use of a hash would allow for this to work (but ArduPilot won't ever send gappy log lists; a quick squiz at PX4 Firmware shows that it might, however).

And, of course, you have to assume that nobody is playing games with you - nobody adding or removing files....

[andyp1per]

@rmackay9 FYI, this bug exists in 4.0.3 also

[andyp1per]

@peterbarker could do with another review now

[andyp1per]

The stats support allows me to see that we really only can get a max of 125kb/s on the dataflash chips. I tried an experiment with quad page program, but that seems to trigger other problems so I gave up.

[peterbarker]

On Sun, 19 Jul 2020, Andy Piper wrote: The stats support allows me to see that we really only can get a max of 125kb/s on the dataflash chips. I tried an experiment with quad page program, but that seems to trigger other problems so I gave up.

So 12kB/s?

[andyp1per]

@peterbarker sorry 125kB/s, 1000kb/s

[vierfuffzig]

@andyp1per just testet on omnibusnanov6 with excellent results. thanks a lot again!

[peterbarker]

Could add a flow-of-control internal error for this sort of thing.

[andyp1per]

Yeah, but internal errors never clear and these can be transient. So I dunno....

[peterbarker]

Merged, thanks!

Appreciate your patience on this one.

Thanks also to all the testers of this PR!

I added some diagnostics for the disarm case I flagged - it's 0.2ms, quite acceptable.

@andyp1per would be nice to get a follow-up PR for the minor stuff I've tagged here.