Server Clock Stops Every Night

[Peter Awad]

I've been trying to work this out for a few days now.
I have a PowerEdge 2950 running FreeNAS 9.1.0
Every night ntpd dies after a sanity check failure and when I get to work there server time can be up to 12 hours behind.
I've turned off ntpd and set a cron job to ntpdate every 20 mintues. That runs fine until some time through the night when the cron job seems to stop and then restart 3 hours later and ntpdate makes a 3hr adjustment.
Next I was going to setup a cron job to restart the ntpd service every 30 mins to make sure it's alive but if the clock seems to "stop" it won't do any good as cron will never get to run.

Any ideas?

--NTPdate log file from last night--
Nov 17 21:00:02 freenas ntpdate[45732]: adjust time server 132.246.11.227 offset -0.000492 sec
Nov 18 08:47:38 freenas ntpdate[46236]: step time server 132.246.11.228 offset 41696.806021 sec
Nov 18 09:00:00 freenas ntpdate[46658]: adjust time server 132.246.11.228 offset -0.000945 sec
Nov 18 09:20:01 freenas ntpdate[47251]: adjust time server 132.246.11.227 offset -0.000763 sec
Nov 18 09:40:01 freenas ntpdate[47834]: adjust time server 132.246.11.227 offset -0.001039 sec
Nov 18 10:00:01 freenas ntpdate[48409]: adjust time server 132.246.11.229 offset -0.000657 sec
Nov 18 10:20:01 freenas ntpdate[48994]: adjust time server 132.246.11.229 offset -0.000699 sec
Nov 18 10:40:00 freenas ntpdate[49573]: adjust time server 132.246.11.228 offset -0.000593 sec
Nov 18 11:00:01 freenas ntpdate[50148]: adjust time server 132.246.11.228 offset -0.000884 sec
Nov 18 11:20:00 freenas ntpdate[50679]: adjust time server 132.246.11.228 offset -0.001051 sec
Nov 18 11:40:01 freenas ntpdate[51098]: adjust time server 132.246.11.227 offset -0.000178 sec
Nov 18 12:00:00 freenas ntpdate[51729]: adjust time server 132.246.11.227 offset -0.001549 sec
Nov 18 12:20:01 freenas ntpdate[52351]: adjust time server 132.246.11.227 offset -0.000209 sec
Nov 18 12:40:00 freenas ntpdate[52928]: adjust time server 132.246.11.229 offset -0.000992 sec
Nov 18 13:00:01 freenas ntpdate[53503]: adjust time server 132.246.11.227 offset -0.000637 sec
Nov 18 13:20:01 freenas ntpdate[54092]: adjust time server 132.246.11.228 offset -0.061566 sec
Nov 18 13:40:01 freenas ntpdate[54666]: adjust time server 132.246.11.228 offset 0.080336 sec
Nov 18 14:00:00 freenas ntpdate[55247]: adjust time server 132.246.11.229 offset -0.030711 sec
Nov 18 14:20:01 freenas ntpdate[55841]: adjust time server 132.246.11.227 offset 0.014344 sec
Nov 18 14:40:01 freenas ntpdate[56416]: adjust time server 132.246.11.229 offset -0.047715 sec
Nov 18 15:00:00 freenas ntpdate[56994]: adjust time server 132.246.11.229 offset 0.061587 sec
Nov 18 15:20:01 freenas ntpdate[57585]: adjust time server 132.246.11.229 offset -0.032293 sec
Nov 18 15:40:01 freenas ntpdate[58156]: adjust time server 132.246.11.228 offset 0.014924 sec
Nov 18 16:00:01 freenas ntpdate[58733]: adjust time server 132.246.11.229 offset -0.008164 sec
Nov 18 16:20:01 freenas ntpdate[59322]: adjust time server 132.246.11.227 offset 0.002154 sec
Nov 18 16:40:01 freenas ntpdate[59894]: adjust time server 132.246.11.228 offset -0.001895 sec
Nov 18 17:00:00 freenas ntpdate[60471]: adjust time server 132.246.11.229 offset -0.000281 sec
Nov 18 17:20:01 freenas ntpdate[61061]: adjust time server 132.246.11.229 offset -0.001065 sec
Nov 18 17:40:01 freenas ntpdate[61638]: adjust time server 132.246.11.228 offset -0.000291 sec
Nov 18 18:00:00 freenas ntpdate[62216]: adjust time server 132.246.11.227 offset -0.001120 sec
Nov 18 18:20:01 freenas ntpdate[62654]: adjust time server 132.246.11.228 offset -0.000623 sec
Nov 18 18:40:01 freenas ntpdate[63071]: adjust time server 132.246.11.227 offset -0.001316 sec
Nov 18 19:00:01 freenas ntpdate[63486]: adjust time server 132.246.11.229 offset 0.000158 sec
Nov 18 19:20:01 freenas ntpdate[63908]: adjust time server 132.246.11.227 offset -0.001722 sec
Nov 18 19:40:00 freenas ntpdate[64336]: adjust time server 132.246.11.228 offset -0.000581 sec
Nov 18 20:00:01 freenas ntpdate[64753]: adjust time server 132.246.11.229 offset -0.001024 sec
Nov 18 20:20:01 freenas ntpdate[65176]: adjust time server 132.246.11.228 offset -0.000254 sec
Nov 18 20:40:01 freenas ntpdate[65587]: adjust time server 132.246.11.227 offset -0.002323 sec
Nov 18 21:00:01 freenas ntpdate[65998]: adjust time server 132.246.11.229 offset -0.000596 sec
Nov 18 21:20:00 freenas ntpdate[66420]: adjust time server 132.246.11.227 offset 0.000504 sec
Nov 18 21:40:01 freenas ntpdate[66831]: adjust time server 132.246.11.228 offset -0.000506 sec
Nov 18 22:00:01 freenas ntpdate[67242]: adjust time server 132.246.11.229 offset -0.001323 sec
Nov 18 22:20:02 freenas ntpdate[67691]: adjust time server 132.246.11.228 offset -0.007837 sec
Nov 18 22:40:02 freenas ntpdate[68108]: adjust time server 132.246.11.227 offset 0.001901 sec
Nov 18 23:00:02 freenas ntpdate[68521]: adjust time server 132.246.11.229 offset -0.001933 sec
Nov 18 23:20:02 freenas ntpdate[68942]: adjust time server 132.246.11.228 offset 0.002142 sec
Nov 18 23:40:01 freenas ntpdate[69355]: adjust time server 132.246.11.229 offset -0.004121 sec
Nov 19 00:00:01 freenas ntpdate[69770]: adjust time server 132.246.11.229 offset 0.001488 sec
Nov 19 00:20:03 freenas ntpdate[70196]: adjust time server 132.246.11.227 offset -0.095641 sec
Nov 19 00:40:01 freenas ntpdate[70608]: adjust time server 132.246.11.227 offset 0.140211 sec
Nov 19 01:00:01 freenas ntpdate[71019]: adjust time server 132.246.11.228 offset -0.061536 sec
Nov 19 01:20:02 freenas ntpdate[71444]: adjust time server 132.246.11.227 offset 0.030958 sec
Nov 19 01:40:02 freenas ntpdate[71884]: adjust time server 132.246.11.228 offset -0.018401 sec
Nov 19 02:00:02 freenas ntpdate[72299]: adjust time server 132.246.11.228 offset 0.010591 sec
Nov 19 02:20:01 freenas ntpdate[72730]: adjust time server 132.246.11.229 offset -0.008240 sec
Nov 19 02:40:01 freenas ntpdate[73143]: adjust time server 132.246.11.228 offset 0.005102 sec
Nov 19 03:00:01 freenas ntpdate[73558]: adjust time server 132.246.11.227 offset -0.003199 sec
Nov 19 03:20:00 freenas ntpdate[74099]: adjust time server 132.246.11.229 offset -0.003434 sec
Nov 19 03:40:01 freenas ntpdate[75098]: adjust time server 132.246.11.229 offset 0.006663 sec
Nov 19 04:00:01 freenas ntpdate[75339]: adjust time server 132.246.11.227 offset 0.004363 sec
Nov 19 04:20:01 freenas ntpdate[75604]: adjust time server 132.246.11.228 offset -0.001418 sec
Nov 19 07:35:00 freenas ntpdate[75854]: step time server 132.246.11.227 offset 10499.194176 sec
Nov 19 07:40:01 freenas ntpdate[75923]: adjust time server 132.246.11.229 offset 0.002981 sec
Nov 19 08:00:01 freenas ntpdate[76181]: adjust time server 132.246.11.228 offset -0.010125 sec
Nov 19 08:20:01 freenas ntpdate[76462]: adjust time server 132.246.11.229 offset 0.011397 sec
Nov 19 08:40:01 freenas ntpdate[76719]: adjust time server 132.246.11.227 offset -0.007192 sec
Nov 19 09:00:01 freenas ntpdate[76979]: adjust time server 132.246.11.227 offset 0.003424 sec
Nov 19 09:20:01 freenas ntpdate[77787]: adjust time server 132.246.11.229 offset -0.003066 sec
--End Log--

 

[dlavigne]

Every night ntpd dies after a sanity check failure

Is there an associated log entry or error message when that happens?

 

[Peter Awad]

This is the only message
Nov 13 19:25:50 freenas ntpd[37501]: time correction of 29398 seconds exceeds sanity limit (1000); set clock manually to the correct UTC time.

Amount of correction varies between a couple of hours to as high as 8 hours.

 

[dlavigne]

Nov 13 19:25:50 freenas ntpd[37501]: time correction of 29398 seconds exceeds sanity limit (1000); set clock manually to the correct UTC time.

That makes sense and is expected ntp behavior. Any idea why the clock keeps shifting? e.g. is there a bios setting that is overriding it or a script that is changing the system time?

 

[Peter Awad]

Nothing running that should be effecting time. This is a basic NAS setup for a mixed network. No other PDCs or servers in the network.
I did find a post about a time problem that was fixed by defaulting the bios and resetting it. Haven't tried yet as I need time to do a full backup and take the server offline for an hour. Crazy busy right now.
Been trying to band-aid the problem till I can get the time, thus the cron job.

 

[dlavigne]

As a temporary measure, include "-g" in your cron job that restarts ntpd: http://linux.die.net/man/8/ntpd.

 

[Peter Awad]

Good idea, but the service already had the -g flag
root 5783 0.0 0.0 22212 3376 ?? Ss 9:18AM 0:00.00 /usr/sbin/ntpd -g -c /etc/ntp.conf -p /var/run/ntpd.pid

Any other ingenious thoughts?
I hope to try and get to the bios today as the next week for me is booked out of the office, and still to date the ntpdate cron job fails as often as ntpd. It's almost as though the server clock stops completely.
Last night the last ntpdate ran at 22:20 and when I got into the office this morning the server time said 22:32. I just ssh to the server and manually run the ntpdate command and everything keeps going as planned.

 

[DJ9]

Ever tried putting a new battery on the motherboard? (since the 2950 series was released in 2007)

Silly question, I know... but it's happened to me before.

 

[Peter Awad]

Done that.
Managed to get the backup done, wipe and reset the bios, as well as update to 9.1.1
Next we'll have to schedule an exorcism if this doesn't work.

 

[Peter Awad]

So far so good. Can't be certain which actually fixed it. Based on other posts my gut says the bios wipe and reset was the key.
Ran cron job every 20 mins to check if ntpd was alive and my logs look like this

Nov 22 07:00:00 freenas root: ntpd is still alive
Nov 22 07:20:00 freenas root: ntpd is still alive
Nov 22 07:40:00 freenas root: ntpd is still alive
Nov 22 08:00:00 freenas root: ntpd is still alive
Nov 22 08:20:00 freenas root: ntpd is still alive
Nov 22 08:40:01 freenas root: ntpd is still alive
Nov 22 09:00:00 freenas root: ntpd is still alive
Nov 22 09:20:00 freenas root: ntpd is still alive
Nov 22 09:40:00 freenas root: ntpd is still alive

 

[DJ9]

Glad to see you got it working Peter.
Exorcism cancelled. ;)