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 available from IOS release 12.3(7)T.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

5 comments:

  1. And you will disable it in two days - or before.

    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.

    ReplyDelete
  2. and adding to the previous post - I've found the "ip ssh logging events" more useful :)

    ReplyDelete
  3. I don't know what you're doing; I have it enabled on my home router and it hasn't generated a message in weeks. You might have an actual problem (whatever it is) that the ntp logging has uncovered ...

    ReplyDelete
  4. c2610a# sh ve | inc IOS
    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 ?

    ReplyDelete
  5. I'm syncing with two external NTP servers (one belonging to my ISP, another one further away).

    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?

    ReplyDelete

You don't have to log in to post a comment, but please do provide your real name/URL. Anonymous comments might get deleted.

Ivan Pepelnjak, CCIE#1354, is the chief technology advisor for NIL Data Communications. He has been designing and implementing large-scale data communications networks as well as teaching and writing books about advanced technologies since 1990. See his full profile, contact him or follow @ioshints on Twitter.