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.