Inconsistent data logging

[adamgarbo]

Hi @PaulZC,

Here's a Monday head-scratcher for you.

I've been testing the most recent release of the u-blox library. The tests were configured with rolling alarms that would log RAWX/SFRBX for 2 hours and sleep for 1 hour. After letting it run overnight, I discovered some very strange behaviour.

In the initial test, the first 2-hour logging period at 22:00 executes as normal. However, at 1:00, data stopped being received 45 minutes into the 2-hour period. The sleep/wake cycles continued as normal, but no data was received over the next 12 hours. Upon each wake cycle, the RTC synchronization function would also fail to obtain a GNSS fix, timing out after 5 minutes, and only 165 KB would be written to the SD card. However, magically at 16:00, data began being received again.

I use a flag to record initialization success/failure and the u-blox showed as successfully initializing at each power cycle. I thought perhaps the issue was due to low battery voltage, so I replaced the battery and repeated the test with the same firmware. As you can see in the results of Test 2, the same behaviour was observed.

I should note that I am using the gnss.end() function before powering down the u-blox. Could this in any way explain the issues described here? I am also wondering if this could also be somehow related to the file buffer or how data is being processed.

Test 1

Datetime	u-blox Init. (ms)	RTC Sync (ms)	GNSS Logging (ms)	Bytes Written	Max Buffer
2021-04-03 22:00:00	1273	26666	7200917	8418448	3016
2021-04-04 1:00:00	1023	26540	7235913	3252824	2680
2021-04-04 4:00:00	1269	300000	6974230	165504	528
2021-04-04 7:00:00	1270	300000	6977998	165576	528
2021-04-04 10:00:00	1025	300000	6987520	165528	528
2021-04-04 13:00:00	1024	300000	6985682	165552	528
2021-04-04 16:00:00	1270	300000	6924799	7558288	2624

Test 2

Datetime	u-blox Init. (ms)	RTC Sync (ms)	GNSS Logging (ms)	Bytes Written	Max Buffer
2021-04-04 23:00:00	1018	26240	7193951	8029560	2696
2021-04-05 2:00:00	1270	26213	7216366	7762696	2600
2021-04-05 5:00:00	1270	300000	6965067	165576	528
2021-04-05 8:00:00	1270	300000	6978940	165552	528
2021-04-05 11:00:00	1269	300000	6986883	165456	528
2021-04-05 14:00:00	1271	300000	6970831	3637352	2608

Cheers,
Adam

[PaulZC]

Head-scratcher is right...
So what data do the 165KB files contain?
If you suspect .end, please try a test with it commented out. It should make no difference whatsoever.
Thanks!
Paul

[adamgarbo]

Hi Paul,

Strangely, the log files contain 165 KB of 0x02 0x15 RAWX messages and no SFRBX. RTKLIB doesn't recognize the .UBX file as valid and can't convert it to RINEX.

What is really perplexing is that the received data is randomly starting/stopping in the middle of the logging periods.

I'm currently running a shorter, 30-minute duration test with code that has improved debugging (i.e. it tracks microSD writes, syncs, closes, etc.). Ideally, I'd log all of the u-blox debugging information over serial but it's not possible to do so outdoors. Can you recommend any specific u-blox flags I should track and log to the debug file to help determine what could be happening?

On a side note, should I be disabling gnss.setAutoPVT(true); during RAWX/SFRBX logging? It's really only required for syncing the RTC. Will it cause unnecessary processing of data (i.e. discarding PVT messages)?

Cheers,
Adam

b562 0215 1000 0000 0000 00b0 7240 0000
1200 0001 1594 4548 b562 0215 1000 0000
0000 00c0 7240 0000 1200 0001 fd97 40cb
b562 0215 1000 0000 0000 00d0 7240 0000
1200 0001 e59b 3c4f b562 0215 1000 0000
0000 00e0 7240 0000 1200 0001 cd9f 38d3
b562 0215 1000 0000 0000 00f0 7240 0000
1200 0001 b5a3 3457 b562 0215 1000 0000
0000 0000 7340 0000 1200 0001 9da7 31e5
b562 0215 1000 0000 0000 0010 7340 0000
1200 0001 85ab 2d69 b562 0215 1000 0000
0000 0020 7340 0000 1200 0001 6daf 29ed
b562 0215 1000 0000 0000 0030 7340 0000
1200 0001 55b3 2571 b562 0215 1000 0000
0000 0040 7340 0000 1200 0001 3db7 21f5
b562 0215 1000 0000 0000 0050 7340 0000
1200 0001 25bb 1d79 ...

[PaulZC]

RTKLIB will fail if there are no SFRBX messages in the UBX files.
Have you tried the UBX integrity checker on those 165KB files? Is the integrity good?
I'm wondering if the myGNSS.setAutoRXMSFRBX(true, false); or myGNSS.logRXMSFRBX(); is being skipped or ignored?
Calling .end will delete all of the RAM allocated for message processing, so you won't see anything sensible in the u-blox structs after calling that. But it would be useful to log the contents of automaticFlags after the .begin and logRXMRAWX / logRXMSFRBX and again before .end just to make sure addToFileBuffer is being set .
Cheers,
Paul

[adamgarbo]

Morning Paul,

Well, this is interesting. I ran another test overnight without .end() and did not encounter the same behaviour. While there was a single failed RTC sync, the timeout was set to 60 seconds and since the receiver is cold-starting each time, I'm only slightly worried. The u-blox also seemed to initialize twice as fast as before.

Datetime	u-blox Init. (ms)	RTC Sync (ms)	GNSS Logging (ms)	Bytes Written	Max Buffer
2021-04-05 21:00:00	519	26495	7187896	10506440	3096
2021-04-06 0:00:00	517	26963	7203331	9571024	2648
2021-04-06 3:00:00	767	26703	7234098	9296928	2656
2021-04-06 6:00:00	518	26962	7247904	9863944	2784
2021-04-06 9:00:00	267	60000	7227219	9752104	3056
2021-04-06 12:00:00	519	27121	7265789	8009536	2904

The only real major change in the code was the omission of the .end() function, so I'm super curious as to what's going on. I still can't think of anything that could start/stop the data stream in the middle of logging. I'll modify the code to log the flags you mentioned and perform another test tonight with the .end() function enabled.

Regarding the integrity of the 165 KB file, it looks like there was simply a lot of empty RAWX messages. No message larger than 16 bytes, which is not much bigger than the basic UBX frame.

UBX Sync Char 1 (0xB5) found at byte 0. Checking for Sync Char 2

Processed 165552 bytes
File size was 165552
Longest UBX message was 16 data bytes
Message types and totals were:
Message type: 0x02 0x15   Total: 6898

Bye!

Cheers,
Adam

[PaulZC]

Here's a theory...
If the RAWX packets contain (only) 16 bytes, they are 'empty', in that numMeas is zero. So that means the module is not tracking any satellites...
Might all constellations have been disabled? GPS included? Could that happen?

[PaulZC]

Maybe try using individual calls to enableGNSS in your if (gnssConfigFlag) code, instead of a multi-cfgvalset? Might be more robust?

[adamgarbo]

It does seem like the u-blox stops tracking the satellite constellations, but does the .end() function clear the CFG-SIGNAL values?

In my code, I only configure the satellite signals once when the program runs for the first time. If I recall correctly, doesn't the newCfgValset8 save to all memory locations?

  // Configure communication interfaces and satellite signals only if the program is running for the first time
  if (gnssConfigFlag)
  {
    // Configure satellite signals
    bool setValueSuccess = true;
    setValueSuccess &= gnss.newCfgValset8(UBLOX_CFG_SIGNAL_GPS_ENA, 1);   // Enable GPS
    setValueSuccess &= gnss.addCfgValset8(UBLOX_CFG_SIGNAL_GLO_ENA, 1);   // Enable GLONASS
    setValueSuccess &= gnss.addCfgValset8(UBLOX_CFG_SIGNAL_GAL_ENA, 0);   // Disable Galileo
    setValueSuccess &= gnss.addCfgValset8(UBLOX_CFG_SIGNAL_BDS_ENA, 0);   // Disable BeiDou
    setValueSuccess &= gnss.sendCfgValset8(UBLOX_CFG_SIGNAL_QZSS_ENA, 0); // Disable QZSS
    myDelay(2000);
    if (!setValueSuccess)
    {
      DEBUG_PRINTLN("Warning: Satellite signals not configured!");
    }
    gnssConfigFlag = false; // Clear flag
  }

Quick edit, if I'm not mistaken, the .enableGNSS() functionality is deprecated for the ZED-F9P.

[PaulZC]

Correct, newCfgValset defaults to all layers (VAL_LAYER_ALL), so the constellations settings should be being saved in BBR.
Correct, enableGNSS is deprecated, but it still works! ;-)
Doing it the new way, maybe individual calls using setVal8 might be more robust than a combined CfgValset. But, agreed, if you're only setting the constellations once then all of this should make no difference...
.end only deletes the memory allocated for message processing. It does not communicate with the module.

[PaulZC]

Final suggestion for now:
Maybe increase this delay to a couple of seconds? Maybe you're just trying to talk to the GNSS module too soon after powering it on?
Cheers!

[PaulZC]

Ignore that... I see you're waiting 2.5seconds already

[adamgarbo]

I wonder if it could be due to a faulty antenna: https://www.sparkfun.com/products/17751 or cable https://www.sparkfun.com/products/17833

[PaulZC]

Seems unlikely. But, that said, I did manage to mate an SMA antenna connection slightly off-angle the other day and, as I tightened it, pushed the central pin back up into the cable. The lack of signal had me scratching my head for a while...

[adamgarbo]

Ugh! I did that to one of my u-blox ANN-MB antennas.

Gosh, this problem is a real tough nut to crack. Perhaps what I'll do is try to run three receivers with the exact same code and see if they all experience the same temporary loss of signal at the same time.

My thought is that if it were a code issue, it would work or it wouldn't. I can't see any way that the satellite tracking could stop in the middle of a logging window, and then magically start again several hours later.

I suppose there is always a risk that the u-blox could have been damaged by ESD, but it is a new module.

Cheers,
Adam

[PaulZC]

Please investigate .end a bit more. It is entirely possible there's a gotcha in there...
Thanks!

[adamgarbo]

As a quick update, I conducted another test overnight. I paired the code that had previously experienced the signal loss (.end() enabled) with an ANN-MB antenna and a different u-blox receiver. No issues were observed.

Datetime	u-blox Init. (ms)	RTC Sync (ms)	GNSS Logging (ms)	Bytes Written	Max Buffer
2021-04-07 0:00:00	514	26688	7168726	7607896	2600
2021-04-07 3:00:00	515	10602	7216069	7615208	2808
2021-04-07 6:00:00	770	9591	7225570	7606392	2720
2021-04-07 9:00:00	769	9412	7231385	9035856	3000
2021-04-07 12:00:00	520	10989	7240428	7949936	2736

I also uploaded the new code to the receiver and TOP106 antenna that had experienced the signal losses (.end() disabled), and again no issues.

🤔

[PaulZC]

Happy days! Many thanks Adam,
Let's leave this open for now just in case you see any more weirdness.
All the best,
Paul

[adamgarbo]

Maybe it was space weather!

Joking aside, I'll continue testing and keep this issue updated with my findings.

Cheers,
Adam

[Niv1900]

Honestly guys you are great, a big thank you to you! As a beginner it's great to be able to benefit from your hindsight!

[PaulZC]

Hi Adam (@adamgarbo ),
Any updates on this? I will be releasing a new version of the library soon, so it would be good to try and close this out before the (if possible!).
Thanks!
Paul

[adamgarbo]

Hi Paul,

I haven't been able to replicate the issue again after the initial two instances (on back-to-back days). It looks like it will remain a mystery for now, so I'm happy to close this issue and revisit it again if I re-encounter it.

Cheers,
Adam

[PaulZC]

Good man - thank you!
Paul