1

For a university task I have a system to do some investigations on. As I analyzed the kern.log as well as the syslog and the auth.log files, I wondered about a specific behavior: Every time the system boots, there is a point within the logs where the log timestamps jump back by two hours.

My first thought was, that the system starts with hwclock UTC time and at some point, the time zone (UTC+2) will be applied. But as the timezone is UTC+2 (and not UTC-2) I would expect the the jump forward and not backward.

Is there anyone how can give me an explanation (or a hint to an explanation) for this behavior?

This is what I mean:

...
Jun  5 20:05:27 pc kernel: [   11.383305] snd_hda_codec_idt hdaudioC0D0: autoconfig for STAC9221 A1: line_outs=3 (0xc/0xf/0xb/0x0/0x0) type:speaker
Jun  5 20:05:27 pc kernel: [   11.383307] snd_hda_codec_idt hdaudioC0D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
Jun  5 20:05:27 pc kernel: [   11.383308] snd_hda_codec_idt hdaudioC0D0:    hp_outs=1 (0xa/0x0/0x0/0x0/0x0)
Jun  5 20:05:27 pc kernel: [   11.383309] snd_hda_codec_idt hdaudioC0D0:    mono: mono_out=0x0
Jun  5 20:05:27 pc kernel: [   11.383310] snd_hda_codec_idt hdaudioC0D0:    dig-out=0x10/0x0
Jun  5 20:05:27 pc kernel: [   11.383310] snd_hda_codec_idt hdaudioC0D0:    inputs:
Jun  5 20:05:27 pc kernel: [   11.383311] snd_hda_codec_idt hdaudioC0D0:      Mic=0xd
Jun  5 20:05:27 pc kernel: [   11.383312] snd_hda_codec_idt hdaudioC0D0:      Line=0xe
Jun  5 20:05:27 pc kernel: [   11.383313] snd_hda_codec_idt hdaudioC0D0:      CD=0x15
Jun  5 20:05:27 pc kernel: [   11.383314] snd_hda_codec_idt hdaudioC0D0:    dig-in=0x11
Jun  5 20:05:27 pc kernel: [   11.407403] input: HDA Intel Mic as /devices/pci0000:00/0000:00:05.0/sound/card0/input8
Jun  5 20:05:27 pc kernel: [   11.407540] input: HDA Intel Line as /devices/pci0000:00/0000:00:05.0/sound/card0/input9
Jun  5 20:05:27 pc kernel: [   11.407675] input: HDA Intel Speaker Front as /devices/pci0000:00/0000:00:05.0/sound/card0/input10
Jun  5 20:05:27 pc kernel: [   11.407810] input: HDA Intel Speaker CLFE as /devices/pci0000:00/0000:00:05.0/sound/card0/input11
Jun  5 20:05:27 pc kernel: [   11.407938] input: HDA Intel Front Headphone as /devices/pci0000:00/0000:00:05.0/sound/card0/input12
Jun  5 20:05:27 pc kernel: [   11.408111] input: HDA Intel SPDIF In as /devices/pci0000:00/0000:00:05.0/sound/card0/input13
Jun  5 20:05:27 pc kernel: [   14.635240] audit: type=1400 audit(1591380319.980:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-xpdfimport" pid=620 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   14.655840] audit: type=1400 audit(1591380320.004:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-senddoc" pid=618 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   14.741500] audit: type=1400 audit(1591380320.088:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-oopslash" pid=617 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   14.742736] audit: type=1400 audit(1591380320.088:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="ippusbxd" pid=616 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   15.019051] audit: type=1400 audit(1591380320.364:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lsb_release" pid=624 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   15.053162] audit: type=1400 audit(1591380320.400:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=627 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   15.053165] audit: type=1400 audit(1591380320.400:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=627 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   15.084543] audit: type=1400 audit(1591380320.428:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=619 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   15.158035] audit: type=1400 audit(1591380320.504:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="system_tor" pid=623 comm="apparmor_parser"
Jun  5 20:05:27 pc kernel: [   15.748144] audit: type=1400 audit(1591380320.652:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=632 comm="apparmor_parser"
Jun  5 20:05:38 pc kernel: [   32.906512] kauditd_printk_skb: 28 callbacks suppressed
Jun  5 20:05:38 pc kernel: [   32.906515] audit: type=1400 audit(1591380338.248:40): apparmor="DENIED" operation="capable" profile="/usr/sbin/cups-browsed" pid=765 comm="cups-browsed" capability=23  capname="sys_nice"
Jun  5 20:05:40 pc kernel: [   34.654094] e1000: enp0s3 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
Jun  5 20:05:40 pc kernel: [   34.654536] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s3: link becomes ready
Jun  5 18:05:55 pc kernel: [   49.364257] snd_hda_intel 0000:00:05.0: Invalid position buffer, using LPIB read method instead.
Jun  5 18:05:55 pc kernel: [   49.571782] snd_hda_intel 0000:00:05.0: Invalid position buffer, using LPIB read method instead.
Jun  5 18:06:21 pc kernel: [   75.730326] rfkill: input handler disabled
Jun  5 18:07:45 pc kernel: [  159.004723] rfkill: input handler enabled
Jun  5 18:07:57 pc kernel: [  171.241572] rfkill: input handler disabled
...
Atilla1899
  • 13
  • 1
    probably the hw saved time is saved as local when the system expects it was saved as UTC. – A.B Jul 26 '20 at 14:15
  • 2
    Is this a dual boot with Windows? – waltinator Jul 26 '20 at 15:06
  • What was the UTC and local time when the system booted (date -u and date)? –  Jul 26 '20 at 15:06
  • @waltinator It might be a dual boot (regarding the partition table). But in case it is, the Windows system has been destroyed. – Atilla1899 Jul 26 '20 at 15:27
  • @Isaac I only got an unmounted image of the system. Where do I find this information within the file system? – Atilla1899 Jul 26 '20 at 15:28
  • So: you don't I have a system, only a copy of some files. No, sorry, there is no way to solve hardware clock issues without a hardware clock to debug. –  Jul 26 '20 at 16:11
  • @Isaac it is a forensic task - so I do not need to fix the issue. Just need to explain it. I hoped that there is a simple explanation for this behavior. – Atilla1899 Jul 26 '20 at 17:04
  • Well, yes, the simple explanation is that the boot time got modified later. But that is not what you want as an answer, you will like to know what modified it and why. We can generate alternatives and propose ideas but only testing them we could reach a solution. I could propose that the systemd-timesyncd is updating the time on boot (note that the time is changed after a network interface got enabled, that could enable an NTP query) , but that gives no explanation of why is it wrong at boot. We would be discussing just opinions. –  Jul 26 '20 at 17:11

1 Answers1

2

You have erroneously configured your hardware RTC as local time.

This has never been a good idea, and it remains not one. This particular problem with it (one out of several) has been well-known for a couple of decades.

What happens is this.

  1. At bootstrap, the kernel sets the system clock (which always runs in UTC) from the hardware clock. This sets your system clock to the wrong time, because your hardware RTC is not set to the UTC time as it should be. Hardware RTC chips (in common platforms) do not have timezone information.
  2. Later in the bootstrap, a non-kernel program works out the offset from local time to UTC by querying your C library's locale database, using a "global" timezone setting from a configuration file, and tells the kernel that offset.
  3. The kernel applies the offset to the system clock and to various drivers (such as the FAT filesystem driver) that pretend that things are in local time. The system clock is now set to a correct UTC value. The system clock jumps by the UTC offset value.

When the configured "global" timezone is behind UTC, as it is in the Americas, the system clock starts behind UTC (as the hardware clock erroneously is) and jumps forwards to UTC once system-manager/systemd/whatever has provided the timezone offset. When the timezone is ahead of UTC, as it is in parts of Europe/Africa and in Asia, the system clock jumps backwards, something which applications do not expect.

The BSDs have a way around this. The timezone offset from UTC can be told to the bootstrap loader, via loader variables in the loader.conf file. So the kernel already knows the offset to apply to the hardware RTC value, in order to obtain the UTC value to set the system clock to, by the point that it performs its initial read of the hardware RTC.

Linux does not have this mechanism, and instead has a magic meaning for the very first program that calls the settimeofday() function in a particular way. The program is usually systemd, the nosh system-manager, or the first invocation of the hwclock program.

Run your hardware real-time clock in UTC, and configure all of your operating systems to know this.

Further reading

JdeBP
  • 68,745