Bug 113610

Summary: Time in logfile messages in UTC for linux kernel entry
Product: [openSUSE] SUSE LINUX 10.0 Reporter: Ulrich Lange <email>
Component: InstallationAssignee: Jiří Suchomel <jsuchome>
Status: RESOLVED FIXED QA Contact: E-mail List <qa-bugs>
Severity: Minor    
Priority: P5 - None    
Version: Beta 3   
Target Milestone: ---   
Hardware: HP   
OS: All   
Whiteboard:
Found By: Other Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: /var/log/messages

Description Ulrich Lange 2005-08-28 09:02:38 UTC
Each Linux kernel entry has a UTC time, other entries are in localtime.
Comment 1 Ulrich Lange 2005-08-28 09:03:18 UTC
Created attachment 47882 [details]
/var/log/messages
Comment 2 Olaf Kirch 2005-08-29 09:11:40 UTC
All timestamps in the system log are generated by syslogd, not the kernel 
itself. So it's a syslogd problem I assume. 
Comment 3 Marius Tomaschewski 2005-08-29 12:12:32 UTC
Yes.
Timestamps for kernel messages are generated by klogd (not by syslog*):

7020  write(1, "<6>Aug 29 13:33:52 kernel: subfs"..., 37) = 37
7020  time([1125315232])                = 1125315232
7020  write(1, "<6>Aug 29 13:33:52 kernel: klogd"..., 76) = 76
7020  read(0, "<7>ISO 9660 Extensions: Microsof"..., 262143) = 49
7020  time([1125315232])                = 1125315232
7020  write(1, "<7>Aug 29 13:33:52 kernel: ISO 9"..., 73) = 73
7020  read(0, "<7>ISO 9660 Extensions: RRIP_199"..., 262143) = 35
7020  time([1125315232])                = 1125315232
7020  write(1, "<7>Aug 29 13:33:52 kernel: ISO 9"..., 59) = 59
7020  read(0, "<6>xen-br0: port 2(peth0) enteri"..., 262143) = 50
7020  time([1125315250])                = 1125315250
7020  write(1, "<6>Aug 29 13:34:10 kernel: xen-b"..., 74) = 74
7020  read(0, "<6>device peth0 left promiscuous"..., 262143) = 88
7020  time([1125315250])                = 1125315250
7020  write(1, "<6>Aug 29 13:34:10 kernel: devic"..., 62) = 62
7020  time([1125315250])                = 1125315250
7020  write(1, "<6>Aug 29 13:34:10 kernel: xen-b"..., 74) = 74
7020  read(0, "<6>ACPI: PCI interrupt for devic"..., 262143) = 56
7020  time([1125315250])                = 1125315250
7020  write(1, "<6>Aug 29 13:34:10 kernel: ACPI:"..., 80) = 80

There is a difference of 12 hours. Is your local time in "M" or "Y"
timezone (+/- 12 hours) ?

Aug 28 05:58:23 linux kernel: ISO 9660 Extensions: RRIP_1991A
Aug 28 05:58:52 linux kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
Aug 28 05:58:52 linux kernel: ISO 9660 Extensions: RRIP_1991A
Aug 28 17:59:47 linux shadow[5945]: group already exists - group=ntadmin, by=0
Aug 28 18:00:43 linux shadow[5980]: group is unknown - group=wwwadmin, by=0
Aug 28 18:00:43 linux shadow[5981]: default group changed - account=wwwrun, uid=
Aug 28 18:00:43 linux shadow[5982]: shell changed - account=wwwrun, uid=30, shel
Aug 28 06:03:02 linux kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
Aug 28 06:03:02 linux kernel: ISO 9660 Extensions: RRIP_1991A
Aug 28 06:03:26 linux kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
Aug 28 06:03:26 linux kernel: ISO 9660 Extensions: RRIP_1991A

I've installed Beta3 today and there is still some bug in YaST2 clock setting
pages. The clock in YaST displayed "localtime +2" with TZ setting as localtime
(it seems YaST assumed, that the hwclock is set to UTC).
The clock on this PC is set to localtime, not UTC, because of WinXP installed
there.
Switching the TZ combo box to UTC and back displayed the correct local time.

It SEEMS, yast2 restarts only syslogd/-ng (manually, instead via init script)
and forgets to restart klogd as well, after it has changed the TZ settings.
Or something like this...
As result, the klogd runs with old TZ settings and syslogd/-ng with new...

I would say, there is nothing we can fix in syslog packages.
YaST seems to need a fix.
Comment 4 Dr. Werner Fink 2005-08-29 12:47:37 UTC
This has nothing todo with syslogd nor with klogd.
Comment 5 Ulrich Lange 2005-08-30 01:55:54 UTC
My HW-Clock is set to the localtime.
Region: Pacific
Time Zone: New Zealand
Hardware Clock set to: Local Time

After several cold starts the time of all entries in logfile are always
localtime. It seems to be only a problem in the installing procedure.
Comment 6 Jiří Suchomel 2005-08-30 09:52:06 UTC
The clock detecting/setting problem mentioned by Marius should be fixed in beta4.

However, after setting the time, YaST does not restart neither syslogd nor
klogd. It only sets the time using hwclock. I don't know if hwclock itself
restarts logging services - does anyonw know?
Comment 7 Marius Tomaschewski 2005-08-30 12:56:27 UTC
No, hwclock does only sets the date.

I've tested a little bit with syslog-ng. There is no need to restart it
neither on timezone nor on time/date changes, since the glibc functions
reads the /etc/localtime every time:

root@Xanthos:~ # logger "======= " $(date) " ============" ; date
Di Aug 30 14:29:52 CEST 2005
root@Xanthos:~ # date 08301230 #MMDDhhmm
Di Aug 30 12:30:00 CEST 2005
root@Xanthos:~ # logger "======= " $(date) " ============" ; date
Di Aug 30 12:30:06 CEST 2005
root@Xanthos:~ # cp -a /usr/share/zoneinfo/UTC /etc/localtime 
root@Xanthos:~ # date
Di Aug 30 10:32:12 UTC 2005
root@Xanthos:~ # logger "======= " $(date) " ============"
root@Xanthos:~ # cp -a /usr/share/zoneinfo/Europe/Berlin /etc/localtime 
root@Xanthos:~ # logger "======= " $(date) " ============"
root@Xanthos:~ # date
Di Aug 30 12:33:05 CEST 2005
root@Xanthos:~ # rcntp restart
Shutting down network time protocol daemon (NTPD)                    done
Try to get initial date and time via NTP from  192.168.110.200 192.16done0.254
Starting network time protocol daemon (NTPD)                         done
root@Xanthos:~ # date
Di Aug 30 14:34:34 CEST 2005
root@Xanthos:~ # logger "======= " $(date) " ============"

Aug 30 14:29:52 Xanthos root: =======  Di Aug 30 14:29:52 CEST 2005  ===========
Aug 30 14:29:57 Xanthos sshd[5710]: Accepted publickey for root from 127.0.0.2 p
Aug 30 12:30:06 Xanthos root: =======  Di Aug 30 12:30:06 CEST 2005  ===========
Aug 30 10:32:18 Xanthos root: =======  Di Aug 30 10:32:18 UTC 2005  ============
Aug 30 12:33:02 Xanthos root: =======  Di Aug 30 12:33:02 CEST 2005  ===========
Aug 30 14:34:23 Xanthos ntpdate[5851]: step time server 192.168.110.200 offset 7
Aug 30 14:34:23 Xanthos ntpd[5856]: ntpd 4.2.0a@1.1191-r Fri Aug 19 22:07:11 UTC
Aug 30 14:34:23 Xanthos ntpd[5856]: precision = 1.000 usec
Aug 30 14:34:23 Xanthos ntpd[5856]: Listening on interface wildcard, 0.0.0.0#123
Aug 30 14:34:23 Xanthos ntpd[5856]: Listening on interface wildcard, ::#123
Aug 30 14:34:23 Xanthos ntpd[5856]: Listening on interface lo, 127.0.0.1#123
Aug 30 14:34:23 Xanthos ntpd[5856]: Listening on interface eth0, 192.168.110.1#1
Aug 30 14:34:23 Xanthos ntpd[5856]: kernel time sync status 0040
Aug 30 14:34:38 Xanthos root: =======  Di Aug 30 14:34:38 CEST 2005  ===========

As far as I can see, klogd uses a time(&now), ctime(&now) combination what
should be also OK.

Hmm.. is there some chroot used and the log forwarded between chroot and
the system?
A chroot would explain it: this will happen if the /etc/localtime of the
system and $chroot/etc/localtime differs and one of the daemons runs in
a chroot...
Comment 8 Marius Tomaschewski 2005-08-30 13:00:54 UTC
(In reply to comment #5)
> It seems to be only a problem in the installing procedure.

Yes, in normal system this does not happen.
Comment 9 Jiří Suchomel 2005-08-30 13:56:41 UTC
So if I understand it correct, it should be fixed by the fix of the bug already
mentioned in comment #3 (... "it seems YaST assumed, that the hwclock is set to
UTC"...).