PDA

View Full Version : [SOLVED] journactl entries in the future.



jonaternet
26th August 2018, 09:16 PM
Hello,

I have system freezing randomly.
I find entries in the journal that are in the future. Then suddenly the time is correct. My bios is set to the correct time. Is it a bug or am I missing something ?
Writing this at 22.11 the 26 of august (aout in french). The logs jump from future to present :


août 26 23:42:00 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-vconsole-setup comm="sy
stemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
août 26 23:42:00 localhost.localdomain systemd[1]: Reached target Switch Root.
août 26 23:42:00 localhost.localdomain systemd[1]: Starting Switch Root...
août 26 23:42:00 localhost.localdomain systemd[1]: Switching root.
août 26 23:42:00 localhost.localdomain systemd-journald[170]: Journal stopped
août 26 21:42:01 localhost.localdomain systemd-journald[170]: Received SIGTERM from PID 1 (systemd).
août 26 21:42:01 localhost.localdomain kernel: systemd: 18 output lines suppressed due to ratelimiting
août 26 21:42:01 localhost.localdomain kernel: SELinux: 32768 avtab hash slots, 115036 rules.
août 26 21:42:01 localhost.localdomain kernel: SELinux: 32768 avtab hash slots, 115036 rules.


I also find this :


août 26 23:41:59 localhost.localdomain kernel: RTC time: 21:41:58, date: 08/26/18

I was inspecting the logs because I was trying to troubleshoot some random system freezes (3 times today, no response at all, ctrl-alt-f3 or anything like this didn't work...) I think it may be related ?

EDIT : This morning I have this, and system freeze occured again :

Window manager warning: last_user_time (1253423) is greater than comparison timestamp (1253419). This most likely represents a buggy client sending inaccurate timestamps in messages such as _NET_ACTIVE_WINDOW. Trying to work around...

Jean Pierre
27th August 2018, 11:21 AM
I also noticed that. IMHO, the system boots using the internal clock, which it assumes to be UTC, so it adds the time zone difference (+2 hours in your case) to get local time shown in the logs. Later it uses the time collected from Internet (the correct one), and you see the jump back from 23:42 to 21:42.

You probably use dual booting with Windows, and Windows sets the local time in the internal clock.

However I do not understand why Fedora does not set its expectation of current time (which would be UTC) in the clock during shutdown, so that the time while booting would be correct at the next startup.

jonaternet
27th August 2018, 01:11 PM
Hi, thanks for the reply. I don't have a Windows dual boot, only Fedora installed. and the internal clock is set correctly. I have a sort of "smart" bios (not UEFI) from MSI, that can connect to internet, so it gets its time from internet I think. It is a real mystery where that time in the journal comes from, it's neither UTC (which would be in the past here) nor internal clock apparently. But I'm happy to have a new element : if you have the same thing in your logs and it does not cause system freezes on your side, then my issue with freezes must be elsewhere.
I also did an fsck, it did not seem to solve the problem, and there weren't timestamp errors there

bgstack15
27th August 2018, 04:17 PM
If your hardware clock is not the same as your local time, I recommend setting the hardware clock to the current system time.

hwclock -w
From my man hwclock(8):

-w, --systohc
Set the Hardware Clock to the current System Time.


I expect that if your system clock is the same as the desired local time, syncing to the Internet for time will not jump your system clock around anymore.

Jean Pierre
27th August 2018, 08:13 PM
and the internal clock is set correctly. I have a sort of "smart" bios (not UEFI) from MSI, that can connect to internet, so it gets its time from internet I think.

If "correctly" means "local time", you might try to set it two hours late (which is UTC) from within the BIOS, and check what happens during boot. I would be surprised if your computer can get the time from Internet before the network stack is up.

bgstack15
27th August 2018, 09:23 PM
Oh, and maybe you need to place a value in /etc/sysconfig/clock or maybe some systemd version nowadays. I remember having to do something like this once. https://www.centos.org/docs/5/html/5.1/Deployment_Guide/s2-sysconfig-clock.html




UTC=<value>, where <value> is one of the following boolean values:

true or yes — The hardware clock is set to Universal Time.

false or no — The hardware clock is set to local time.

marcin82
27th August 2018, 09:51 PM
Post output of commands as root:

hwclock --verbose
timedatectl status


Look here. (https://wiki.archlinux.org/index.php/time#Time_standard)

jonaternet
27th August 2018, 10:58 PM
So I tried to set the bios manually to UTC (two hours less than local time) and... I get the logs at the right time, but then... They're in the past ! fortunately it gets adjusted after a while, behaving as described in the link marcin82 suggested.

Logs at 22.58 local time :


août 27 22:58:41 localhost.localdomain systemd[1]: Switching root.
août 27 22:58:41 localhost.localdomain systemd-journald[173]: Journal stopped
août 27 20:58:41 localhost.localdomain systemd-journald[173]: Received SIGTERM from PID 1 (systemd).
[...]
août 27 20:58:54 localhost.localdomain chronyd[619]: System clock wrong by 7201.353012 seconds, adjustment started
août 27 22:58:55 localhost.localdomain chronyd[619]: System clock was stepped by 7201.353012 seconds


Right now it looks all right but in some previous reboots the RTC had been set again to local automagically. So I tried to reboot again and this time it remained good. A strange random thing was going on. So I tried the following :


[jonath@localhost ~]$ sudo timedatectl status
Local time: lun. 2018-08-27 23:40:27 CEST
Universal time: lun. 2018-08-27 21:40:27 UTC
RTC time: lun. 2018-08-27 21:40:26
Time zone: Europe/Paris (CEST, +0200)
System clock synchronized: yes
systemd-timesyncd.service active: yes
RTC in local TZ: yes

Warning: The system is configured to read the RTC time in the local time zone.
This mode cannot be fully supported. It will create various problems
with time zone changes and daylight saving time adjustments. The RTC
time is never updated, it relies on external facilities to maintain it.
If at all possible, use RTC in UTC by calling
'timedatectl set-local-rtc 0'.
[jonath@localhost ~]$ sudo timedatectl set-local-rtc 0
[jonath@localhost ~]$ sudo timedatectl status
Local time: lun. 2018-08-27 23:48:07 CEST
Universal time: lun. 2018-08-27 21:48:07 UTC
RTC time: lun. 2018-08-27 21:48:07
Time zone: Europe/Paris (CEST, +0200)
System clock synchronized: yes
systemd-timesyncd.service active: yes
RTC in local TZ: no

Hopefully it's been fixed by issuing sudo timedatectl set-local-rtc 0. I'll confirm that later, as you ca see it's pretty late on local time ;) . Thank you,

jonaternet
28th August 2018, 11:40 AM
Fixed ! Now the logs keep consistent time during all the boot process. Thank you all for your support.
It was provoking an incoherent behavior of journactl : journactl -b 1 or -b 3 or even -b 35 would show me the same logs again and again, making the analysis of my system freezes more difficult. A workaround is to check individual journal files :

ls -l /var/log/journal/<numbers>/
journalctl --file <name of file with date of crash>
Like in good old days of text logs. I found thousand times that messages and then nothing (button shutdown)

août 26 19:09:42 localhost.localdomain kernel: nouveau 0000:01:00.0: Xwayland[1727]: nv50cal_space: -16
So it was obviously a Wayland bug. I switched to Xorg/gnome session and so far since yesterday, it does not freeze anymore. I filed that bug https://bugzilla.redhat.com/show_bug.cgi?id=1622988
I wonder if the clock thing is to be considered as a bug too.