Playoff Logfiles Not Saved to /media/sda1
randomstring opened this issue · 10 comments
We are running AdvantageKit with logging set up as described in in the docs:
logger.addDataReceiver(new WPILOGWriter("/media/sda1"));
logger.addDataReceiver(new NT4Publisher());This last weekend we had our first competition event and I pulled the USB thumbdrive to review some match data. I discovered that none of the playoff matches got recorded, there are a couple fragments of wpilog files, but not a complete match. I was able to find at least a few of our qual match data in it's entirety in the logs. There are also some "temp" files, partial log file on the thumb drive. I'm wondering if we're doing something wrong or if there's a bug in the wpilib tempfile renaming. Maybe reanaming isn't working on FAT32?
The USB thumb drive is formatted FAT32. I didn't see any guidance in the docs about what format to use for the USB drive.
I will pull the logs from the roboRIO later today and see what they say.
Directory listing below, sorted by file modification time.
Never mind. All the match data was in the temp_ files. I hadn't downloaded all the temp files.
I was not expecting temp files to have production data in them. Temp files, in my experience, are transitory files that are expected to be deleted. Is this a AdvantageKit thing or a WPILib thing?
I’m glad you found the data, but this is definitely not the expected behavior. The temp files are meant to be renamed when the RIO receives a timestamp from the DS. I’ll take a look when I get a chance.
v2.2.2 makes some improvements to the logic for detecting when the timestamp is updated from the DS. Let me know if you see the issue again on the new release (I know it may not be easily reproducible).
I spoke too soon, we did lose data. We only have a small fragment of data, from before being enabled, of our Finals 1 match. There's data missing from other matches as well. We have plenty of log files from when we did systems checks in the pits, which is not as useful.
I haven't looked at the code. Shouldn't there be a log rotate event when disconnecting from FMS to make sure the match data is captured?
Is there some issue with the file renaming failing on FAT32? Should we format the USB drive in ext3? Are temp files getting written to /tmp ?
Might there be some evidence in the DS logs about the file rename failing? I can check them later today.
Is 0b2a046 going to be sufficient in a competition setting where the DS might have a very long delay before connecting to the robot? seems like FMS is always being restarted before matches. Last weekend there were several times where our robot was powered on for > 1 minute before our DS attached.
I'm not sure how to test this without having a FMS system.
Not sure if this is related, but we noticed an issue where we had a robot code reboot while waiting for match start. Upon reviewing the logs, it looks like we only have a single log file temp_qxx.wpilog for that match.
What is the expected behavior for Logfile naming during matches? I would think the filename would be the match name and a timestamp to account for this situation. It looks to me like the code currently just renames to the match name without timestamp though. And when the DataLog setFilename function is called, that rename operation is destructive if a file already exists with it.
@jwbonner should I create a new issue for the above or is that the intended behavior?
OK, I've done some further testing and I think there are several issues here:
- Before 0b2a046, the check for when the timestamp was received from the DS was broken after a clean shutdown. This meant that the timestamp could sometimes be incorrect but still included in the filename. This is the same issue as allwpilib#5164 and should now be fixed. @randomstring this will work on the FMS because (when it works correctly, see below) data is written to the temporary log file until the DS connects. Even if the DS connection doesn't happen for several minutes the robot will log data normally and rename the log once a timestamp is received.
- On v2.2.2, when the timestamp and match number are updated in the same cycle several rename operations occur in quick succession. Adding the match number involved modifying the current filename, which didn't work in that case. 3c5e563 fixes this issue by renaming only once per loop cycle and building the filename from its components during a rename operation (prefix + time + match + suffix). We were running with this code during our event last weekend and it worked perfectly.
- If a timestamp is not received from the DS for any reason, the destructive rename operation means that data can be lost. This should theoretically only happen if the robot is turned on without a DS (which wouldn't include useful data), but if anything goes wrong with the timestamp rename during a match the data is lost. To fix this, 3c5e563 uses WPILib's strategy of adding a random string to log files without timestamps. This is mostly a last resort to ensure that match data can't be lost.
To be clear, the expected behavior for renaming log files should now be:
- The code starts and creates a log file with a random identifier (e.g.
Log_a10a94b7e465f11f.wpilog) - A timestamp is received from the DS and 8 seconds later the log is renamed (e.g.
Log_23-03-12_17-32-04.wpilog) - When on FMS, a match number is received from the DS and the log is renamed (e.g.
Log_23-03-12_17-32-04_e15.wpilog).
I'll make a v2.2.3 release shortly. As I said, this has all been tested on a real FMS successfully.
I haven't checked all the files yet to make sure they aren't truncated, but all the ones I have look goo. Filenames look correct. All our elimination matches are in files like Log_23-03-19_13-00-19_e1.wpilog and not temp_e1.wpilog.
As far as I can tell, this issue has been fixed. Feel free to reopen or create a new issue if there are continued problems with file renaming.