When examining /var/log/messages, one will notice that many messages seem to be coming from some time in the future. If one is not aware of this, it can be very confusing while trying to troubleshoot problems. Even if one
is aware of it, it is confusing since not
all messages arrive via time warps, so one cannot simply subtract a constant offset to determine the actual time that any given message arrived. It is as if time keeps jumping backward and forward.
(Although I don't have Precise Puppy, this behavior has existed in recent Puppies, and looking at the appropriate scripts in Woof, I see no reason to think that this has changed.)
Here is what is happening:
In order to prevent timestamps from the future from being written to a partition during e2fsck, in the init script in initrd, the TZ environment variable is set to a fictitious time zone 23 hours east of Greenwich ("TZ=XXX-23"). (See Barry's blog:
Timezone in the initrd (initramfs))
So if the hardware clock currently says 12:00 noon on Monday, Linux will assume it is 12:00 noon on Monday in that fictitious time zone when init executes "/bin/hwclock --hctosys --localtime", and sets the system clock to 13:00 UTC on Sunday.
This is good. It works as intended.
But the system clock will later be reset by /etc/rc.country based upon the user's actual timezone. If the user lives in London, the system clock will be reset to 12:00 noon UTC on Monday.
Now any process that still believes "TZ=XXX-23" will believe that the local time is 11:00 AM on Tuesday.
Because syslogd and klogd were started with "TZ=XXX-23" in their environment, they still think they are living in that fictitious time zone. So klogd will send log messages with timestamps based on local time in that timezone, which will be 23 hours ahead of UTC. Messages passed to syslogd will also be logged with a timestamp 23 hours ahead of UTC, unless the caller passes its own timestamp along with the message that it passes to syslogd.
The time offset will not always be 23 hours, but will vary depending upon the user's time zone. For instance, in the UTC+1 time zone the offset will be only 22 hours. In the UTC+8 time zone it will be 15 hours. But it can be as much as 35 hours -- that would be in the UTC-12 time zone (although that time zone mostly applies only to folks visiting a few uninhabited Pacific islands or in the radio room of a ship on the high seas just east of 180 degrees of longitude
).
Here is an example:
In the following excerpt from a bash session I run logger to send a message to syslogd; logger knows the correct timezone and so sends a good timestamp. Then I pass a message to /dev/kmsg, which klogd finds and sends on to syslogd; klogd still thinks the timezone is "XXX-23" so sends a bad timestamp. (I am using UTC for localtime.)
Code: Select all
# date
Fri Feb 22 13:49:26 UTC 2013
# logger "Test message via logger."
# echo "Test message via klogd." > /dev/kmsg
# tail -n 2 /var/log/messages
Feb 22 13:49:33 puppypc9902 user.notice root: Test message via logger.
Feb 23 12:49:43 puppypc9902 user.warn kernel: [771703.492205] Test message via klogd.
# date
Fri Feb 22 13:50:11 UTC 2013
#
The easiest way to fix it is probably to simply restore one line of code in /etc/rc.d/rc.sysinit that Barry added on 2010-Mar-19, but soon commented-out. This is the line:
Code: Select all
#unset TZ #100319 busybox hwclock gives priority to this (rather than /etc/localtime) and 'init' has set it wrong.
Then, after restoring:
Code: Select all
unset TZ #100319 busybox hwclock gives priority to this (rather than /etc/localtime) and 'init' has set it wrong.
I have not tried this, so this advice comes with no warranty, and I don't know if there might be any nasty side-effects. But I don't anticipate any, since all it does is allow processes started to use /etc/localtime, whatever that may be, or UTC if /etc/localtime doesn't exist, rather the the fictitious time zone.
Barry, I'm guessing that you commented-out that line since the time zone would soon be set in rc.country, based on the next comment in the code:
Code: Select all
#...comment-out for now. note, TZ now set in rc.country.
If I am assuming incorrectly, and unsetting TZ caused problems, a better fix will obviously be needed.
(One minor side-effect of this suggested fix would be that any messages logged by syslogd or klogd in the few seconds before the system clock is reset -- including any in the kmsg queue -- will have a wrong timestamp. As it stands now, if the hardware clock is set to local time, those timestamps will actually be right: since both the system clock and the time zone are wrong, the two wrongs cancel each other out. With the suggested fix, during those few seconds timestamps would seem to come from the past by varying amounts of time, again depending upon local time zone, or by exactly 23 hours on first boot when the /etc/localtime symlink does not yet exist. That's assuming hardware clock is on local time. If it is on UTC, timestamps would seem to come from exactly 23 hours in the past, or by varying amounts of time on first boot when the /etc/localtime symlink does not yet exist. But it seems preferable to have the timestamps correct for all the time between boot and shutdown than to have them correct during a small fraction of the boot process.)
Of course there are alternate solutions:
The syslogd and klogd daemons could be restarted
after rc.country sets the clock properly by running "00sys_logger stop" and 00sys_logger start".
Or setting the clock could be moved forward in the boot process so that it happens before those logging daemons are first started. But I don't know what complications might arise from doing that.
Here is an example of someone who ran into this timestamp problem. He reported that restoring the "unset TZ" line in rc.sysinit fixed it.
Time weirdness, reported time is 31 hours into the future
(His local time was UTC-8. 8 + 23 = 31.)
Here is
my response.
Another report: