Log the NTP events
I almost started writing an EEM applet that would detect and log the changes in router’s system time caused by NTP synchronizations, but then I’ve decided to check the IOS documentation first and found the ntp logging command.
For example, if you configure…
rtr(config)#ntp logging
rtr(config)#ntp server 172.16.0.12
… the router will generate the following syslog messages when it synchronizes its time with the NTP server:
%NTP-6-RESTART: NTP process starts
%SYS-6-CLOCKUPDATE: System clock has been updated from 17:06:03 UTC Fri Mar 30 2007 to 17:04:07 UTC Fri Mar 30 2007, configured from NTP by 172.16.0.12.
%NTP-5-PEERSYNC: NTP synced to peer 172.16.0.12
I had it enabled - was filling the logs with "lost contact with NTP server", "connected to NTP server", "lost contact" and so on and so on forever.
Funny thing is that the NTP server is located on the internal network, there are multiple redundant paths to it, and no packet filtering/firewall between client and servers.
Dunno WHY keeps losing contact with it, and then being able to contact it again.
Cisco IOS Software, C2600 Software (C2600-ADVSECURITYK9-M), Version 12.4(17), RELEASE SOFTWARE (fc1)
000251: Oct 9 2007 07:05:39.021 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 07:05:38 EDT Tue Oct 9 2007 to 07:05:39 EDT Tue Oct 9 2007, configured from NTP by 172.16.1.9.
000252: Oct 9 2007 07:05:39.025 EDT: %NTP-4-UNSYNC: NTP sync is lost
000253: Oct 9 2007 07:06:43.020 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000254: Oct 9 2007 07:06:43.020 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000255: Oct 9 2007 14:10:26.876 EDT: %NTP-4-UNSYNC: NTP sync is lost
000256: .Oct 9 2007 14:22:48.475 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 14:22:47 EDT Tue Oct 9 2007 to 14:22:48 EDT Tue Oct 9 2007, configured from NTP by 172.16.1.9.
000257: Oct 9 2007 14:23:52.422 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000258: Oct 9 2007 14:23:52.422 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000259: Oct 9 2007 14:26:00.432 EDT: %NTP-4-UNSYNC: NTP sync is lost
000260: .Oct 9 2007 14:31:19.980 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 14:31:20 EDT Tue Oct 9 2007 to 14:31:19 EDT Tue Oct 9 2007, configured from NTP by 172.16.1.9.
000261: Oct 9 2007 14:32:23.991 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000262: Oct 9 2007 14:32:23.991 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000263: Oct 9 2007 23:05:29.174 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 23:05:29 EDT Tue Oct 9 2007 to 23:05:29 EDT Tue Oct 9 2007, configured from NTP by 172.16.1.9.
000264: Oct 9 2007 23:05:29.178 EDT: %NTP-4-UNSYNC: NTP sync is lost
000265: Oct 9 2007 23:06:33.177 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000266: Oct 9 2007 23:06:33.177 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000267: Oct 10 2007 07:05:05.260 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 07:05:05 EDT Wed Oct 10 2007 to 07:05:05 EDT Wed Oct 10 2007, configured from NTP by 172.16.1.9.
000268: Oct 10 2007 07:05:05.264 EDT: %NTP-4-UNSYNC: NTP sync is lost
000269: Oct 10 2007 07:06:09.263 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000270: Oct 10 2007 07:06:09.263 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000271: Oct 10 2007 15:05:40.312 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 15:05:40 EDT Wed Oct 10 2007 to 15:05:40 EDT Wed Oct 10 2007, configured from NTP by 172.16.1.9.
000272: Oct 10 2007 15:05:40.316 EDT: %NTP-4-UNSYNC: NTP sync is lost
000273: Oct 10 2007 15:06:44.315 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000274: Oct 10 2007 15:06:44.315 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000275: Oct 10 2007 23:03:18.413 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 23:03:18 EDT Wed Oct 10 2007 to 23:03:18 EDT Wed Oct 10 2007, configured from NTP by 172.16.1.9.
000276: Oct 10 2007 23:03:18.417 EDT: %NTP-4-UNSYNC: NTP sync is lost
000277: Oct 10 2007 23:04:22.408 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000278: Oct 10 2007 23:04:22.412 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000279: Oct 11 2007 00:34:35.585 EDT: %NTP-4-UNSYNC: NTP sync is lost
000280: .Oct 11 2007 00:40:51.813 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 00:40:51 EDT Thu Oct 11 2007 to 00:40:51 EDT Thu Oct 11 2007, configured from NTP by 172.16.1.9.
000281: Oct 11 2007 00:41:29.817 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000282: Oct 11 2007 00:41:29.817 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000283: Oct 11 2007 00:50:45.851 EDT: %NTP-4-UNSYNC: NTP sync is lost
000284: .Oct 11 2007 00:56:17.632 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 00:56:17 EDT Thu Oct 11 2007 to 00:56:17 EDT Thu Oct 11 2007, configured from NTP by 172.16.1.9.
000285: Oct 11 2007 00:57:21.635 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000286: Oct 11 2007 00:57:21.635 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000287: Oct 11 2007 07:06:03.467 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 07:06:03 EDT Thu Oct 11 2007 to 07:06:03 EDT Thu Oct 11 2007, configured from NTP by 172.16.1.9.
000288: Oct 11 2007 07:06:03.471 EDT: %NTP-4-UNSYNC: NTP sync is lost
000289: Oct 11 2007 07:07:07.466 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000290: Oct 11 2007 07:07:07.466 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
000291: Oct 11 2007 11:17:17.944 EDT: %NTP-4-UNSYNC: NTP sync is lost
000292: .Oct 11 2007 11:23:02.403 EDT: %WCCP-5-SERVICEFOUND: Service 60 acquired on WCCP client 192.168.1.6
000293: .Oct 11 2007 11:23:06.402 EDT: %WCCP-5-SERVICEFOUND: Service 80 acquired on WCCP client 192.168.1.6
000294: .Oct 11 2007 11:23:12.408 EDT: %WCCP-5-SERVICEFOUND: Service 81 acquired on WCCP client 192.168.1.6
000295: .Oct 11 2007 11:23:12.408 EDT: %WCCP-5-SERVICEFOUND: Service 82 acquired on WCCP client 192.168.1.6
000296: .Oct 11 2007 11:23:12.412 EDT: %WCCP-5-SERVICEFOUND: Service 83 acquired on WCCP client 192.168.1.6
000297: .Oct 11 2007 11:23:24.408 EDT: %WCCP-5-SERVICEFOUND: Service web-cache acquired on WCCP client 192.168.1.6
000298: Oct 11 2007 12:26:18.075 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000299: Oct 11 2007 15:05:43.525 EDT: %SYS-6-CLOCKUPDATE: System clock has been updated from 15:05:43 EDT Thu Oct 11 2007 to 15:05:43 EDT Thu Oct 11 2007, configured from NTP by 172.16.1.9.
000300: Oct 11 2007 15:05:43.529 EDT: %NTP-4-UNSYNC: NTP sync is lost
000301: Oct 11 2007 15:06:47.528 EDT: %NTP-5-PEERSYNC: NTP synced to peer 172.16.1.9
000302: Oct 11 2007 15:06:47.528 EDT: %NTP-6-PEERREACH: Peer 172.16.1.9 is reachable
There were *no* routing protocol flaps, nor interface flaps, nor reloads, nor nothing . . .
Is it working for you? Are you syncing to another IOS device or to pool.ntp.org ?
It looks to me that you have a clock drift problem somewhere. The first three resync events in your printout shift the clock by a second in both directions, so obviously the router is trying to estimate the correct clock frequency and correcting back-and-forth.
Even after a good estimate of the clock frequency is achieved, it gets out-of-sync every now and then (next few days), which (to me) indicate a jitter somewhere. It might be the hardware clocks, the overloaded network or a non-responsive NTP server.
I can only guess what might be the causes, but check the load on the links. Also, if you're syncing to another IOS device, make sure it's not heavily loaded; routers tend to forward data before they turn their attention to other trivial things like NTP packets. Furthermore, as IOS is non-preemptive operating system, one process (for example, BGP or OSPF routing process) can usurp the CPU for a long time, making NTP processing unreliable. Does anything I've written apply to you?