Time weirdness, reported time is 31 hours into the future

Using applications, configuring, problems
Post Reply
Message
Author
edwin.evans
Posts: 60
Joined: Thu 15 Nov 2012, 16:06

Time weirdness, reported time is 31 hours into the future

#1 Post by edwin.evans »

I have a log file that gets written out with timestamps. If I run "date" or "hwclock" command it reports the correct time and when I start my program, the logging shows the correct time but then at some point in the future it switches to 31 hours into the future although date/hwclock is still reporting the correct time. Any idea what could be going on?

I'm using NLog/Mono for the logging and Puppy 5.0 (and can't upgrade).

jafadmin
Posts: 1249
Joined: Thu 19 Mar 2009, 15:10

#2 Post by jafadmin »

go to: Menu->Setup->Setup Puppy->Personalize-Settings

Make sure your time zone is set correctly and you are not using UTC hardware clock.

Now make sure your clock is set to the correct date and time.

edwin.evans
Posts: 60
Joined: Thu 15 Nov 2012, 16:06

#3 Post by edwin.evans »

jafadmin wrote:go to: Menu->Setup->Setup Puppy->Personalize-Settings

Make sure your time zone is set correctly and you are not using UTC hardware clock.

Now make sure your clock is set to the correct date and time.
I set my time zone to Los Angeles, then updated my system time and then syched my hardware clock to it. I'm not sure if my hardware clock is using UTC time but I only did hwclock --synctosys. Then I start my logging. At this point everything looks correct (date, hwclock, time displayed at bottom right, log timestamp). But at some time later the log timestamp changes to 31 hours in the future. It is always 31 hours in future. Los Angeles is currently 8 hours behind UTC. How do I check if my hwclock is using UTC (but even still I don't see how it could be more than 24 hours off)?

jafadmin
Posts: 1249
Joined: Thu 19 Mar 2009, 15:10

#4 Post by jafadmin »

LA is currently UTC -7 due to Daylight Saving Time. 24 + 7 = 31

Your HW clock shouldn't care about the TZ. Just open a terminal window and type "Date" (without quotes) and press <Enter>

If it doesn't show the correct date/time/TZ, reset accordingly.

It sounds like somewhere the system is still being told to use UTC.

edwin.evans
Posts: 60
Joined: Thu 15 Nov 2012, 16:06

#5 Post by edwin.evans »

jafadmin wrote:LA is currently UTC -7 due to Daylight Saving Time. 24 + 7 = 31

Your HW clock shouldn't care about the TZ. Just open a terminal window and type "Date" (without quotes) and press <Enter>

If it doesn't show the correct date/time/TZ, reset accordingly.

It sounds like somewhere the system is still being told to use UTC.
DST doesn't start until March for LA. If I type "date" I get the correct time:

Tue Jan 1 14:12:53 GMT+8 2013.

This is the correct local time (+8 instead of -8 since that Linux does offsets backwards) so I don't see why it would be off by 31 hours. In any case, any suggestion for how to fix?

jafadmin
Posts: 1249
Joined: Thu 19 Mar 2009, 15:10

#6 Post by jafadmin »

When I run the date command I get:

sh-4.1# date
Tue Jan 1 21:31:08 PST 2013
sh-4.1#

Try setting your time zone to PST instead of GMT +8:00

FYI, PST= GMT-8:00

npierce
Posts: 858
Joined: Tue 29 Dec 2009, 01:40

#7 Post by npierce »

I am unfamiliar with NLog and Mono, but this sounds like the same problem that is exhibited by klogd and syslogd in Racy 5.2.2 (and likely other Puppies of the past few years).

On March 18, 2010, Barry added code to the init script in the initrd to set the TZ environmental variable to "XXX-23", just before the system clock is set.

"XXX-23" is a fictitious timezone which is 23 hours ahead of UTC.

Later, after control passes to /etc/rc.d/rc.sysinit, the busybox syslogd and busybox klogd daemons are started. Later still, /etc/localtime is symlinked to the appropriate zoneinfo file for your local timezone. (The /etc/localtime symlink is normally used these days instead of the TZ environmental variable.)

Because busybox syslogd and busybox klogd were started when TZ was "XXX-23", they are under the mistaken belief that that is the correct timezone. (From now on, I'll just refer to the daemons as "syslogd" and "klogd", since they are symlinked to those names.) Therefore klogd will pass kernel messages to syslogd with a timestamp that is 23 hours ahead of UTC. Now, if you've done the math, you will have noticed that if you add the time that klog believes it is ahead of UTC to the time that your timezone is behind UTC, you get 23 + 8 = 31.

Taking a look at /var/log/messages, it will be noted that the first entries have timestamps that are consistent with your hardware clock (local time if your hardware clock is set to local time, or UTC if it is set to UTC). (There may be over a thousand of these messages, happening all within a few seconds.) Then suddenly the next messages jump into the future. That happens after your correct local time is set.

Adding to the confusion is the fact that you may sometimes see messages with correct timestamps interspersed with those with the bad timestamps -- time seems to keep jumping backward and forward.

The reason for that is that syslogd may sometimes get messages from programs that pass a correct timestamp. I think the way it works is that if syslogd is passed a good timestamp, it will log the good timestamp, if passed a bad timestamp it will log the bad timestamp, if passed no timestamp it will create and log its own -- which in this case will be bad since syslogd thinks it is in the "XXX-23" timezone.

For instance, 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 Jan  4 15:27:25 UTC 2013
# logger "Test message via logger."
# echo "Test message via klogd." > /dev/kmsg
# tail -n 2 /var/log/messages
Jan  4 15:27:43 puppypc4820 user.notice root: Test message via logger.
Jan  5 14:27:59 puppypc4820 user.warn kernel: [47749.533263] Test message via klogd.
# date
Fri Jan  4 15:28:19 UTC 2013
# 
The quickest way to fix things is to simply restart the daemons after your local time is properly set, which can easily be done with these two commands:

Code: Select all

/etc/init.d/00sys_logger stop
/etc/init.d/00sys_logger start
Repeating my earlier bash session, both timestamps are now correct:

Code: Select all

# date
Fri Jan  4 15:31:11 UTC 2013
# logger "Test message via logger."
# echo "Test message via klogd." > /dev/kmsg
# tail -n 2 /var/log/messages
Jan  4 15:31:18 puppypc4820 user.notice root: Test message via logger.
Jan  4 15:31:24 puppypc4820 user.warn kernel: [47954.723102] Test message via klogd.
# date
Fri Jan  4 15:31:37 UTC 2013
# 
As I said, I am unfamiliar with Nlog and Mono, so I don't know exactly what's happening in your case, but here are a couple of possibilities (there could certainly be others):

1: Nlog is passing messages to syslogd without timestamps, so syslogd creates its own bad timestamp. (This could be fixed by restarting syslogd.)

2: Nlog or Mono is being started before your local time is set, so one of them is creating its own bad timestamps. (This could be fixed by restarting Nlog or Mono.)

If restarting syslogd and klogd (or Nlog or Mono) solves your problem, you may be able to avoid doing that after every reboot by modifying one line in /etc/rc.d/rc.sysinit:

Code: Select all

#unset TZ #100319 busybox hwclock gives priority to this (rather than /etc/localtime) and 'init' has set it wrong.
Remove the hash character at the beginning of the line so that it reads:

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 other side-effects.

While I don't know about all programs, C programs using the usual GNU C library on Linux that use the standard C time functions will use TZ if it exists, and the current value of /etc/localtime if not (or /usr/local/etc/localtime if so configured -- but I know of no Puppies like that). So if TZ exists, the program sticks with that timezone for its duration, but if not the timezone used by the program will change with /etc/localtime. This means that if you unset TZ before starting the logging daemons, then after your local time gets set properly they will use that.

Good luck.

edwin.evans
Posts: 60
Joined: Thu 15 Nov 2012, 16:06

#8 Post by edwin.evans »

Thank you so much!! (I haven't got a chance to try this yet but I will soon.)

npierce
Posts: 858
Joined: Tue 29 Dec 2009, 01:40

#9 Post by npierce »

You're welcome.

Did this solve your problem?

Your feedback would help us find the best solution to prevent this or similar problems in future Puppies.

edwin.evans
Posts: 60
Joined: Thu 15 Nov 2012, 16:06

#10 Post by edwin.evans »

npierce wrote:You're welcome.

Did this solve your problem?

Your feedback would help us find the best solution to prevent this or similar problems in future Puppies.
Sorry for the slow reply. (I wasn't able to get back to this for a while and then still seeing issue related to my nlog filenames but I think that is an nlog config issue.)

Yes, this solved my problem! Thank you!

npierce
Posts: 858
Joined: Tue 29 Dec 2009, 01:40

#11 Post by npierce »

Great! That's good to know. Thanks for the feedback.

Maurizio4Puppy
Posts: 12
Joined: Mon 24 Oct 2016, 13:00

#12 Post by Maurizio4Puppy »

This bug is still present in Slacko64 6.3.2.

I have solved this issue adding the line

Code: Select all

[ -e /etc/localtime ] && export TZ=$(readlink /etc/localtime|sed -e 's,/usr/share/zoneinfo/,,' -e 's,Etc/,,')
in /etc/rc.d/rc.sysinit:

Code: Select all

# diff -u rc.sysinit.orig rc.sysinit
--- rc.sysinit.orig	2016-06-21 02:04:58.000000000 +0200
+++ rc.sysinit	2017-01-07 20:36:24.796083211 +0100
@@ -204,6 +204,8 @@
 #redirect all output to a log file (must do after remount rw)...
 [ ! "$LOGLEVEL" ] && exec 1>/tmp/bootsysinit.log 2>&1
 
+[ -e /etc/localtime ] && export TZ=$(readlink /etc/localtime|sed -e 's,/usr/share/zoneinfo/,,' -e 's,Etc/,,')
+
 mkdir -p /dev/pts #120503 if kernel mounts a f.s. on /dev, removes my skeleton /dev
 busybox mount -o dev,suid /dev/pts ;STATUS=$((STATUS+$?))
 mkdir /sys 2>/dev/null
Regards,
Maurizio

Post Reply