LinuxQuestions.org

LinuxQuestions.org (/questions/)
-   Linux - General (https://www.linuxquestions.org/questions/linux-general-1/)
-   -   Timestamps in "messages" are "off" (https://www.linuxquestions.org/questions/linux-general-1/timestamps-in-messages-are-off-4175622551/)

rnturn 01-27-2018 10:05 PM
Timestamps in "messages" are "off"
 
I experienced a desktop crash a few days ago--stepped away for dinner and I found that X had crashed while I was away leaving me at a console prompt--and while I was poring over the messages file looking for clues why, I ran across some time stamp "oddness" marked w/ arrows in the snippet below:

Code:
  Jan 25 20:57:41 systemname PackageKit: daemon start
  Jan 25 20:57:40 systemname kernel: snd_hda_intel 0000:00:1b.0: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
  Jan 25 20:57:53 systemname polkitd[6751]: Registered Authentication Agent for unix-session:1 (system bus name :1.33 [/usr/lib64/kde4/libexec/polkit-kde-authentication-agent-1], object path /org/kde/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Successfully called chroot.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Successfully dropped privileges.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Successfully limited resources.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Running.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Watchdog thread running.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Canary thread running.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Successfully made thread 7125 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' high priority at nice level -11.
-> Jan 26 02:57:54 systemname rtkit-daemon[7126]: Supervising 1 threads of 1 processes of 1 users.
  Jan 25 20:57:56 systemname hp-systray: hp-systray[6939]: error: option -s not recognized
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 1 threads of 1 processes of 1 users.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7151 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 5.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 2 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 2 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7152 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 3 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 3 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7155 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 4 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 4 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7154 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 5.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 5 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 5 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7153 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7155 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 4 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 4 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7154 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 5.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 5 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 5 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7153 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 6 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 6 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7157 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 5.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 7 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 7 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7158 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 8 threads of 1 processes of 1 users.
  Jan 25 20:57:57 systemname rtkit-daemon: Last message 'Supervising 8 thread' repeated 1 times, suppressed by syslog-ng on systemname
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Successfully made thread 7156 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 9.
-> Jan 26 02:57:57 systemname rtkit-daemon[7126]: Supervising 9 threads of 1 processes of 1 users.
  Jan 25 20:58:01 systemname PackageKit: get-updates transaction /1_dddbdeba from uid 1000 finished with success after 8093ms
-> Jan 26 02:58:01 systemname rtkit-daemon[7126]: Supervising 9 threads of 1 processes of 1 users.
-> Jan 26 02:58:01 systemname rtkit-daemon[7126]: Successfully made thread 7212 of process 7125 (/usr/bin/pulseaudio) owned by 'your-name-here' RT at priority 6.
-> Jan 26 02:58:01 systemname rtkit-daemon[7126]: Supervising 10 threads of 1 processes of 1 users.
  Jan 25 20:58:01 systemname PackageKit: get-distro-upgrades transaction /2_ebeabdba from uid 1000 finished with success after 514ms
I have never seen this before.

Q: Is it normal for some process on the system--in this case, "rtkit-daemon"--to be unaware of the time zone and have the timestamp off by hours? Note that it's not consistently off. After the desktop crash, the normal filesystem checks after a reboot showed that the "/home" filesystem was corrupted. Running "e2fsck" placed a ton of entries in "lost+found"--thank goodness for daily backups. I found nothing in the messages file that seemed to be related to something mucking up the filesystem (which was the reason I was looking at the log in the first place.)

Background: OpenSUSE 13.2 (upgrading to Leap "real soon now"). Multiple Chrome windows were open at the time and a Perl script was beavering away and inserting info into a remote PostgreSQL database just before or at the time of the desktop crash. Jack was running but no clients were doing anything sound-related at the time. Reply with questions about what else was running at the time and I'll try and recall (no guarantees; memories fading fast).

Has anyone seen this before?

Any theories are welcome---heck, even wild-eyed guesses, too, for that matter. This chunk of log file's got me stumped.

TIA...

--
Rick

RockDoctor 01-28-2018 07:52 AM
Haven't seen it before, but it looks like UTC (Jan 26 02:57:57) vs. CST (Jan 25 20:57:57).

norobro 01-28-2018 10:07 AM
Old bug that is marked "duplicate" but might point you in the right direction: https://bugzilla.redhat.com/show_bug.cgi?id=689655

I LOL'ed at post #7.

rnturn 01-28-2018 12:08 PM
Quote:
Originally Posted by norobro (Post 5812585)
Old bug that is marked "duplicate" but might point you in the right direction: https://bugzilla.redhat.com/show_bug.cgi?id=689655

I LOL'ed at post #7.
I just did, too.

(Thanks for that link, BTW.)

Sounds like the vaunted systemd doesn't know the correct order to be starting processes, doesn't it?

I'll mark this thread as solved even though I have no idea how to fix this and it doesn't seem like the systemd folks have much interest in fixing the real problem. Not shiny enough, I guess.

I'll see what I get after my Leap (of Faith) upgrade is complete.


All times are GMT -5. The time now is 05:05 AM.