Re: NTP stuck in init state

Rickyccnp2020 · ‎07-03-2020

Installed Tardis2000 (Windows-based NTP server) on my laptop configured my switch (Catalyst 3750-X) as a client to sync with the NTP server.

Even though the two devices see each others and exchange messages, the time on the switch is not syncing with the NTP server

Switch# ping 192.168.1.10
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 192.168.1.10, timeout is 2 seconds:
!!!!!
Success rate is 100 percent (5/5), round-trip min/avg/max = 1/4/9 ms

clock timezone EST -5 0
clock summer-time EDT date Mar 8 2020 0:00 Nov 1 2020 0:00

.

.ntp server 192.168.1.10 prefer source Vlan1

Current configuration : 85 bytes
!
interface Vlan1
ip address 192.168.1.122 255.255.255.0
ntp broadcast client
end

Switch#sh ntp status
Clock is unsynchronized, stratum 16, no reference clock
nominal freq is 119.2092 Hz, actual freq is 119.2092 Hz, precision is 2**19
ntp uptime is 869200 (1/100 of seconds), resolution is 8403
reference time is 00000000.00000000 (19:00:00.000 EST Thu Dec 31 1899)
clock offset is 0.0000 msec, root delay is 0.00 msec
root dispersion is 130.34 msec, peer dispersion is 0.00 msec
loopfilter state is 'FSET' (Drift set from file), drift is 0.000000000 s/s
system poll interval is 8, never updated.
Switch#sh ntp ass
Switch#sh ntp associations

address ref clock st when poll reach delay offset disp
~192.168.1.10 .USER. 16 - 1024 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 8192 0 0.000 0.000 15937.

Switch#sh ntp status
Clock is unsynchronized, stratum 16, no reference clock
nominal freq is 119.2092 Hz, actual freq is 119.2092 Hz, precision is 2**19
ntp uptime is 966600 (1/100 of seconds), resolution is 8403
reference time is 00000000.00000000 (19:00:00.000 EST Thu Dec 31 1899)
clock offset is 0.0000 msec, root delay is 0.00 msec
root dispersion is 144.95 msec, peer dispersion is 0.00 msec
loopfilter state is 'FSET' (Drift set from file), drift is 0.000000000 s/s
system poll interval is 8, never updated.

Switch#debug ntp all
NTP events debugging is on
NTP core messages debugging is on
NTP clock adjustments debugging is on
NTP reference clocks debugging is on
NTP packets debugging is on
Switch#
*Jan 2 02:32:12.668: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:32:12.668: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:32:12.668: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:32:45.736: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:33:16.665: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:33:16.665: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:33:16.665: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:33:49.725: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:34:04.723: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:34:20.687: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:34:20.687: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:34:20.687: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:34:42.724: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:35:02.722: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:35:24.700: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:35:24.700: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:35:24.700: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:35:51.728: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:36:28.705: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:36:28.714: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:36:28.714: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:37:32.719: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:37:32.727: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:37:32.727: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:37:42.727: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:37:47.726: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:38:17.724: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 02:38:36.732: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 02:38:36.732: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 02:38:36.732: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 02:38:52.729: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).

Richard Burts · ‎07-03-2020

If you are configuring ntp server then I would suggest removing the ntp broadcast client from the vlan interface config. If that does not improve things then please post the complete config of the switch.

HTH

Rick

Rickyccnp2020 · ‎07-03-2020

The NTP server is the software on the Windows machine. (192.168.1.10)

I have removed the ntp broadcast client config from int vlan 1

Now debug shows:

ntp: IPv4 NTP broadcast packet discarded on interface Vlan1 (not a broadcast client).

>ping 192.168.1.122 -t

Pinging 192.168.1.122 with 32 bytes of data:
Reply from 192.168.1.122: bytes=32 time=2ms TTL=255
Reply from 192.168.1.122: bytes=32 time=7ms TTL=255
Reply from 192.168.1.122: bytes=32 time=1ms TTL=255
Reply from 192.168.1.122: bytes=32 time=6ms TTL=255
Reply from 192.168.1.122: bytes=32 time=1ms TTL=255
Reply from 192.168.1.122: bytes=32 time=13ms TTL=255
Reply from 192.168.1.122: bytes=32 time=2ms TTL=255
Reply from 192.168.1.122: bytes=32 time=3ms TTL=255
Reply from 192.168.1.122: bytes=32 time=14ms TTL=255
Reply from 192.168.1.122: bytes=32 time=9ms TTL=255
Reply from 192.168.1.122: bytes=32 time=15ms TTL=255
Reply from 192.168.1.122: bytes=32 time=8ms TTL=255

Ping statistics for 192.168.1.122:
Packets: Sent = 12, Received = 12, Lost = 0 (0% loss),
Approximate round trip times in milli-seconds:
Minimum = 1ms, Maximum = 15ms, Average = 6ms

running config file attached

Georg Pauwen · ‎07-04-2020

Hello,

try and use a different NTP version (3 is the default I think, so try 1 or 2):

ntp server x.x.x.x version 1/2

Also, it sometimes help to manually set the clock to something close to the real time (wait for a while an check if the device synchronizes)

clock set

Rickyccnp2020 · ‎07-04-2020

I have tried that. Same results.
ntp server 192.168.1.10 prefer source Vlan1 version 2

The problem is not with the configurations, but more of the switch accepting sync request from that NTP server.
If I point the switch to a Cisco router that's running NTP server it will work just fine.
What I can't figure out is debug is not pinpointing any problem withe communication between server and client .

*Jan 2 07:47:13.393: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:47:13.401: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:47:13.401: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:47:30.564: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:48:17.415: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:48:17.415: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:48:17.415: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:48:37.564: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:49:21.428: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:49:21.428: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:49:21.428: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:50:25.442: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:50:25.442: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:50:25.442: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:50:34.568: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:51:13.567: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:51:29.455: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:51:29.455: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:51:29.455: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:52:33.477: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:52:33.477: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:52:33.485: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:53:37.499: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:53:37.499: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:53:37.499: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:54:41.512: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:54:41.512: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:54:41.512: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:55:18.565: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:55:45.517: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:55:45.517: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:55:45.517: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:56:11.564: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:56:30.564: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:56:49.522: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:56:49.522: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:56:49.522: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:57:18.564: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:57:53.544: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 07:57:53.544: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 07:57:53.544: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 07:58:16.571: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).

Rickyccnp2020 · ‎07-04-2020

When the switch is pointed to a different NTP server ( Cisco router acting as a master)

Sync take place immediately

*Jul 4 10:16:33.458: NTP Core(INFO): 192.168.1.120 8034 84 reachable
*Jul 4 10:16:33.458: NTP Core(INFO): 192.168.1.120 964A 8A sys_peer
*Jul 4 10:16:33.458: NTP Core(NOTICE): Clock is synchronized.
Jul 4 10:16:35.463: NTP message sent to 192.168.1.120, from interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:35.463: NTP message received from 192.168.1.120 on interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:35.463: NTP Core(DEBUG): ntp_receive: message received
Jul 4 10:16:35.463: NTP Core(DEBUG): ntp_receive: peer is 0x09719208, next action is 1.
Jul 4 10:16:37.468: NTP message sent to 192.168.1.120, from interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:37.468: NTP message received from 192.168.1.120 on interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:37.468: NTP Core(DEBUG): ntp_receive: message received
Jul 4 10:16:37.468: NTP Core(DEBUG): ntp_receive: peer is 0x09719208, next action is 1.
Jul 4 10:16:39.465: NTP message sent to 192.168.1.120, from interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:39.465: NTP message received from 192.168.1.120 on interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:39.465: NTP Core(DEBUG): ntp_receive: message received
Jul 4 10:16:39.465: NTP Core(DEBUG): ntp_receive: peer is 0x09719208, next action is 1.
Jul 4 10:16:41.461: NTP message sent to 192.168.1.120, from interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:41.461: NTP message received from 192.168.1.120 on interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:41.461: NTP Core(DEBUG): ntp_receive: message received
Jul 4 10:16:41.461: NTP Core(DEBUG): ntp_receive: peer is 0x09719208, next action is 1.
Jul 4 10:16:43.483: NTP message sent to 192.168.1.120, from interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:43.483: NTP message received from 192.168.1.120 on interface 'Vlan1' (192.168.1.122).
Jul 4 10:16:43.483: NTP Core(DEBUG): ntp_receive: message received
Jul 4 10:16:43.483: NTP Core(DEBUG): ntp_receive: peer is 0x09719208, next action is 1.

#sh ntp associations

address ref clock st when poll reach delay offset disp
*~192.168.1.120 .LOCL. 1 37 64 3 2.308 -3.389 63.382
192.168.1.10 .INIT. 16 - 4096 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 4096 0 0.000 0.000 15937.
192.168.1.10 .INIT. 16 - 4096 0 0.000 0.000 15937.
* sys.peer, # selected, + candidate, - outlyer, x falseticker, ~ configured

sh ntp status
Clock is synchronized, stratum 2, reference is 192.168.1.120
nominal freq is 119.2092 Hz, actual freq is 119.2092 Hz, precision is 2**19
ntp uptime is 2929200 (1/100 of seconds), resolution is 8403
reference time is E2AAD581.761FAE9A (06:16:33.461 EDT Sat Jul 4 2020)
clock offset is -3.3893 msec, root delay is 2.30 msec
root dispersion is 7943.12 msec, peer dispersion is 1.85 msec
loopfilter state is 'CTRL' (Normal Controlled Loop), drift is -0.000000011 s/s
system poll interval is 64, last update
Jul 4 10:18:58.455: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122). was 146 sec ago.

sh clock
06:19:22.824 EDT Sat Jul 4 2020

But that does not resolve the issue why I'm unable to sync with the Windows-based server, which I know it's configured correctly.

I have restarted the service on the windows machine but did not resolve the issue.

The search for an answer continues .........................................

Richard Burts · ‎07-04-2020

Are there any logs on the Tardis that might shed light on what is going on? If you have no problem getting NTP from another device but can not get it from Tardis it seems that something is not in agreement between you and Tardis.

HTH

Rick

Rickyccnp2020 · ‎07-04-2020

That's what I'm trying to figure out. I don't have any kind of authentication between the two devices, but Tardis has an option to generate a debug log. I'll try that and see what I can come up with

What's also strange is, NTP debug on the switch did not show any type of error, it was receiving the NTP solicitation message from the NTP server and responding back as you can see on the debug output

*Jan 2 07:59:00.578: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 07:59:21.566: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 08:00:01.563: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 08:00:01.571: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 08:00:01.571: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 08:01:05.585: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 08:01:05.593: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 08:01:05.593: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 08:01:05.593: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 08:01:28.569: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 08:01:29.568: NTP Core(DEBUG): drift value to save: 0.000000000
*Jan 2 08:01:29.568: %NTP : Drift string saved to persistent data: NTPv4_Drift=0.0
*Jan 2 08:01:29.568: NTP Core(DEBUG): drift value saved.
*Jan 2 08:01:29.568: NTP Core(DEBUG): hourly stats called. Count=8
*Jan 2 08:01:53.568: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 08:02:09.590: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 08:02:09.590: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 08:02:09.590: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 08:03:13.603: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 08:03:13.603: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 08:03:13.603: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.
*Jan 2 08:03:48.567: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 08:04:01.569: NTP message sent to 192.168.1.10, from interface 'Vlan1' (192.168.1.122).
*Jan 2 08:04:17.625: NTP message received from 192.168.1.10 on interface 'Vlan1' (255.255.255.255).
*Jan 2 08:04:17.625: NTP Core(DEBUG): ntp_receive: message received
*Jan 2 08:04:17.625: NTP Core(DEBUG): ntp_receive: peer is 0x00000000, next action is 6.

Georg Pauwen · ‎07-04-2020

Hello,

can you check if SNTP works ?

--> sntp server 192.168.1.10

I somewhere remember that, at least that's what it used to be, any Windows machine does SNTP only...

Rickyccnp2020 · ‎07-05-2020

Good tip, Let me try it

Rickyccnp2020 · ‎07-05-2020

SW10(config)#ntp authenticate
SW10(config)#ntp authenticatication
SW10(config)#ntp authentication-key 1 md5 NTPKEY
SW10(config)#ntp trusted-key 1

SW10(config)#ntp server 192.168.1.10 prefer source Vlan1 version 2

SW10#sh ntp association

address ref clock st when poll reach delay offset disp
~192.168.1.10 .INIT. 16 - 64 0 0.000 0.000 15937.
* sys.peer, # selected, + candidate, - outlyer, x falseticker, ~ configured

SW10#sh ntp status
Clock is unsynchronized, stratum 16, no reference clock
nominal freq is 119.2092 Hz, actual freq is 119.2092 Hz, precision is 2**19
ntp uptime is 17724600 (1/100 of seconds), resolution is 8403
reference time is E2AD172F.586E3CDC (23:21:19.345 EDT Sun Jul 5 2020)
clock offset is 0.0000 msec, root delay is 0.00 msec
root dispersion is 1.18 msec, peer dispersion is 0.00 msec
loopfilter state is 'NSET' (Never set), drift is 0.000000000 s/s
system poll interval is 64, last update was 214 sec ago.

SW10#ntp clear drift

.Jul 6 03:34:18.245: NTP Core(NOTICE): ntpd PPM
.Jul 6 03:34:18.245: NTP Core(DEBUG): internal drift value reset.
.Jul 6 03:34:18.245: %NTP : Internal Drift Reset.
.Jul 6 03:34:18.245: %NTP : Drift string saved to persistent data: NTPv4_Drift=0.0
.Jul 6 03:34:18.254: %NTP : Exernal Drift Removed.
.Jul 6 03:34:18.254: %NTP : Drift Totally Removed.

Now the Switch is sending messages to the Tardis server, but not receiving any replies

I have already restarted the Windows time service and the Tradis time service

Not sure if I need to apply any other configurations on under the vlan 1 interface