[ntp:questions] Netra X1 time warp

Roman Maeder maeder+news at mathconsult.ch
Sat Jan 24 22:44:27 UTC 2004


Netra X1, Solaris 8, Generic_108528-27 (64 bits) time problems

Around 04:00 MET, January 22, 2004, the system time of my Netra X1 web server 
(www.mathematica.ch) suddenly jumped back exactly 100 years into the past.
The same thing had happened before, on January 4. Here is all the evidence I 
could collect from log files and observations.


1. syslog

The log files show an apparent difference of one hour, but
the "date" command told me that the machine thought that at that time
in January 1904 it was daylight savings time, therefore the difference
of one hour. Normal time zone is MET, one hour ahead of GMT. Syslog
does not log years, so one has to look closely to see any problems.


2. ISC BIND 9

the name server started to emit assert failures, at a rate of several
per second, of the nature

Jan 22 04:58:15 www named[245]: [ID 873579 daemon.error] general: timer.c:407: 
unexpected error:
Jan 22 04:58:15 www named[245]: [ID 873579 daemon.error] general: 
isc_time_now() failed: unexpected error
Jan 22 04:58:15 www named[245]: [ID 873579 daemon.error] client: client 
127.0.0.1#60232: setting timeout: unexpected error
Jan 22 04:58:15 www named[245]: [ID 873579 daemon.error] general: 
resolver.c:2310: unexpected error:
Jan 22 04:58:15 www named[245]: [ID 873579 daemon.error] general: 
isc_time_nowplusinterval: unexpected error


3. ntpd

the machine runs ntpd (4.2.0, gcc 3.3.2), synchronizing to a local DCF
clock and several external sources. The ntp loopstats show

53026 10545.254 -0.001645081 24.395203 0.002312878 0.008095 6
53026 10611.248 -0.000174861 24.394536 0.002184543 0.007018 6
53026 29205.270 0.000000000 24.298000 0.000001907 0.000000 4
53026 29269.271 0.000000000 24.298000 0.000001907 0.000000 6

( the time 29205 was after I rebooted the machine). So ntpd was sleeping 
during the time the clock was in the past.

similar picture with the peerstats:

53026 10638.728 194.42.48.120 b394 -0.005090503 0.013437269 0.003051554 
0.010387413
53026 10647.725 62.65.128.33 b494 -0.000153512 0.012491237 0.001427164 0.000305911
53026 29010.265 127.127.1.0 9014 0.000000000 0.000000000 0.000030000 0.000001907
53026 29076.267 127.127.1.0 9014 0.000000000 0.000000000 0.000990000 0.000001907

Another Netra X1, which synchronizes its time with this machine's ntp,
showed

22 Jan 04:32:57 ntpd[7610]: time correction of -1008276352 seconds exceeds
sanity limit (1000); set clock manually to the correct UTC time.
(which is about 36 years, maybe -100 mod 136 ?)


4. cron

I run a cron job that logs the machine's temperature (as reported by
"lom -t") every 10 minutes. Here's the relevant excerpt from the log

2004.01.22T03:50:00 12439.1181 27
1904.01.22T05:00:00 -24085.8750 27

first column is formatted result of "date" command (local time),
second column is number of days since epoch, the value of perl's date()
divided by 86400, the amount is -65.9435 years, or January 22, 1904 (GMT).


5. other evidence

no other service reported any errors, Apache continued normally (but could
not resove IP addresses, because of the named problems). Mod times of files
touched during the period of wrong time showed 1904 time stamps.


Why would this happen, and not happen to the second Netra I have, configured
similary (as backup, test, and development system for the web server)?

Roman Maeder




More information about the questions mailing list