Huge offset just before entering HOLDOVER state about oscillatord

[vvfedorenko]

@CharlesParent I was able to reproduce this problem in case of low-quality GNSS signal with debug=1. Full log is attached
oscillatord_huge_phaseoffset.log

The things that I would pay attention to are:

Mar 31 16:21:55 homelab.localdomain oscillatord[1465]: 16:21:55 DEBUG Phasemeter: phase_error: 0ns
Mar 31 16:21:55 homelab.localdomain oscillatord[1465]: 16:21:55 DEBUG GNSS data: Fix 3D (5), Fix ok: False, satellites num 5, antenna status: 4, valid 1, time 1648743657, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10686056, lsSet: True
Mar 31 16:21:55 homelab.localdomain oscillatord[1465]: 16:21:55 INFO  input: phase_error = (0s, 000000000ns),valid = false, lock = true, fine = 2509, coarse = 4186511, temp = 41.5°C, calibration requested: false
Mar 31 16:21:55 homelab.localdomain oscillatord[1465]: 16:21:55 DEBUG OD_PROCESS: State is 1, gnss valid is 0 and mRO lock is 1

Here we can see that with 2 PPS signals and 0 phase_error, this data point is treated as not valid, because GNSS fix state is false. At the same time, GNSS library thinks that GNSS point is valid. And the next cut:

Mar 31 16:21:56 homelab.localdomain oscillatord[1465]: 16:21:56 DEBUG Phasemeter: phase_error: 33672640ns
Mar 31 16:21:56 homelab.localdomain oscillatord[1465]: 16:21:56 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 4, antenna status: 4, valid 0, time 1648743658, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10686057, lsSet: True

Here we can see that phase_error is really high, but parsed GNSS data has Fix status True, even though GNSS library says this point is not valid. If this point is the latest in 6 seconds loop, OD_PROCESS will treat it as absolutely valid signal and will produce phase shift to absolutely crazy 33672640ns ahead.
You can find several occurrences of such situation in 1 minute log attached to this comment

[CharlesParent]

@vvfedorenko Could you rerun the test and send me logs with debug set to 1 in oscillatord.conf ?

I will do tests on my side

[CharlesParent]

@vvfedorenko I think I know the problem comes:

When the antenna is unplugged, the GNSS receiver takes some time to discard its value and to set its fix to false. during this period the time pulse is not to be trusted and may vary a lot because it relies on its internal OCXO.

Fortunately the GNSS receiver sends us data about the antenna status.
For test and experiences we have been very kind with the condition about the antenna status (we accept OK status, and also short and open state of the antenna).
What we could do is to only authorize disciplining when the anttenna status is OK and go in holdover else. This will drasticly decrease time to holdover when removing antenna but this would mean that some setup (for example if you have multiple splitters with other receivers connected) would not work and will stay forever in holdover.

Here is an example with antenna status accepting OPEN as a valid state: It takes 20 seconds to enter holdover:

16:22:02 DEBUG Phasemeter: phase_error: 0ns
16:22:03 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 19, antenna status: 2, valid 1, time 1648570923, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513323, lsSet: True, QErr(n) -397, qErr(n-1) 1211
16:22:03 DEBUG Phasemeter: phase_error: 5ns
16:22:04 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 17, antenna status: 4, valid 1, time 1648570924, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513324, lsSet: True, QErr(n) -2217, qErr(n-1) -397
16:22:04 DEBUG Phasemeter: phase_error: 5ns
16:22:05 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 15, antenna status: 4, valid 1, time 1648570925, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513325, lsSet: True, QErr(n) 3353, qErr(n-1) -2217
16:22:05 DEBUG Phasemeter: phase_error: 0ns
16:22:06 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 11, antenna status: 4, valid 1, time 1648570926, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513326, lsSet: True, QErr(n) -643, qErr(n-1) 3353
16:22:06 DEBUG Phasemeter: phase_error: 5ns
16:22:07 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 11, antenna status: 4, valid 1, time 1648570927, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513327, lsSet: True, QErr(n) 2537, qErr(n-1) -643
16:22:07 DEBUG Phasemeter: phase_error: 5ns
16:22:08 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 7, antenna status: 4, valid 1, time 1648570928, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513328, lsSet: True, QErr(n) 3187, qErr(n-1) 2537
16:22:08 INFO  input: phase_error = (0s, 000000005ns), valid = true, qErr = 2537,lock = true, fine = 2263, coarse = 4186525, temp = 42.4°C, calibration requested: false
16:22:08 DEBUG OD_PROCESS: State is 1, gnss valid is 1 and mRO lock is 1
16:22:08 DEBUG Unfiltered phase error: 5, qErr: 2537
16:22:08 DEBUG Phase filtered with qErr: 7.537000
16:22:08 DEBUG kalman->Kphase += interval * estimated_drift = 1.174740
16:22:08 INFO  Filtered phase is 3.827944
16:22:08 INFO  Estimated equilibrium with exponential smooth is 2254
16:22:08 INFO  get_reactivity gives 39.354023, react coeff is now -0.097269
16:22:08 INFO  Fine adjustement to value 2294 requested
16:22:08 DEBUG Phasemeter: phase_error: 0ns
16:22:09 DEBUG GNSS data: Fix 3D (5), Fix ok: False, satellites num 5, antenna status: 4, valid 1, time 1648570929, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513329, lsSet: True, QErr(n) -772, qErr(n-1) 3187
16:22:09 DEBUG Phasemeter: phase_error: 5ns
16:22:10 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 4, antenna status: 4, valid 0, time 1648570930, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513330, lsSet: True, QErr(n) 2138, qErr(n-1) -772
16:22:10 DEBUG Phasemeter: phase_error: 0ns
16:22:11 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 8, antenna status: 4, valid 1, time 1648570931, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513331, lsSet: True, QErr(n) -2417, qErr(n-1) 2138
16:22:11 DEBUG Phasemeter: phase_error: 5ns
16:22:12 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 9, antenna status: 4, valid 1, time 1648570932, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513332, lsSet: True, QErr(n) 895, qErr(n-1) -2417
16:22:12 DEBUG Phasemeter: phase_error: 0ns
16:22:13 DEBUG GNSS data: Fix 2D (4), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648570933, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513333, lsSet: True, QErr(n) 2913, qErr(n-1) 895
16:22:13 DEBUG Phasemeter: phase_error: -100ns
16:22:14 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 3, antenna status: 4, valid 1, time 1648570934, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513334, lsSet: True, QErr(n) 226, qErr(n-1) 2913
16:22:14 INFO  input: phase_error = (0s, -00000100ns), valid = true, qErr = 2913,lock = true, fine = 2294, coarse = 4186525, temp = 42.4°C, calibration requested: false
16:22:14 DEBUG OD_PROCESS: State is 1, gnss valid is 1 and mRO lock is 1
16:22:14 DEBUG Unfiltered phase error: -100, qErr: 2913
16:22:14 DEBUG Phase filtered with qErr: -97.086998
16:22:14 DEBUG kalman->Kphase += interval * estimated_drift = 3.244327
16:22:14 INFO  Filtered phase is -38.596066
16:22:14 INFO  get_reactivity gives 15.000000, react coeff is now 6.472466
16:22:14 WARN  Control value is out of range, if convergence is not reached consider recalibration or other reactivity parameters
16:22:14 INFO  Estimated drift is now -1.922828
16:22:14 INFO  Fine adjustement to value 3200 requested
16:22:14 DEBUG Phasemeter: phase_error: -140ns
16:22:15 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648570935, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513335, lsSet: True, QErr(n) 3000, qErr(n-1) 226
16:22:15 DEBUG Phasemeter: phase_error: -150ns
16:22:16 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648570936, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513336, lsSet: True, QErr(n) -1994, qErr(n-1) 3000
16:22:16 DEBUG Phasemeter: phase_error: -295ns
16:22:17 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648570937, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513337, lsSet: True, QErr(n) 1109, qErr(n-1) -1994
16:22:17 DEBUG Phasemeter: phase_error: -300ns
16:22:18 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 7, antenna status: 4, valid 1, time 1648570938, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513338, lsSet: True, QErr(n) 3765, qErr(n-1) 1109
16:22:18 DEBUG Phasemeter: phase_error: -310ns
16:22:19 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 6, antenna status: 4, valid 1, time 1648570939, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513339, lsSet: True, QErr(n) 3066, qErr(n-1) 3765
16:22:19 DEBUG Phasemeter: phase_error: -245ns
16:22:20 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 8, antenna status: 4, valid 1, time 1648570940, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513340, lsSet: True, QErr(n) -1971, qErr(n-1) 3066
16:22:20 INFO  input: phase_error = (0s, -00000245ns), valid = true, qErr = 3066,lock = true, fine = 3200, coarse = 4186525, temp = 42.4°C, calibration requested: false
16:22:20 DEBUG OD_PROCESS: State is 1, gnss valid is 1 and mRO lock is 1
16:22:20 DEBUG Unfiltered phase error: -245, qErr: 3066
16:22:20 DEBUG Phase filtered with qErr: -241.934006
16:22:20 DEBUG kalman->Kphase += interval * estimated_drift = -50.133036
16:22:20 INFO  Filtered phase is -130.118301
16:22:20 INFO  get_reactivity gives 15.000000, react coeff is now 16.128933
16:22:20 WARN  Control value is out of range, if convergence is not reached consider recalibration or other reactivity parameters
16:22:20 INFO  Estimated drift is now -1.922828
16:22:20 INFO  Fine adjustement to value 3200 requested
16:22:20 DEBUG Phasemeter: phase_error: -240ns
16:22:21 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 6, antenna status: 4, valid 1, time 1648570941, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513341, lsSet: True, QErr(n) 801, qErr(n-1) -1971
16:22:21 DEBUG Phasemeter: phase_error: -250ns
16:22:22 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 8, antenna status: 4, valid 1, time 1648570942, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513342, lsSet: True, QErr(n) -1682, qErr(n-1) 801
16:22:22 DEBUG Phasemeter: phase_error: -290ns
16:22:23 DEBUG GNSS data: Fix no fix (1), Fix ok: False, satellites num 5, antenna status: 4, valid 1, time 1648570943, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513343, lsSet: True, QErr(n) -1682, qErr(n-1) 801
16:22:24 DEBUG GNSS data: Fix no fix (1), Fix ok: False, satellites num 0, antenna status: 4, valid 0, time 1648570944, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513344, lsSet: True, QErr(n) -1682, qErr(n-1) 801
16:22:24 WARN  Phasemeter: Did not receive GNSS pps event
16:22:25 DEBUG GNSS data: Fix no fix (1), Fix ok: False, satellites num 0, antenna status: 4, valid 0, time 1648570945, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513345, lsSet: True, QErr(n) -1682, qErr(n-1) 801
16:22:26 DEBUG GNSS data: Fix no fix (1), Fix ok: False, satellites num 0, antenna status: 4, valid 0, time 1648570946, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513346, lsSet: True, QErr(n) -1682, qErr(n-1) 801
16:22:26 INFO  input: phase_error = (0s, -00000290ns), valid = false, qErr = 801,lock = true, fine = 3200, coarse = 4186525, temp = 42.4°C, calibration requested: false
16:22:26 DEBUG OD_PROCESS: State is 1, gnss valid is 0 and mRO lock is 1
16:22:26 WARN  HOLDOVER activated: GNSS data is not valid and/or oscillator's lock has been lost

You can see the disconnection of the antenna when the antenna status goes from 2 to 4

Here is another example where the only valid state for antenna is ok: It takes only 2 seconds

6:29:01 DEBUG Phasemeter: phase_error: -25ns
16:29:02 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 17, antenna status: 2, valid 1, time 1648571342, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513742, lsSet: True, QErr(n) -898, qErr(n-1) -3861
16:29:02 DEBUG Phasemeter: phase_error: -30ns
16:29:03 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 17, antenna status: 2, valid 1, time 1648571343, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513743, lsSet: True, QErr(n) 2416, qErr(n-1) -898
16:29:03 DEBUG Phasemeter: phase_error: -30ns
16:29:04 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 15, antenna status: 4, valid 0, time 1648571344, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513744, lsSet: True, QErr(n) -2351, qErr(n-1) 2416
16:29:04 DEBUG Phasemeter: phase_error: -25ns
16:29:05 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 10, antenna status: 4, valid 0, time 1648571345, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513745, lsSet: True, QErr(n) 868, qErr(n-1) -2351
16:29:05 INFO  input: phase_error = (0s, -00000025ns), valid = false, qErr = -2351,lock = true, fine = 2163, coarse = 4186525, temp = 42.5°C, calibration requested: false
16:29:05 DEBUG OD_PROCESS: State is 1, gnss valid is 0 and mRO lock is 1
16:29:05 WARN  HOLDOVER activated: GNSS data is not valid and/or oscillator's lock has been lost
16:29:05 INFO  Applying estimated equilibirum until going out of holdover
16:29:05 INFO  Fine adjustement to value 2372 requested
16:29:05 DEBUG Phasemeter: phase_error: -25ns
16:29:06 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 11, antenna status: 4, valid 0, time 1648571346, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10513746, lsSet: True, QErr(n) -3307, qErr(n-1) 868
16:29:06 DEBUG Phasemeter: phase_error: -20ns

[CharlesParent]

@vvfedorenko Could you please try with branch fix-holdover-enter-condition ?

[vvfedorenko]

@CharlesParent We use Huber-Suhner splitter to provide GPS signal to servers in rack, and we have normal operation status as following:

GNSS:
	fix: 3D (5)
	fixOk: true
	antenna_power: ON (1)
	antenna_status: OPEN (4)

That's why we cannot use this fix.

And the problem actually is somehow different. If you take closer look at logs I provided you can find that there were 2 consequent phase jumps in different directions (negative and then positive):

Mar 28 14:19:34 time05 oscillatord[32584]: 14:19:34 #033[32mINFO #033[0m input: phase_error = (0s, 032912790ns),valid = true, lock = true, fine = 2292, coarse = 4186>
Mar 28 14:19:34 time05 oscillatord[32584]: 14:19:34 #033[32mINFO #033[0m Phase jump requested
Mar 28 14:19:34 time05 oscillatord[32584]: 14:19:34 #033[32mINFO #033[0m /dev/ptp2: applying phase offset correction of -32912790ns
Mar 28 14:19:35 time05 oscillatord[32584]: 14:19:34 #033[33mWARN #033[0m Diff is sup to 500 ms, getting a third timestamp
Mar 28 14:19:35 time05 oscillatord[32584]: 14:19:35 #033[33mWARN #033[0m Could not get timestamp diff inferior to 500ms, restarting
Mar 28 14:19:36 time05 oscillatord[32584]: 14:19:36 #033[33mWARN #033[0m Diff is sup to 500 ms, getting a third timestamp
Mar 28 14:19:40 time05 oscillatord[32584]: 14:19:40 #033[32mINFO #033[0m input: phase_error = (0s, -32912800ns),valid = true, lock = true, fine = 2292, coarse = 4186>
Mar 28 14:19:40 time05 oscillatord[32584]: 14:19:40 #033[32mINFO #033[0m Phase jump requested
Mar 28 14:19:40 time05 oscillatord[32584]: 14:19:40 #033[32mINFO #033[0m /dev/ptp2: applying phase offset correction of 32912800ns
Mar 28 14:19:46 time05 oscillatord[32584]: 14:19:46 #033[32mINFO #033[0m input: phase_error = (0s, 031906890ns),valid = true, lock = true, fine = 2292, coarse = 4186>
Mar 28 14:19:46 time05 oscillatord[32584]: 14:19:46 #033[32mINFO #033[0m Phase jump requested
Mar 28 14:19:46 time05 oscillatord[32584]: 14:19:46 #033[32mINFO #033[0m /dev/ptp2: applying phase offset correction of -31906890ns
Mar 28 14:19:52 time05 oscillatord[32584]: 14:19:52 #033[32mINFO #033[0m input: phase_error = (0s, -31906890ns),valid = true, lock = true, fine = 2292, coarse = 4186>
Mar 28 14:19:52 time05 oscillatord[32584]: 14:19:52 #033[32mINFO #033[0m Phase jump requested
Mar 28 14:19:52 time05 oscillatord[32584]: 14:19:52 #033[32mINFO #033[0m /dev/ptp2: applying phase offset correction of 31906890ns

These jump look like some problem of providing PPS signal in ptp device that is monitored by phasemeter.
I would suggest filtering out such huge jumps in case when previous phase diffs were relatively small as we assume that Atomic Clock is precise enough to be stable for tens nanoseconds between PPS signals

[CharlesParent]

@vvfedorenko could you rerun the test with debug set to 1 in oscillatord.conf and send me the logs ?
Could you also tell me the exact time in logs where you disconnect the antenna ?
That way I will be able to understand when these phase jumps occur

[vvfedorenko]

@CharlesParent I started test with debug information, but the actual problem is that ART card lost GNSS when other servers showed good amount of satellites, there was no physical disconnection of antenna. This situation happens with all 4 ART card we have in prod right now occasionally and I will wait for another occurrence of it with debug log on.

[vvfedorenko]

I got even better log
oscillatord_huge_phaseoffset_1.log

Mar 31 17:17:24 homelab.localdomain oscillatord[1783]: 17:17:24 DEBUG Phasemeter: phase_error: 5ns
Mar 31 17:17:24 homelab.localdomain oscillatord[1783]: 17:17:24 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648746986, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689385, lsSet: True
Mar 31 17:17:25 homelab.localdomain oscillatord[1783]: 17:17:25 DEBUG Phasemeter: phase_error: 0ns
Mar 31 17:17:25 homelab.localdomain oscillatord[1783]: 17:17:25 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648746987, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689386, lsSet: True
Mar 31 17:17:26 homelab.localdomain oscillatord[1783]: 17:17:26 DEBUG Phasemeter: phase_error: 0ns
Mar 31 17:17:26 homelab.localdomain oscillatord[1783]: 17:17:26 DEBUG GNSS data: Fix 3D (5), Fix ok: False, satellites num 5, antenna status: 4, valid 1, time 1648746988, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689387, lsSet: True
Mar 31 17:17:27 homelab.localdomain oscillatord[1783]: 17:17:27 DEBUG Phasemeter: phase_error: 35666370ns
Mar 31 17:17:27 homelab.localdomain oscillatord[1783]: 17:17:27 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 4, antenna status: 4, valid 0, time 1648746989, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689388, lsSet: True
Mar 31 17:17:28 homelab.localdomain oscillatord[1783]: 17:17:28 DEBUG Phasemeter: phase_error: 0ns
Mar 31 17:17:28 homelab.localdomain oscillatord[1783]: 17:17:28 DEBUG GNSS data: Fix 3D (5), Fix ok: False, satellites num 5, antenna status: 4, valid 1, time 1648746990, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689389, lsSet: True
Mar 31 17:17:29 homelab.localdomain oscillatord[1783]: 17:17:29 DEBUG Phasemeter: phase_error: 35666365ns
Mar 31 17:17:29 homelab.localdomain oscillatord[1783]: 17:17:29 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 4, antenna status: 4, valid 0, time 1648746991, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689390, lsSet: True
Mar 31 17:17:30 homelab.localdomain oscillatord[1783]: 17:17:30 INFO  input: phase_error = (0s, 035666365ns),valid = true, lock = true, fine = 2502, coarse = 4186511, temp = 42.2°C, calibration requested: false
Mar 31 17:17:30 homelab.localdomain oscillatord[1783]: 17:17:30 DEBUG OD_PROCESS: State is 1, gnss valid is 1 and mRO lock is 1
Mar 31 17:17:30 homelab.localdomain oscillatord[1783]: 17:17:30 INFO  Phase jump requested
Mar 31 17:17:30 homelab.localdomain oscillatord[1783]: 17:17:30 INFO  /dev/ptp0: applying phase offset correction of -35666365ns
Mar 31 17:17:30 homelab.localdomain oscillatord[1783]: 17:17:30 DEBUG Phasemeter: phase_error: 5ns
Mar 31 17:17:30 homelab.localdomain oscillatord[1783]: 17:17:30 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648746992, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689391, lsSet: True
Mar 31 17:17:31 homelab.localdomain oscillatord[1783]: 17:17:31 DEBUG Phasemeter: phase_error: -35666365ns
Mar 31 17:17:31 homelab.localdomain oscillatord[1783]: 17:17:31 DEBUG GNSS data: Fix 3D (5), Fix ok: False, satellites num 5, antenna status: 4, valid 1, time 1648746993, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689392, lsSet: True
Mar 31 17:17:32 homelab.localdomain oscillatord[1783]: 17:17:32 DEBUG Phasemeter: phase_error: -5ns
Mar 31 17:17:32 homelab.localdomain oscillatord[1783]: 17:17:32 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 4, antenna status: 4, valid 0, time 1648746994, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689393, lsSet: True
Mar 31 17:17:33 homelab.localdomain oscillatord[1783]: 17:17:33 DEBUG Phasemeter: phase_error: -35666360ns
Mar 31 17:17:33 homelab.localdomain oscillatord[1783]: 17:17:33 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648746995, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689394, lsSet: True
Mar 31 17:17:34 homelab.localdomain oscillatord[1783]: 17:17:34 DEBUG Phasemeter: phase_error: -35666360ns
Mar 31 17:17:34 homelab.localdomain oscillatord[1783]: 17:17:34 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648746996, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689395, lsSet: True
Mar 31 17:17:35 homelab.localdomain oscillatord[1783]: 17:17:35 DEBUG Phasemeter: phase_error: -35666365ns
Mar 31 17:17:35 homelab.localdomain oscillatord[1783]: 17:17:35 DEBUG GNSS data: Fix 3D (5), Fix ok: True, satellites num 5, antenna status: 4, valid 1, time 1648746997, leapm_seconds 18, leap_notify 0, lsChange 0, timeToLsChange -10689396, lsSet: True
Mar 31 17:17:36 homelab.localdomain oscillatord[1783]: 17:17:36 DEBUG ignoring 1 input due to phase jump
Mar 31 17:17:36 homelab.localdomain oscillatord[1783]: 17:17:36 INFO  input: phase_error = (0s, -35666365ns),valid = true, lock = true, fine = 2502, coarse = 4186511, temp = 42.2°C, calibration requested: false
Mar 31 17:17:36 homelab.localdomain oscillatord[1783]: 17:17:36 DEBUG OD_PROCESS: State is 1, gnss valid is 1 and mRO lock is 1
Mar 31 17:17:36 homelab.localdomain oscillatord[1783]: 17:17:36 INFO  Phase jump requested
Mar 31 17:17:36 homelab.localdomain oscillatord[1783]: 17:17:36 INFO  /dev/ptp0: applying phase offset correction of 35666365ns
Mar 31 17:17:36 homelab.localdomain oscillatord[1783]: 17:17:36 DEBUG Phasemeter: phase_error: -71332725ns

First we got pahse_error: 35666365ns with Fix: true, but value is not parsed as valid by GNSS. At the same time was used to correct phase. Then couple of changes to other direction and the actual time goes bananas in the end.

[CharlesParent]

Hi @vvfedorenko ! Thanks for the logs, do not hesitate to post more logs in you have !

I will investigate why Fix Ok is returning false but valid still equals one.

Where do these logs come from ? Are you on your home setup on in a close-to-production setup ? Because you only have 4/5 satellites, this is not ideal

[vvfedorenko]

Hi @CharlesParent! Yes, it's my home setup and I specially made such conditions to have low-quality GNSS signal to reproduce the issue. According to our production setup monitoring we had the same conditions (small amount of visible satellites) during issues before