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).

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)?

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.)

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:

#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:

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.

You cannot post new topics in this forumYou cannot reply to topics in this forumYou cannot edit your posts in this forumYou cannot delete your posts in this forumYou cannot vote in polls in this forumYou cannot attach files in this forumYou can download files in this forum