Bug 689655 - rtkit messages in /var/log/messages (syslog?) display the wrong time
Summary: rtkit messages in /var/log/messages (syslog?) display the wrong time
Keywords:
Status: CLOSED DUPLICATE of bug 698040
Alias: None
Product: Fedora
Classification: Fedora
Component: rtkit
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Lennart Poettering
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-03-22 02:36 UTC by Tom London
Modified: 2011-04-28 02:19 UTC (History)
2 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2011-04-27 22:32:48 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
/var/log/messages (4.61 MB, text/plain)
2011-04-27 10:27 UTC, Steve Tyler
no flags Details

Description Tom London 2011-03-22 02:36:08 UTC
Description of problem:
I'm seeing syslog messages in /var/log/messages from rtkit that display the wrong time(zone?):

Mar 21 06:12:37 tlondon dbus: [system] Rejected send message, 2 matched rules; type="method_call", sender=":1.56" (uid=500 pid=1804 comm="/usr/libexec/gnome-settings-daemon ") interface="org.freedesktop.DBus.Properties" member="GetAll" error name="(unset)" requested_reply=0 destination=":1.23" (uid=0 pid=1462 comm="/usr/sbin/console-kit-daemon --no-daemon "))
Mar 21 06:12:37 tlondon setroubleshoot: SELinux is preventing /usr/bin/gnome-keyring-daemon from using the transition access on a process. For complete SELinux messages. run sealert -l 3db35756-bb61-4f6e-99f4-f20d34033daa
Mar 21 13:12:39 tlondon rtkit-daemon[858]: Successfully made thread 1868 of process 1868 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Mar 21 06:12:39 tlondon pulseaudio[1868]: pid.c: Daemon already running.
Mar 21 06:12:50 tlondon accounts-daemon[1681]: ** (accounts-daemon:1681): WARNING **: user root has 7 groups
Mar 21 06:12:50 tlondon pam: gdm-password[1690]: DEBUG(+): ActUserManager: user changed

This appears to happen for every rtkit message:

[root@tlondon ~]# tail -400 /var/log/messages | grep rtkit
Mar 21 13:12:36 tlondon rtkit-daemon[858]: Successfully made thread 1842 of process 1842 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Mar 21 13:12:36 tlondon rtkit-daemon[858]: Successfully made thread 1843 of process 1842 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Mar 21 13:12:37 tlondon rtkit-daemon[858]: Successfully made thread 1844 of process 1842 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Mar 21 13:12:39 tlondon rtkit-daemon[858]: Successfully made thread 1868 of process 1868 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
[root@tlondon ~]# 

Here is a bit of context for the last message:

Mar 21 06:12:37 tlondon dbus: [system] Rejected send message, 2 matched rules; type="method_call", sender=":1.56" (uid=500 pid=1804 comm="/usr/libexec/gnome-settings-daemon ") interface="org.freedesktop.DBus.Properties" member="GetAll" error name="(unset)" requested_reply=0 destination=":1.23" (uid=0 pid=1462 comm="/usr/sbin/console-kit-daemon --no-daemon "))
Mar 21 06:12:37 tlondon setroubleshoot: SELinux is preventing /usr/bin/gnome-keyring-daemon from using the transition access on a process. For complete SELinux messages. run sealert -l 3db35756-bb61-4f6e-99f4-f20d34033daa
Mar 21 13:12:39 tlondon rtkit-daemon[858]: Successfully made thread 1868 of process 1868 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Mar 21 06:12:39 tlondon pulseaudio[1868]: pid.c: Daemon already running.
Mar 21 06:12:50 tlondon accounts-daemon[1681]: ** (accounts-daemon:1681): WARNING **: user root has 7 groups
Mar 21 06:12:50 tlondon pam: gdm-password[1690]: DEBUG(+): ActUserManager: user changed
Mar 21 06:15:43 tlondon setroubleshoot: SELinux is preventing /usr/bin/sudo from sendto access on the unix_dgram_socket /dev/log. For complete SELinux messages. run sealert -l 00433895-dd2d-46b5-8a1f-c3efb808d262


Version-Release number of selected component (if applicable):
rtkit-0.10-1.fc16.x86_64
rsyslog-5.7.9-1.fc16.x86_64

How reproducible:
Appears so....

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 1 Lennart Poettering 2011-03-31 12:32:15 UTC
hmm, if you disable selinux during boot, does the timezone work correctly then?

Comment 2 Tom London 2011-03-31 13:44:17 UTC
Well, I've been booting permissively....

Here is a snippet from the latest boot:

Mar 31 06:32:45 tlondon pulseaudio[1788]: module.c: Failed to load  module "module-alsa-card" (argument: "device_id="29" name="platform-thinkpad_acpi" card_name="alsa_card.platform-thinkpad_acpi" tsched=yes ignore_dB=no card_properties="module-udev-detect.discovered=1""): initialization failed.
Mar 31 13:32:47 tlondon rtkit-daemon[843]: Successfully made thread 1811 of process 1811 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Mar 31 06:32:47 tlondon pulseaudio[1811]: pid.c: Daemon already running.
Mar 31 06:32:48 tlondon dbus: [system] Service 'org.freedesktop.ConsoleKit' is already active


Here is a snippet from the previous (enforcing) boot:

Mar 31 13:11:38 tlondon rtkit-daemon[840]: Failed to make thread 1542 RT: Operation not permitted
Mar 31 13:11:38 tlondon rtkit-daemon[840]: Failed to make thread 1542 RT: Operation not permitted
Mar 31 06:11:38 tlondon pulseaudio[1539]: module-alsa-card.c: Failed to find a working profile.
Mar 31 06:11:38 tlondon pulseaudio[1539]: module.c: Failed to load  module "module-alsa-card" (argument: "device_id="29" name="platform-thinkpad_acpi" card_name="alsa_card.platform-thinkpad_acpi" tsched=yes ignore_dB=no card_properties="module-udev-detect.discovered=1""): initialization failed.

But it does appear that the 'first few' rtkit-daemon messages have the proper time:

[root@tlondon ~]# tail -1000 /var/log/messages | grep rtkit-daemon
Mar 31 06:32:06 tlondon kernel: [   16.239978] rtkit-daemon[843]: Successfully called chroot.
Mar 31 06:32:06 tlondon kernel: [   16.241647] rtkit-daemon[843]: Successfully dropped privileges.
Mar 31 06:32:06 tlondon kernel: [   16.243194] rtkit-daemon[843]: Successfully limited resources.
Mar 31 06:32:06 tlondon kernel: [   16.244753] rtkit-daemon[843]: Running.
Mar 31 06:32:06 tlondon kernel: [   16.246333] rtkit-daemon[843]: Watchdog thread running.
Mar 31 06:32:06 tlondon kernel: [   16.247906] rtkit-daemon[843]: Canary thread running.
Mar 31 13:32:29 tlondon rtkit-daemon[843]: Successfully made thread 1534 of process 1534 (/usr/bin/pulseaudio) owned by '42' high priority at nice level -11.
Mar 31 13:32:29 tlondon rtkit-daemon[843]: Failed to make thread 1537 RT: Operation not permitted
Mar 31 13:32:29 tlondon rtkit-daemon[843]: Failed to make thread 1537 RT: Operation not permitted
Mar 31 13:32:30 tlondon rtkit-daemon[843]: Failed to make thread 1538 RT: Operation not permitted
Mar 31 13:32:30 tlondon rtkit-daemon[843]: Failed to make thread 1538 RT: Operation not permitted
Mar 31 13:32:30 tlondon rtkit-daemon[843]: Failed to make thread 1539 RT: Operation not permitted
Mar 31 13:32:30 tlondon rtkit-daemon[843]: Failed to make thread 1539 RT: Operation not permitted
Mar 31 13:32:45 tlondon rtkit-daemon[843]: Successfully made thread 1788 of process 1788 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
Mar 31 13:32:45 tlondon rtkit-daemon[843]: Successfully made thread 1789 of process 1788 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Mar 31 13:32:45 tlondon rtkit-daemon[843]: Successfully made thread 1790 of process 1788 (/usr/bin/pulseaudio) owned by '500' RT at priority 5.
Mar 31 13:32:47 tlondon rtkit-daemon[843]: Successfully made thread 1811 of process 1811 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11.
[root@tlondon ~]# 


This last set of messages was produced from a permissive boot ('enforcing=0'), but I see the same thing with an enforcing boot.

Comment 3 Steve Tyler 2011-04-27 10:27:35 UTC
Created attachment 495167 [details]
/var/log/messages

rtkit-daemon is logging in UTC instead of local time.

Apr 27 03:06:26 fir pulseaudio    [PDT = UTC - 7 ]
Apr 27 10:06:26 fir rtkit-daemon  [UTC = PDT + 7]

$ date; date -u
Wed Apr 27 03:21:26 PDT 2011
Wed Apr 27 10:21:26 UTC 2011

$ getenforce
Enforcing

Comment 4 Steve Tyler 2011-04-27 10:31:19 UTC
(In reply to comment #3)
> rtkit-daemon is logging in UTC instead of local time.

rtkit-0.10-1.fc15.x86_64

Comment 5 Lennart Poettering 2011-04-27 22:31:57 UTC
Recent rtkit chroot()s, and the timezone data is not available in it. Ideally rsyslog owuld just override the time data for local clients from SO_TIMESTAMP. Or glibc should be able to cache the tzdata instead of always going to disk. I think I filed a bug requesting the latter some time back.

Comment 6 Lennart Poettering 2011-04-27 22:32:48 UTC

*** This bug has been marked as a duplicate of bug 698040 ***

Comment 7 Steve Tyler 2011-04-28 02:19:57 UTC
(In reply to comment #6)
> 
> *** This bug has been marked as a duplicate of bug 698040 ***

Reaction as expected, Commander ... ;-)


Note You need to log in before you can comment on or make changes to this bug.