search

sparkfun / SparkFun_RTK_Firmware

Centimeter precision GPS/GNSS using L1/L2 signals broadcast over Bluetooth SPP (using the ESP32) in an easy to use enclosure.
https://docs.sparkfun.com/SparkFun_RTK_Firmware/
Other
82 stars 46 forks source link

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

Closed tonycanike closed 2 years ago

tonycanike commented 2 years ago

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 4) 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 commented 2 years ago

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 commented 2 years ago

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.