Log files with old date in filename created/used when turning logging on and off

[tonycanike]

Subject of the issue

Old log files are opened and written to when turning logging on and off.

While debugging another issue, I was trying to get the Facet to close the current and open a new log file by turning logging off and on (via AP WiFi or serial) when I noticed this issue. ( The other issue is I'm still getting corrupted log files (UBX_Integrity_checker.py reporting resyncs). See #345 . I had a theory that using the AP WiFi configuration and/or the serial menu was consuming resources (heap, CPU, etc.) that caused the log file corruption. )

Serial terminal log below. You can see way down at the bottom that a days-old old log file was reopened when newer (from this same day) log files existed.

I think the user should have more control to open a clean new file, but that will be a separate issue (#344 ).

Your workbench

Facet (the one before cases came with them)
Firmware: RC from October 1, 2022

Steps to reproduce

SparkFun RTK Facet v2.6-RC-Oct 1 2022
** Bluetooth broadcasting as: Facet Rover-4CC2 **
Menu: Main

1. Configure GNSS Receiver
2. Configure GNSS Messages
3. Configure Base
4. Configure Ports
5. Configure Logging
   p) Configure User Profiles
   r) Configure Radios
   s) Configure System
   f) Firmware upgrade
   x) Exit
   ss

Menu: System
[ 62238][W][Wire.cpp:204] begin(): Bus already started in Master Mode.
GNSS: Online - ZED-F9P firmware: HPG 1.32
SIV: 26, HPA (m): 1.125, Lat: 38.20844032, Lon: -79.62183965, Altitude (m): 624.5
Display: Online
Accelerometer: Online
Fuel Gauge: Online - Batt (101%) / Voltage: 4.20V
microSD: Online
Bluetooth (4CC2): Online
WiFi MAC Address: 30:C6:F7:41:4C:C0
System Uptime: 0 00:01:02.262 (Resets: 0)
f) Display microSD Files
e) Echo User Input: On
d) Configure Debug
z) Set time zone offset: 00:00:00
b) Set Bluetooth Mode: Classic
c) Enable/disable WiFi NMEA client (connect to phone): Disabled
n) Enable/disable WiFi NMEA server: Disabled
r) Reset all settings to default
B) Switch to Base mode
R) Switch to Rover mode
W) Switch to WiFi Config mode
S) Shut down
x) Exit
ff
Files found (date time size name):

2022-10-03 11:57 5274 SFE_Facet_Settings_0.txt
2022-09-20 22:59 5197 SFE_Facet_Settings_2.txt
2022-10-03 11:48 13214 SFE_Facet_221003_114753.ubx
2022-04-17 11:45 3599 SFE_Facet_Settings ROVER As Delivered 2022-04-17.txt
2022-10-03 11:52 121166 SFE_Facet_221003_115117.ubx
2022-10-03 11:50 87174459 SFE_Facet_220927_155046.ubx
2022-08-02 15:18 1997360 RTK_Surveyor_Firmware_v2_3.bin
2022-08-19 20:18 5198 SFE_Facet_Settings_0_SAFE.txt
2022-08-19 20:19 5201 SFE_Facet_Settings_1_SAFE.txt
2022-08-19 20:24 5200 SFE_Facet_Settings_2_SAFE.txt
2022-08-19 20:17 5202 SFE_Facet_Settings_3_SAFE.txt
2022-09-20 14:57 2052352 RTK_Surveyor_Firmware_v2_4.bin
2022-09-27 08:08 2225008 RTK_Surveyor_Firmware_v2_5.bin
2022-10-03 07:43 2160832 RTK_Surveyor_Firmware_RC-Oct_01_2022.bin

Menu: System
[ 62991][W][Wire.cpp:204] begin(): Bus already started in Master Mode.
GNSS: Online - ZED-F9P firmware: HPG 1.32
SIV: 26, HPA (m): 1.125, Lat: 38.20844032, Lon: -79.62183965, Altitude (m): 624.5
Display: Online
Accelerometer: Online
Fuel Gauge: Online - Batt (101%) / Voltage: 4.20V
microSD: Online
Bluetooth (4CC2): Online
WiFi MAC Address: 30:C6:F7:41:4C:C0
System Uptime: 0 00:01:03.015 (Resets: 0)
f) Display microSD Files
e) Echo User Input: On
d) Configure Debug
z) Set time zone offset: 00:00:00
b) Set Bluetooth Mode: Classic
c) Enable/disable WiFi NMEA client (connect to phone): Disabled
n) Enable/disable WiFi NMEA server: Disabled
r) Reset all settings to default
B) Switch to Base mode
R) Switch to Rover mode
W) Switch to WiFi Config mode
S) Shut down
x) Exit
xx

SparkFun RTK Facet v2.6-RC-Oct 1 2022
** Bluetooth broadcasting as: Facet Rover-4CC2 **
Menu: Main

1. Configure GNSS Receiver
2. Configure GNSS Messages
3. Configure Base
4. Configure Ports
5. Configure Logging
   p) Configure User Profiles
   r) Configure Radios
   s) Configure System
   f) Firmware upgrade
   x) Exit
   22

Menu: GNSS Messages
Active messages: 7

1. Set NMEA Messages
2. Set RTCM Messages
3. Set RXM Messages
4. Set NAV Messages
5. Set MON Messages
6. Set TIM Messages
7. Reset to Surveying Defaults (NMEAx5)
8. Reset to PPP Logging Defaults (NMEAx5 + RXMx2)
9. Turn off all messages
10. Turn on all messages
    x) Exit
    88
    Reset to PPP Logging Defaults (NMEAx5 + RXMx2)

Menu: GNSS Messages
Active messages: 7

1. Set NMEA Messages
2. Set RTCM Messages
3. Set RXM Messages
4. Set NAV Messages
5. Set MON Messages
6. Set TIM Messages
7. Reset to Surveying Defaults (NMEAx5)
8. Reset to PPP Logging Defaults (NMEAx5 + RXMx2)
9. Turn off all messages
10. Turn on all messages
    x) Exit
    xx
    menuMessages: UART1 messages successfully enabled

SparkFun RTK Facet v2.6-RC-Oct 1 2022
** Bluetooth broadcasting as: Facet Rover-4CC2 **
Menu: Main

1. Configure GNSS Receiver
2. Configure GNSS Messages
3. Configure Base
4. Configure Ports
5. Configure Logging
   p) Configure User Profiles
   r) Configure Radios
   s) Configure System
   f) Firmware upgrade
   x) Exit

[ 92225][D][NVM.ino:90] recordSystemSettingsToFileSD(): Removing from SD: /SFE_Facet_Settings_0.txt
[ 92268][D][NVM.ino:109] recordSystemSettingsToFileSD(): Settings recorded to SD: /SFE_Facet_Settings_0.txt
[ 92292][D][NVM.ino:136] recordSystemSettingsToFileLFS(): Removing LittleFS: /SFE_Facet_Settings_0.txt
[ 92423][D][NVM.ino:148] recordSystemSettingsToFileLFS(): Settings recorded to LittleFS: /SFE_Facet_Settings_0.txt
Rover Accuracy (m): 1.1181
Batt (101%): Voltage: 4.20V Charging: 0.83%/hr Green
Rover Accuracy (m): 1.0626
Rover Accuracy (m): 1.0558

SparkFun RTK Facet v2.6-RC-Oct 1 2022
** Bluetooth broadcasting as: Facet Rover-4CC2 **
Menu: Main

1. Configure GNSS Receiver
2. Configure GNSS Messages
3. Configure Base
4. Configure Ports
5. Configure Logging
   p) Configure User Profiles
   r) Configure Radios
   s) Configure System
   f) Firmware upgrade
   x) Exit
   55

Menu: Logging
microSD card is online

1. Log to microSD: Disabled
2. Write Marks_date.csv file to microSD: Disabled
   x) Exit
   11

Menu: Logging
microSD card is online

1. Log to microSD: Enabled
2. Set max logging time: 1440 minutes
3. Set max log length: 1440 minutes
4. Write Marks_date.csv file to microSD: Disabled
   x) Exit
   xx

SparkFun RTK Facet v2.6-RC-Oct 1 2022
** Bluetooth broadcasting as: Facet Rover-4CC2 **
Menu: Main

1. Configure GNSS Receiver
2. Configure GNSS Messages
3. Configure Base
4. Configure Ports
5. Configure Logging
   p) Configure User Profiles
   r) Configure Radios
   s) Configure System
   f) Firmware upgrade
   x) Exit
   xx
   [108959][D][NVM.ino:90] recordSystemSettingsToFileSD(): Removing from SD: /SFE_Facet_Settings_0.txt
   [109004][D][NVM.ino:109] recordSystemSettingsToFileSD(): Settings recorded to SD: /SFE_Facet_Settings_0.txt
   [109029][D][NVM.ino:136] recordSystemSettingsToFileLFS(): Removing LittleFS: /SFE_Facet_Settings_0.txt
   [109271][D][NVM.ino:148] recordSystemSettingsToFileLFS(): Settings recorded to LittleFS: /SFE_Facet_Settings_0.txt
   Rover Accuracy (m): 1.0559
   Batt (101%): Voltage: 4.20V Charging: 0.62%/hr Green
   [109464][D][menuMessages.ino:369] beginLogging(): Using last log file.
   Appending last available log
   Log file created: SFE_Facet_220927_155046.ubx
   UBX file size: 87174556 - Generation rate: 17434.9kB/s - Write speed: 18690942.5kB/s

Tell us how to reproduce this issue. Please post any log files from serial output that may have been generated.

Expected behavior

Tell us what should happen

Actual behavior

Tell us what happens instead

[nseidle]

Let's walk through the logic to try to explain what's going on:

When the unit powers on, it checks to see if the boot was normal power on then reuseLastLog = false. If boot was because system was reset (could be anything from WiFi AP config reset to system overload) then reuseLastLog = true;

So when you go into the logging menu and disable logging, then re-enable logging, the system still uses the reuseLastLog variable. ie, if you've recently configured the device from AP, it will 'reuse'. If you've recently powered on the device, it will create a new log. I've confirmed this behavior.

Now, there's a 3rd dimension: how do we establish what the 'last' log was. It's not a sophisticated search. Here's the code:

  while (tempFile.openNext(&dir, O_READ))
  {
    if (tempFile.isFile())
    {
      tempFile.getName(fname, sizeof(fname));

      //Check for matching file name prefix and extension
      if (strcmp(LOG_EXTENSION, &fname[strlen(fname) - strlen(LOG_EXTENSION)]) == 0)
      {
        if (strstr(fname, LOG_PREFIX) != NULL)
        {
          strcpy(lastLogName, fname); //Store this file as last known log file
          foundAFile = true;
        }
      }
    }
    tempFile.close();
  }

Essentially, we get a list of files (in some order) and remember the last file name we see on the list. The problem is that I'm not entirely sure how the files will be listed, but I suspect it is listed by creation date/time not by last modified date/time. This works fine if the unit is generating the files but if you are loading files via computer->SD card, or modifying files, or swapping SD cards between units I would not be surprised if the unit attempts to append to a file that looks older.

If we really want to be sure to record to the last log (for sure, for sure), we could store the log name into the settings file and pull it.

Given that #344 is implemented, is this still an issue?

[tonycanike]

Thank you for the detailed explanation, appreciate it! The functionality to reopen the last log file could be very useful to many applications. Yes, the implementation of #344 makes this a non-issue.