Description of problem:
I'm trying to debug bug 1212009, and NetworkManager maintainers complained that there seems to be a system time jump during startup, which might confuse networking tools. After further investigation, it seems that anaconda is partly responsible for it, and that's what this bug is about.

When booting DVD or netinst (Live is not affected), as soon as you confirm your language choice and enter the main hub, system time seems to be shifted forward.

This is happening every time, consistently, on two tested bare metal machines and in a VM. The time is shifted by 56 minutes, if the machine doesn't have an internet connection at the time of the transition to the main hub screen. If it does have connection, the time is shifted by 1h 40min. In both cases there are no seconds changes, the shift is rounded perfectly to whole minutes.

This is how it looks like in the journal on a T540p machines, which I booted with an ethernet cable pulled out:

...
May 27 12:39:49 localhost audit[1305]: <audit-1300> arch=c000003e syscall=2 success=yes exit=7 a0=7fd184003350 a1=80100 a2=180 a3=0 items=0 ppid=1 pid=1305 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="in:imfile" exe="/usr/sbin/rsyslogd" subj=system_u:system_r:syslogd_t:s0 key=(null)
May 27 12:39:49 localhost audit: <audit-1327> proctitle=2F7573722F7362696E2F727379736C6F6764002D6E
May 27 12:40:08 localhost kernel: Btrfs loaded
########### <-- this is where I enter anaconda main hub
May 27 13:36:09 localhost systemd[1]: Time has been changed
May 27 13:36:09 localhost systemd[1]: Time has been changed
May 27 13:36:09 localhost systemd[1]: Time has been changed
########### <-- this is where I put in the cable and active network in anaconda
May 27 13:36:34 localhost kernel: e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
May 27 13:36:34 localhost kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
May 27 13:36:48 localhost systemd[1]: Cannot add dependency job for unit fedora-loadmodules.service, ignoring: Unit fedora-loadmodules.service is masked.
May 27 13:36:48 localhost systemd[1]: Cannot add dependency job for unit fedora-autorelabel.service, ignoring: Unit fedora-autorelabel.service is masked.
May 27 13:36:48 localhost systemd[1]: Cannot add dependency job for unit fedora-autorelabel-mark.service, ignoring: Unit fedora-autorelabel-mark.service is masked.
May 27 13:36:48 localhost systemd[1]: Starting Network Manager Script Dispatcher Service...
May 27 13:36:48 localhost systemd[1]: Started Network Manager Script Dispatcher Service.
May 27 13:36:48 localhost audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 13:36:48 localhost systemd[1]: Unit iscsi.service cannot be reloaded because it is inactive.
May 27 13:36:49 localhost systemd[1]: Cannot add dependency job for unit fedora-loadmodules.service, ignoring: Unit fedora-loadmodules.service is masked.
May 27 13:36:49 localhost systemd[1]: Cannot add dependency job for unit fedora-autorelabel.service, ignoring: Unit fedora-autorelabel.service is masked.
May 27 13:36:49 localhost systemd[1]: Cannot add dependency job for unit fedora-autorelabel-mark.service, ignoring: Unit fedora-autorelabel-mark.service is masked.
May 27 13:36:49 localhost systemd[1]: Starting Hostname Service...
May 27 13:36:49 localhost audit: <audit-1325> table=filter family=2 entries=0
May 27 13:36:49 localhost audit[1708]: <audit-1300> arch=c000003e syscall=272 success=yes exit=0 a0=40000000 a1=7ffcbfe60890 a2=40000040 a3=7f5fb4792700 items=0 ppid=1 pid=1708 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="(ostnamed)" exe="/usr/lib/systemd/systemd" subj=system_u:system_r:init_t:s0 key=(null)
May 27 13:36:49 localhost audit: <audit-1327> proctitle="(ostnamed)"
May 27 13:36:49 localhost systemd[1]: Started Hostname Service.
May 27 13:36:49 localhost audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 13:36:49 localhost audit[1308]: <audit-1107> pid=1308 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=method_return dest=:1.164 spid=1708 tpid=1706 scontext=system_u:system_r:systemd_hostnamed_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus
                                        exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'
May 27 13:36:49 localhost systemd-hostnamed[1708]: Changed static host name to 'localhost.localdomain'
May 27 13:36:49 localhost systemd-hostnamed[1708]: Changed host name to 'localhost.localdomain'
May 27 13:37:00 dhcp-28-138.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 12:41:14 dhcp-28-138.brq.redhat.com systemd[1]: Time has been changed
May 27 12:41:20 dhcp-28-138.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

Notice that the time shifted by 56 minutes as soon as I entered main hub, and corrected itself shortly I put in ethernet cable and activated network, probably due to systemd ntp service.


This is another example, this time from an AMD box, which I booted with ethernet cable connected:

May 27 12:25:55 dhcp-28-115.brq.redhat.com audit: <audit-1327> proctitle=6877636C6F636B002D2D6863746F737973002D2D757463
May 27 12:25:55 dhcp-28-115.brq.redhat.com audit[1605]: <audit-1111> pid=1605 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:hwclock_t:s0 msg='changing system time exe="/usr/sbin/hwclock" hostname=? addr=? terminal=pts/0 res=success'
May 27 12:25:55 dhcp-28-115.brq.redhat.com kernel: Adjusting tsc more than 11% (2412493 vs 2386887)
May 27 12:26:01 dhcp-28-115.brq.redhat.com kernel: Btrfs loaded
######## <-- this is where I enter anaconda main hub
May 27 14:06:03 dhcp-28-115.brq.redhat.com systemd[1]: Time has been changed
May 27 14:06:03 dhcp-28-115.brq.redhat.com systemd[1]: Time has been changed
May 27 14:06:03 dhcp-28-115.brq.redhat.com systemd[1]: Time has been changed
May 27 14:06:44 dhcp-28-115.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 14:06:50 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-loadmodules.service, ignoring: Unit fedora-loadmodules.service is masked.
May 27 14:06:50 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel-mark.service, ignoring: Unit fedora-autorelabel-mark.service is masked.
May 27 14:06:50 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel.service, ignoring: Unit fedora-autorelabel.service is masked.
May 27 14:06:50 dhcp-28-115.brq.redhat.com systemd[1]: Starting System clock and RTC settings service...
May 27 14:06:50 dhcp-28-115.brq.redhat.com systemd[1]: Started System clock and RTC settings service.
May 27 14:06:50 dhcp-28-115.brq.redhat.com audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 14:07:20 dhcp-28-115.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 14:07:32 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-loadmodules.service, ignoring: Unit fedora-loadmodules.service is masked.
May 27 14:07:32 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel-mark.service, ignoring: Unit fedora-autorelabel-mark.service is masked.
May 27 14:07:32 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel.service, ignoring: Unit fedora-autorelabel.service is masked.
May 27 14:07:32 dhcp-28-115.brq.redhat.com systemd[1]: Starting System clock and RTC settings service...
May 27 14:07:32 dhcp-28-115.brq.redhat.com systemd[1]: Started System clock and RTC settings service.
May 27 14:07:32 dhcp-28-115.brq.redhat.com audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 14:08:02 dhcp-28-115.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 14:08:49 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-loadmodules.service, ignoring: Unit fedora-loadmodules.service is masked.
May 27 14:08:49 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel-mark.service, ignoring: Unit fedora-autorelabel-mark.service is masked.
May 27 14:08:49 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel.service, ignoring: Unit fedora-autorelabel.service is masked.
May 27 14:08:49 dhcp-28-115.brq.redhat.com systemd[1]: Starting System clock and RTC settings service...
May 27 14:08:49 dhcp-28-115.brq.redhat.com systemd[1]: Started System clock and RTC settings service.
May 27 14:08:49 dhcp-28-115.brq.redhat.com audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
######## <-- if I wait long enough, the time corrects itself automatically
May 27 12:29:12 dhcp-28-115.brq.redhat.com systemd[1]: Time has been changed
May 27 12:29:20 dhcp-28-115.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 12:33:26 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-loadmodules.service, ignoring: Unit fedora-loadmodules.service is masked.
May 27 12:33:26 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel-mark.service, ignoring: Unit fedora-autorelabel-mark.service is masked.
May 27 12:33:26 dhcp-28-115.brq.redhat.com systemd[1]: Cannot add dependency job for unit fedora-autorelabel.service, ignoring: Unit fedora-autorelabel.service is masked.
May 27 12:33:26 dhcp-28-115.brq.redhat.com systemd[1]: Starting System clock and RTC settings service...
May 27 12:33:26 dhcp-28-115.brq.redhat.com systemd[1]: Started System clock and RTC settings service.
May 27 12:33:26 dhcp-28-115.brq.redhat.com audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 12:33:56 dhcp-28-115.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=timedatex comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 12:39:26 dhcp-28-115.brq.redhat.com systemd[1]: Starting Cleanup of Temporary Directories...
May 27 12:39:26 dhcp-28-115.brq.redhat.com systemd[1]: Started Cleanup of Temporary Directories.
May 27 12:39:26 dhcp-28-115.brq.redhat.com audit[1]: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-tmpfiles-clean comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 27 12:39:26 dhcp-28-115.brq.redhat.com audit[1]: <audit-1131> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-tmpfiles-clean comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'


This can be easily reproduced in a VM, both without a network card (to simulate missing connection) and with a network card.

The question is, why does anaconda do this? It might cause some side effects, as in bug 1183807.


Version-Release number of selected component (if applicable):
F22 Server DVD/netinst
anaconda 22.20.13-1

How reproducible:
always

Steps to Reproduce:
1. prepare a VM without a network card
2. boot DVD/netinst, do not transition into the main hub
3. check current time in console, see that no time shifts are stated in journal
4. enter anaconda main hub
5. check current time in console, see that it has shifted 56 minutes forward
6. check system journal, see that several time shifts are stated to have occurred

Additional info:
I would understand if anaconda tried to set my local time to the timezone selected on the main hub. But from the looks of it, it doesn't seem to do that. This seems to be just an arbitrary time shift.