Windows 10 getting strange timeouts from pfSense running w32tm /stripchart
-
I posted this over on reddit/sysadmin and felt like everyone there were broken robots or something
https://www.reddit.com/r/sysadmin/comments/wiutcd/15_ntp_queries_pass_then_pattern_of_1_response/
Or am I the broken robot? And what's up with my ntp-packet lossTracking 10.44.44.1 [10.44.44.1:123]. The current time is 8/8/2022 6:06:51 PM. 18:06:51, d:+00.0082480s o:-2167.5148292s [@ | ] 18:06:53, d:+00.0116425s o:-2167.5111673s [@ | ] 18:06:56, d:+00.1303509s o:-2167.4515853s [@ | ] 18:06:58, d:+00.0206609s o:-2167.5195336s [@ | ] 18:07:00, d:+00.0040292s o:-2167.5140717s [@ | ] 18:07:02, d:+00.0074171s o:-2167.5139673s [@ | ] 18:07:04, d:+00.0056643s o:-2167.5134431s [@ | ] 18:07:06, d:+00.0091521s o:-2167.5157149s [@ | ] 18:07:08, d:+00.0093153s o:-2167.5119231s [@ | ] 18:07:10, d:+00.0139556s o:-2167.5131276s [@ | ] 18:07:12, d:+00.0097919s o:-2167.5122211s [@ | ] 18:07:14, d:+00.0055584s o:-2167.5140281s [@ | ] 18:07:16, d:+00.0156451s o:-2167.5168013s [@ | ] 18:07:18, d:+00.0052002s o:-2167.5141456s [@ | ] 18:07:20, d:+00.0142125s o:-2167.5097240s [@ | ] 18:07:22, d:+00.0091005s o:-00.0045502s [ * ] 18:07:24, error: 0x800705B4 18:07:27, error: 0x800705B4 18:07:30, error: 0x800705B4 18:07:33, d:+00.0092455s o:-00.0046227s [ * ] 18:07:35, error: 0x800705B4 18:07:38, error: 0x800705B4 18:07:41, error: 0x800705B4 18:07:44, d:+00.0045669s o:-00.0022834s [ * ] 18:07:46, error: 0x800705B4 18:07:49, error: 0x800705B4 18:07:52, error: 0x800705B4 18:07:55, d:+00.0177104s o:-00.0088552s [ * ] 18:07:57, error: 0x800705B4 18:08:00, error: 0x800705B4 18:08:03, error: 0x800705B4 18:08:06, d:+00.0160178s o:-00.0080089s [ * ] 18:08:08, error: 0x800705B4 18:08:11, error: 0x800705B4 18:08:14, error: 0x800705B4 18:08:17, d:+00.0149625s o:-00.0074812s [ * ] 18:08:19, error: 0x800705B4 18:08:22, error: 0x800705B4 18:08:25, error: 0x800705B4 18:08:28, d:+00.0149499s o:-00.0074749s [ * ] 18:08:30, error: 0x800705B4 18:08:33, error: 0x800705B4 18:08:36, error: 0x800705B4 18:08:39, d:+00.0161804s o:-00.0080902s [ * ] 18:08:42, error: 0x800705B4 1``` -
Even this says it was posted 37 minutes ago as soon as I submitted it...
-
Is the clock on your Windows box really that far out?
The pattern of errors is weird. Do you see that from all hosts querying against ntpd in pfSense?
Steve
-
No it isn't that far out from what I see.
I see the same pattern of errors from the other Windows 10 machine on my network (a VM).
I don't know how to test in the same way as the /stripchart method from a debian machine.
The IP cameras I thought were strange when they were querying pfSense. Their reported origin time being way far out either in past or future. But I'm wondering if they just randomly generate that, the time pfSense responds with seems accurate.
-
@boethius you understand 2167 seconds your off is the 36-37 minutes you reported being off..
d is the delay in response the o is the actual offset from the timeserver your talking to and your client..
0x800705B4 means the time source isn’t available. So yeah you have a problem.
Set your local time, the offset from your windows pc and timesource (ntp on pfsense) if that is actually insync should be really close..
$ w32tm /stripchart /computer:192.168.9.100 Tracking 192.168.9.100 [192.168.9.100:123]. The current time is 8/10/2022 4:54:47 PM. 16:54:47, d:+00.0001144s o:+00.0000367s [ * ] 16:54:49, d:+00.0001525s o:+00.0000186s [ * ] 16:54:51, d:+00.0002116s o:+00.0000145s [ * ] 16:54:54, d:+00.0001762s o:+00.0000096s [ * ] 16:54:56, d:+00.0001188s o:+00.0000353s [ * ] 16:54:58, d:+00.0002407s o:+00.0000237s [ * ] 16:55:00, d:+00.0001947s o:+00.0000550s [ * ] 16:55:02, d:+00.0003062s o:+00.0000741s [ * ] 16:55:04, d:+00.0002196s o:+00.0000524s [ * ] 16:55:06, d:+00.0001851s o:+00.0000485s [ * ] 16:55:08, d:+00.0002053s o:+00.0000081s [ * ] 16:55:10, d:+00.0001881s o:+00.0000092s [ * ]Are you syncing over wireless or something - your delay times are huge.. Locally it should be like sub ms.. in response..
I am not really a fan of the windows implementation of keeping time.. I always just run the actual ntp client on my windows machines.
You can get a copy here
https://www.meinbergglobal.com/english/sw/ntp.htm#ntp_stable
https://www.meinbergglobal.com/download/ntp/windows/ntp-4.2.8p15-v2-win32-setup.exe -
Is the pfSense time accurate? Is the ntp log error free?
-
https://pastebin.com/6WczqvKn
Here's the ntp log.
pfsense time is accurate as far as I can tell.
-
@boethius well right here ntp in pfsense is not in sync
Aug 8 09:52:28 ntpd 82489 kernel reports TIME_ERROR: 0x41: Clock Unsynchronized -
@johnpoz Ok, I was simply using the 'date' command and checking against a clock in a browser to see if it was synchronized better than 1s. Which it was.
I don't know why it would report unsynchronized on Aug 8.
I think there's a general problem in software that conditions users to accepting errors and warnings as "normal". But for now, what am I to make of it?
Jul 13 15:28:52 ntpd 43971 0.0.0.0 c012 02 freq_set kernel 43.732 PPM Jul 13 15:28:52 ntpd 43971 kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Jul 13 15:28:52 ntpd 43971 0.0.0.0 c01d 0d kern kernel time sync enabled Jul 13 15:28:52 ntpd 43971 kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Jul 13 15:28:52 ntpd 43971 0.0.0.0 8811 81 mobilize assoc 64855 Jul 13 15:28:52 ntpd 43971 0.0.0.0 8811 81 mobilize assoc 64854 Jul 13 15:28:52 ntpd 43971 0.0.0.0 8811 81 mobilize assoc 64853 Jul 13 15:28:52 ntpd 43971 Listening on routing socket on fd #31 for interface updates Jul 13 15:28:52 ntpd 43971 Listen normally on 10 lagg0.44 10.44.44.1:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 9 lagg0.44 [fe80::20d:b9ff:fe51:9ba6%15]:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 8 lagg0.172 172.16.0.1:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 7 lagg0.172 [fe80::20d:b9ff:fe51:9ba6%14]:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 6 lagg0.192 192.168.1.1:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 5 lagg0.192 [fe80::20d:b9ff:fe51:9ba6%13]:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 4 lagg0.35 10.44.35.1:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 3 lagg0.35 [fe80::20d:b9ff:fe51:9ba6%12]:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 2 lo0 127.0.0.1:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 1 lo0 [fe80::1%6]:123 Jul 13 15:28:52 ntpd 43971 Listen normally on 0 lo0 [::1]:123 Jul 13 15:28:52 ntpd 43971 gps base set to 2021-01-24 (week 2142) Jul 13 15:28:52 ntpd 43971 basedate set to 2021-01-24 Jul 13 15:28:52 ntpd 43971 proto: precision = 0.413 usec (-21) Jul 13 15:28:52 ntpd 43849 ---------------------------------------------------- Jul 13 15:28:52 ntpd 43849 available at https://www.nwtime.org/support Jul 13 15:28:52 ntpd 43849 corporation. Support and training for ntp-4 are Jul 13 15:28:52 ntpd 43849 Inc. (NTF), a non-profit 501(c)(3) public-benefit Jul 13 15:28:52 ntpd 43849 ntp-4 is maintained by Network Time Foundation, Jul 13 15:28:52 ntpd 43849 ---------------------------------------------------- Jul 13 15:28:52 ntpd 43849 Command line: /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid Jul 13 15:28:52 ntpd 43849 ntpd 4.2.8p15@1.3728-o Fri Feb 5 22:07:56 UTC 2021 (1): Starting Jul 13 15:28:52 ntpd 15196 0.0.0.0 061d 0d kern kernel time sync disabled Jul 13 15:28:52 ntpd 15196 23.157.160.168 local addr 10.44.44.1 -> <null> Jul 13 15:28:52 ntpd 15196 23.157.160.168 1412 82 demobilize assoc 18793 Jul 13 15:28:52 ntpd 15196 50.205.244.37 local addr 10.44.44.1 -> <null> Jul 13 15:28:52 ntpd 15196 50.205.244.37 1612 82 demobilize assoc 18792 Jul 13 15:28:52 ntpd 15196 50.205.244.108 local addr 10.44.44.1 -> <null> Jul 13 15:28:52 ntpd 15196 50.205.244.108 1412 82 demobilize assoc 18791 Jul 13 15:28:52 ntpd 15196 0.0.0.0 8812 82 demobilize assoc 18785 Jul 13 15:28:52 ntpd 15196 0.0.0.0 8812 82 demobilize assoc 18784 Jul 13 15:28:52 ntpd 15196 0.0.0.0 8812 82 demobilize assoc 18783 Jul 13 15:28:52 ntpd 15196 ntpd exiting on signal 15 (Terminated) Jul 13 13:20:03 ntpd 15196 50.205.244.37 145a 8a sys_peer Jul 13 10:44:29 ntpd 15196 50.205.244.37 144a 8a sys_peer Jul 13 10:13:42 ntpd 15196 50.205.244.108 14fa 8a sys_peer Jul 13 05:00:34 ntpd 15196 50.205.244.37 143a 8a sys_peer Jul 13 04:48:56 ntpd 15196 23.157.160.168 146a 8a sys_peer Jul 13 03:50:12 ntpd 15196 50.205.244.37 142a 8a sys_peer Jul 13 01:38:52 ntpd 15196 50.205.244.108 14ea 8a sys_peer Jul 13 00:19:53 ntpd 15196 50.205.244.37 141a 8a sys_peerLooking at this section, all within the same second, it tells me that "gps base set to 2021-01-24" when it's July of '22, and there's no "GPS" unit on this pfsense box. It also says basedate set to the same , totally wrong date.
It tells me that kernel time sync is disabled. Then enabled. To me, it doesn't make sense. I'm coming from the standpoint of having done a basic configuration of pfSense and wanting to fix it. What should I do if its reporting that it is unsynchronized, as it is?
And what of the change in PID? Significant? Why would the PID change suddenly, all within the same second. because NTP shutdown. But why would it do that?
-
Yeah it's normal to see those sync errors when ntpd starts and ~5min after it starts but not any time after that. Your logs look to have only the expected errors.
What pfSense version is that? The only reason I can imagine the base dates being that far out is if it's a much older version.
Steve
-
@stephenw10 Running version 2.5.2.
-
Any reason you're not running 2.6.0?
The base date are set at compile time I believe which is why it's reporting that. It shouldn't make any real difference though other than maybe a little longer to sync.
Steve
