Puppy Linux Discussion Forum Forum Index Puppy Linux Discussion Forum
Puppy HOME page : puppylinux.com
"THE" alternative forum : puppylinux.info
 
 FAQFAQ   SearchSearch   MemberlistMemberlist   UsergroupsUsergroups   RegisterRegister 
 ProfileProfile   Log in to check your private messagesLog in to check your private messages   Log inLog in 

The time now is Sun 21 Dec 2014, 23:33
All times are UTC - 4
 Forum index » House Training » Users ( For the regulars )
Time weirdness, reported time is 31 hours into the future
Moderators: Flash, Ian, JohnMurga
Post_new_topic   Reply_to_topic View_previous_topic :: View_next_topic
Page 1 of 1 Posts_count  
Author Message
edwin.evans

Joined: 15 Nov 2012
Posts: 60

PostPosted: Sat 29 Dec 2012, 16:05    Post_subject:  Time weirdness, reported time is 31 hours into the future  

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).
Back to top
View user's profile Send_private_message 
jafadmin

Joined: 19 Mar 2009
Posts: 444

PostPosted: Sun 30 Dec 2012, 10:41    Post_subject:  

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.
Back to top
View user's profile Send_private_message 
edwin.evans

Joined: 15 Nov 2012
Posts: 60

PostPosted: Sun 30 Dec 2012, 12:20    Post_subject:  

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)?
Back to top
View user's profile Send_private_message 
jafadmin

Joined: 19 Mar 2009
Posts: 444

PostPosted: Tue 01 Jan 2013, 01:14    Post_subject:  

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.
Back to top
View user's profile Send_private_message 
edwin.evans

Joined: 15 Nov 2012
Posts: 60

PostPosted: Tue 01 Jan 2013, 18:14    Post_subject:  

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?
Back to top
View user's profile Send_private_message 
jafadmin

Joined: 19 Mar 2009
Posts: 444

PostPosted: Wed 02 Jan 2013, 01:34    Post_subject:  

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
Back to top
View user's profile Send_private_message 
npierce

Joined: 28 Dec 2009
Posts: 858

PostPosted: Fri 04 Jan 2013, 11:57    Post_subject:  

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:
# 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:
/etc/init.d/00sys_logger stop
/etc/init.d/00sys_logger start

Repeating my earlier bash session, both timestamps are now correct:
Code:
# 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:
#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.

Good luck.
Back to top
View user's profile Send_private_message 
edwin.evans

Joined: 15 Nov 2012
Posts: 60

PostPosted: Sat 05 Jan 2013, 17:08    Post_subject:  

Thank you so much!! (I haven't got a chance to try this yet but I will soon.)
Back to top
View user's profile Send_private_message 
npierce

Joined: 28 Dec 2009
Posts: 858

PostPosted: Tue 29 Jan 2013, 09:48    Post_subject:  

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.
Back to top
View user's profile Send_private_message 
edwin.evans

Joined: 15 Nov 2012
Posts: 60

PostPosted: Tue 29 Jan 2013, 15:21    Post_subject:  

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!
Back to top
View user's profile Send_private_message 
npierce

Joined: 28 Dec 2009
Posts: 858

PostPosted: Wed 30 Jan 2013, 10:13    Post_subject:  

Great! That's good to know. Thanks for the feedback.
Back to top
View user's profile Send_private_message 
Display_posts:   Sort by:   
Page 1 of 1 Posts_count  
Post_new_topic   Reply_to_topic View_previous_topic :: View_next_topic
 Forum index » House Training » Users ( For the regulars )
Jump to:  

Rules_post_cannot
Rules_reply_cannot
Rules_edit_cannot
Rules_delete_cannot
Rules_vote_cannot
You cannot attach files in this forum
You can download files in this forum


Powered by phpBB © 2001, 2005 phpBB Group
[ Time: 0.0945s ][ Queries: 12 (0.0209s) ][ GZIP on ]