Sunday, February 1, 2009

NTP - How long is too long?

This is how long I waited for NTP to sync today:

R2(config)#ntp server 136.10.4.4
R2(config)#^Z
Feb 1 19:26:53.915: %SYS-5-CONFIG_I: Configured from console by console

Feb 1 19:37:11.852: NTP Core(NOTICE): Clock is synchronized.


More than 10 minutes. It should be noted that the clocks were only seconds apart to begin with. Code on these routers is 12.4(22)T. I don't know if I have ever waited so long but it's unbelievably ridiculous.

Then I enable authentication:

R4(config)#ntp authentication-key 1 md5 ipexpert

R2(config)#ntp authentication-key 1 md5 ipexpert
R2(config)#ntp trusted-key 1
R2(config)#ntp authenticate
R2(config)#ntp server 136.10.4.4 key 1

Feb 1 19:45:02.628: NTP Core(INFO): key (1) added.
Feb 1 19:45:02.752: NTP Core(INFO): key (1) marked as trusted.
Feb 1 19:45:03.276: NTP Core(INFO): system event 'event_clock_reset' (0x05) status 'sync_alarm, sync_unspec, 10 events, event_peer/strat_chg' (0xC0A4)
Feb 1 19:45:03.276: NTP Core(NOTICE): Clock synchronization lost.


Peers never come up, I get this every so often (debug ntp all):

.Feb 1 19:45:47.852: NTP message sent to 136.10.4.4, from interface 'Loopback0' (136.10.2.2).
.Feb 1 19:45:47.852: NTP message received from 136.10.4.4 on interface 'Loopback0' (136.10.2.2).
.Feb 1 19:45:47.852: NTP Core(DEBUG): ntp_receive: message received
.Feb 1 19:45:47.852: NTP Core(DEBUG): ntp_receive: peer is 0x674B9DF8, next action is 1.
.Feb 1 19:45:47.852: NTP Core(NOTICE): ntp_receive: dropping message: crypto-NAK.

.Feb 1 19:50:52.852: NTP message sent to 136.10.4.4, from interface 'Loopback0' (136.10.2.2).
.Feb 1 19:50:52.852: NTP message received from 136.10.4.4 on interface 'Loopback0' (136.10.2.2).
.Feb 1 19:50:52.852: NTP Core(DEBUG): ntp_receive: message received
.Feb 1 19:50:52.852: NTP Core(DEBUG): ntp_receive: peer is 0x674B9DF8, next action is 1.
.Feb 1 19:50:52.852: NTP Core(NOTICE): ntp_receive: dropping message: crypto-NAK.


Here we are still

.Feb 1 19:58:19.851: NTP message sent to 136.10.4.4, from interface 'Loopback0' (136.10.2.2).
.Feb 1 19:58:19.851: NTP message received from 136.10.4.4 on interface 'Loopback0' (136.10.2.2).
.Feb 1 19:58:19.851: NTP Core(DEBUG): ntp_receive: message received
.Feb 1 19:58:19.851: NTP Core(DEBUG): ntp_receive: peer is 0x674B9DF8, next action is 1.
.Feb 1 19:58:19.851: NTP Core(NOTICE): ntp_receive: dropping message: crypto-NAK
.

So, for kicks on the master I do this:

R4(config)#ntp authenticate
R4(config)#ntp trusted-key 1


I now get a new message on R2:

.Feb 1 20:01:20.851: NTP message sent to 136.10.4.4, from interface 'Loopback0' (136.10.2.2).
.Feb 1 20:01:20.851: NTP message received from 136.10.4.4 on interface 'Loopback0' (136.10.2.2).
.Feb 1 20:01:20.851: NTP Core(DEBUG): ntp_receive: message received
.Feb 1 20:01:20.851: NTP Core(DEBUG): ntp_receive: peer is 0x674B9DF8, next action is 1.
.Feb 1 20:01:20.851: NTP Core(DEBUG): receive: packet given to process_packet


This looks promising:

R2#
.Feb 1 20:03:30.851: NTP message sent to 136.10.4.4, from interface 'Loopback0' (136.10.2.2).
.Feb 1 20:03:30.851: NTP message received from 136.10.4.4 on interface 'Loopback0' (136.10.2.2).
.Feb 1 20:03:30.851: NTP Core(DEBUG): ntp_receive: message received
.Feb 1 20:03:30.851: NTP Core(DEBUG): ntp_receive: peer is 0x674B9DF8, next action is 1.
.Feb 1 20:03:30.851: NTP Core(DEBUG): receive: packet given to process_packet
.Feb 1 20:03:30.851: NTP Core(DEBUG): Peer becomes reachable, poll set to 6.
.Feb 1 20:03:30.851: NTP Core(INFO): peer 136.10.4.4 event 'event_reach' (0x84) status 'unreach, conf, auth, 1 event, event_reach' (0xE014)


TA-DA!

.Feb 1 20:06:43.851: NTP Core(NOTICE): Clock is synchronized.

I have never had to enable trusted-key on the master before. Watch this:

R4(config)#no ntp trusted-key 1

Back on R2:

R2#
Feb 1 20:07:47.851: NTP message sent to 136.10.4.4, from interface 'Loopback0' (136.10.2.2).
Feb 1 20:07:47.851: NTP message received from 136.10.4.4 on interface 'Loopback0' (136.10.2.2).
Feb 1 20:07:47.851: NTP Core(DEBUG): ntp_receive: message received
Feb 1 20:07:47.851: NTP Core(DEBUG): ntp_receive: peer is 0x674B9DF8, next action is 1.
Feb 1 20:07:47.851: NTP Core(INFO): system event 'event_clock_reset' (0x05) status 'sync_alarm, sync_unspec, 15 events, event_peer/strat_chg' (0xC0F4)
Feb 1 20:07:47.851: NTP Core(NOTICE): Clock synchronization lost.
.Feb 1 20:07:47.851: NTP Core(NOTICE): ntp_receive: dropping message: crypto-NAK.


Maybe something has changed in this T train but looks like we need "ntp trusted-key" on the Master now. I am not an NTP guru by any means but if you look at some of my other ntp blogs, you will see I didn't need this command. Note that I only needed "trusted-key" on the Master, not "ntp authenticate" even though I showed it above. Removing it did not cause sync loss. Something to keep in mind if you find yourself singing the NTP blues.

Oh, and while you are waiting for the sync - go configure something else in the meantime!

3 comments:

  1. Thanks!!! I had been struggling with this problem in my own lab for several days. I even tried changing the IOS version (I'm now running 12.4(24)T2 adv IP services), but still nothing worked.

    I must admit it never even crossed my mind to enable ntp trusted key on the server. And I still don't see the logic behind this...

    ReplyDelete
  2. Thanks for this post. Helped me figure out why it wasn't working for me.

    ReplyDelete
  3. 12.4(20)T and above went to NTPv4, which takes longer to synchronize and might affect the authentication (as in it actually attempts to authenticate the packet).

    ReplyDelete

Note: Only a member of this blog may post a comment.