Support Central: KB #82: NIOS NTP Out of Synchronization Error

[#1]

 

Each week we're sharing a support KB article to help you with trending topics & support questions.

Problem Summary

Grid Members show a red status of "NTP out of synchronization". 

Customer Environment

NIOS Grid configured to sync time with External NTP servers or with the Grid Master.

Version

NIOS 6.x and later versions.

Causes

Cause for Grid member (Non HA):

When you see a status of "NTP out of synchronization" or you receive out-of-synchronization alerts for a Grid Member, these messages can be generally associated with one of two events:

• The Grid Member is going out-of-sync with its NTP source OR
• The Grid Member is disconnecting and reconnecting to the grid.

Cause for Grid Master (Non HA):

If you see a status of "NTP out of synchronization" or you receive out-of-synchronization alerts for a Grid Master, the Grid Master may be going out-of-sync with its NTP source or a communication issue with an external NTP server. Please note that, this is normal during an upgrade because the Grid Master will lose connection to the NTP source when rebooting. Once the Grid Master is up and running after the reboot, NTP should automatically synchronize.

Cause for Grid Master / Member (HA Pair):

A Grid Master and/or a Grid Member which are configured as an HA pair may show NTP out-of-sync if one of the nodes goes out-of-sync with the NTP source under the following conditions:

• If the Active node is out-of-sync, this could mean that it lost connection with either the Grid Master or the external NTP source
• If the Passive node of the HA pair showing NTP out-of-sync, this may occur if the Active node of the HA pair is having issues with syncing time with the Grid Master or the configured external source

Resolution

If you have configured Grid Master or Member to use external the NTP server for the first time, it may take some time to adjust the clock and to sync with the external NTP server. The length of time depends on the time difference between the external server and the local clock. To learn how the NTP Offset is adjusted in NIOS, see KB 1436.

In both cases you can use the CLI to gather additional information to understand what is going on.

First, identify the node with which the Grid Member or Grid Master is synchronizing NTP. You can run "show ntp" from the CLI to get an output similar to this:

Infoblox > show ntp

remote refid st t when poll reach delay offset jitter

===============================================================

*LOCAL(1) LOCAL(1) 12 l 52 64 377 0.000 0.000 0.008

Infoblox >

In the above example, the Grid Master is not configured to use an external source and is synchronizing with itself. The asterisk next to the name shows who it is synchronizing. If the Grid Master/Member was configured for an external source, you would see additional lines indication the NTP sources. For example, on a Grid Member, you would typically see the below when its syncing time with the Grid Master or the Active node if configured as HA pair. 169.254.x.x address is basically a Grid VPN address:

Infoblox > show ntp

remote refid st t when poll reach delay offset jitter

=============================================================

*169.254.0.1 192.168.1.2 2 u 18 64 377 1.216 0.938 0.625

LOCAL(1) LOCAL(1) 12 l 52 64 377 0.000 0.000 0.008

The following example shows a sample output of an appliance that is syncing time with an external NTP source:

Infoblox > show ntp

remote refid st t when poll reach delay offset jitter

==============================================================================

*129.6.15.28 .ACTS. 1 u 13 64 377 100.770 48920.8 67.505

127.127.1.1 .LOCL. 12 l 19 64 377 0.000 0.000 0.000

Infoblox >

Sample logs during an NTP syncs to the local clock

2013-04-16T20:11:37+03:00 daemon (none) ntpd[5244]: info system event 'event_peer/strat_chg' (0x04) status 'leap_none, sync_local_proto, 5 events, event_peer/strat_chg' (0x554)

2013-04-16T20:11:37+03:00 daemon (none) ntpd[5244]: info synchronized to LOCAL(1), stratum 14

Sample logs during NTP startup and NTP are out of sync

2013-06-29T18:36:21+03:00 daemon (none) ntpd[5244]: debug new interface(s) found: waking up resolver

2013-06-29T18:36:24+03:00 daemon (none) ntpd[5244]: info Listening on interface #10 eth2, fe80::200:5eff:fe00:164#123 Enabled

2013-06-29T18:36:24+03:00 daemon (none) ntpd[5244]: debug new interface(s) found: waking up resolver

2013-06-29T18:36:48+03:00 daemon (none) ntpd[5244]: info Listening on interface #11 tun1, 169.254.0.1#123 Enabled

2013-06-29T18:36:48+03:00 daemon (none) ntpd[5244]: debug new interface(s) found: waking up resolver

2013-06-29T18:36:48+03:00 daemon (none) ntpd[5244]: notice ntpd exiting on signal 15

2013-06-29T18:36:56+03:00 daemon (none) ntpdate[11000]: err no server suitable for synchronization found

Sample logs during an NTP configuration change

[2013/06/05 14:18:31.872] (31554 /infoblox/one/bin/check_ntp_conf) : Restarting ntpd due to conf file differences below:

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : -server time.nist.gov iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : -server ntp0.cornell.edu iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : -server ntp-1.cede.psu.edu iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +server navobs1.oar.net iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +server tock.usno.navy.mil iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +server gnomon.cc.columbia.edu iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +server tick.gatech.edu iburst minpoll 6 maxpoll 8

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : -restrict time.nist.gov noquery

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : -restrict ntp0.cornell.edu noquery

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : -restrict ntp-1.cede.psu.edu noquery

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +restrict navobs1.oar.net noquery

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +restrict tock.usno.navy.mil noquery

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +restrict gnomon.cc.columbia.edu noquery

[2013/06/05 14:18:31.881] (31554 /infoblox/one/bin/check_ntp_conf) : +restrict tick.gatech.edu noquery

[2013/06/05 14:18:31.921] (31573 /infoblox/one/bin/set_ntp_time) main.c:452 snt_process(): Starting ntp on the grid master when ntp is enabled

[2013/06/05 14:18:39.435] (31573 /infoblox/one/bin/set_ntp_time) util.c:2397 one_get_time_offset(): Offset between ntp server, navobs1.oar.net tock.usno.navy.mil gnomon.cc.columbia.edu tick.ga

tech.edu, and me = -0.026432

[2013/06/05 14:18:39.435] (31573 /infoblox/one/bin/set_ntp_time) main.c:418 snt_set_ntp_time(): Offset is less than 300 secs

[2013/06/05 14:18:39.435] (31573 /infoblox/one/bin/set_ntp_time) main.c:419 snt_set_ntp_time(): Starting ntpd

Sample logs during an NTP time slew

2011-04-12T18:21:31-04:00 daemon (none) ntpdate[30866]: notice step time server 10.2.168.4 offset -1000.286508 sec ....

2012-06-11T09:29:50-04:00 daemon (none) ntpd[3256]: notice time slew -999.144755 s

2012-06-11T09:30:54-04:00 daemon (none) ntpd[3256]: notice time slew -999.385354 s

2012-06-11T09:32:00-04:00 daemon (none) ntpd[3256]: notice time slew -999.542901 s

2012-06-11T09:34:06-04:00 daemon (none) ntpd[3256]: err time correction of -1000 seconds exceeds sanity limit (1000); set clock manually to the correct UTC time.

2012-06-11T09:34:28-04:00 user (none) monitor[2537]: alert Type: NTP Synchronization, State: Red, Event: The NTP service is out of synchronization.

Sample logs during a normal NTP sync

[2013/08/17 21:34:09.355] (4785 /infoblox/one/bin/set_ntp_time) main.c:419 snt_set_ntp_time(): Starting ntpd

2013-08-17T21:34:09+02:00 daemon (none) ntpdate[4834]: notice step time server 10.110.0.130 offset -14.860211 sec

2013-08-17T21:34:09+02:00 daemon (none) ntpd[5300]: notice ntpd 4.2.4p8@1.1612-o Thu Feb 14 03:40:56 UTC 2013 (1)

2013-08-17T21:34:09+02:00 daemon (none) ntpd[5325]: info precision = 0.102 usec

2013-08-17T21:34:09+02:00 daemon (none) ntpd[5325]: debug ntp_io: estimated max descriptors: 1024, initial socket boundary: 16

2013-08-17T21:34:09+02:00 daemon (none) ntpd[5325]: info kernel time sync status 2040

2013-08-17T21:34:09+02:00 daemon (none) ntpd[5325]: info frequency initialized 63.982 PPM from /storage/etc/ntp.drift

2013-08-17T21:34:09+02:00 daemon (none) ntpd[5325]: info frequency initialized 63.982 PPM from /storage/etc/ntp.drift

2013-08-17T21:34:34+02:00 user (none) monitor[5597]: alert Type: NTP Synchronization, State: Green, Event: The NTP service resumed synchronization.