Created attachment 1264342 [details]
/var/log contents from the server

Created attachment 1264343 [details]
/var/log from the client (with sssd debug level at 6)

Proposing this as an Alpha blocker for now, per criterion "It must be possible to join the system to a FreeIPA or Active Directory domain at install time and post-install, and the system must respect the identity, authentication and access control configuration provided by the domain" - https://fedoraproject.org/wiki/Fedora_26_Alpha_Release_Criteria#Remote_authentication

Discussed during the 2017-03-20 blocker review meeting: [1]

The decision was made to classify this bug as an AcceptedBlocker (Alpha) as it violates the following criteria:

"It must be possible to join the system to a FreeIPA or Active Directory domain at install time and post-install, and the system must respect the identity, authentication and access control configuration provided by the domain."

[1] https://meetbot.fedoraproject.org/fedora-blocker-review/2017-03-20/f26-blocker-review.2017-03-20-16.06.txt

So, it's definitely the system time that's causing the problem here.

When you enrol a system as a FreeIPA client, ipa-client-install disables chrony (Fedora's default time sync daemon), syncs time with the domain server (which runs an NTP server), and enables ntpd.service . This all seems to happen, during enrolment - which occurs in the installer environment, after install has completed, in a chroot into the installed system - and the time the clock is set to looks correct.

For some reason, when the system is rebooted after the install, the clock is completely wrong - it's off by almost exactly 5 hours. The ntpd service starts up during boot, but doesn't actually seem to correct the system time.

To confirm all this, I adjusted the tests on staging openQA to have both server and client run 'date -u' (to show what the system considers the current UTC time to be). I also adjusted the client test to stop ntpd.service and use 'ntpdate' to adjust the system clock before doing the login test. Here you can see that happening:

https://openqa.stg.fedoraproject.org/tests/82906#step/freeipa_client/39

After those tweaks, the test passes - so that's how we know the time difference is the problem, because correcting it makes the test pass.

So the remaining unknowns are:

1) why doesn't ntpd.service correct the client's clock?
2) why does the client system have the wrong time to start with?

I have a suspicion for 2), though I haven't tested it. The openQA worker host machines (like all Fedora infra machines) have their time zone set to UTC (so their 'local' time is the same as UTC). The kickstart we use for the enrol-via-kickstart test specifies the America/New York timezone, and Eastern time is usually UTC-5 (and remember, our system's clock was off by nearly precisely 5 hours). However, this isn't quite as neat as all that, since New York is currently on daylight savings time, so the current delta is actually *four* hours. Still, it's a theory.

I'm currently working on those unknowns.

So, okay, I have a couple of leads.

I hacked up the test again so that, while the kickstarted install is running, we switch to a console and run:

hwclock
date
date -u

every few seconds, to see what's going on with the system clock in the installer environment. I also tried running the test on Fedora 25 Final to compare the result with current 26/Rawhide.

25 does not show the same bug, as I expected; the installed system's clock is more or less correct at boot time, when we run 'ntpdate' it does not correct the clock by 5 hours, as it does on 26/Rawhide.

There is a significant difference to the result of the installer clock check, too. On Fedora 25, each time we do it, all three commands return approximately the same time, and it is the correct current UTC time.

On 26/27, the *first* time the commands are run, all three commands return approximately the same time, and both 'date' and 'date -u' show the timezone as UTC, but the time is *not* the correct current UTC time; it's five hours behind. The *second* time the command is run, and all subsequent times the command is run, 'date' and 'date -u' show the correct current UTC time, but 'hwclock' still has the time as five hours earlier.

So basically what's going on here is, somehow, anaconda in 26/27 is screwing up the hardware clock when installing from a kickstart like this, whereas anaconda in 25 did not. I'll have to dig into what changed some more tomorrow.

I suspect we can get away with not having this as a blocker for Alpha at least, as the enrolment works fine, and all you need to do to fix things after boot is...correct the clock, which is not hard. But there's definitely at least one bug here.

I did notice one other thing, too: a difference in the ntp configuration. In an F25 install, /etc/ntp/step-tickers looks like this:

# Use IPA-provided NTP server for initial time
ipa001.domain.local

in a Rawhide install, it looks like this:

# List of NTP servers used by the ntpdate service.

0.fedora.pool.ntp.org

i.e., somehow, ipa-client-install on Rawhide isn't writing that file as it should. But I don't think that's a significant factor in *this* bug, as the 0.fedora.pool.ntp.org server should also work fine. I'm guessing the reason ntpd doesn't correct the clock is probably just that ntpd has always refused to make huge corrections when run as a daemon, though I'm pretty sure it used to log / warn about this...

BTW, here are the last tests I ran:

https://openqa.stg.fedoraproject.org/tests/82967 (Rawhide)
https://openqa.stg.fedoraproject.org/tests/82965 (F25)

I had to cancel the Rawhide test as it got stuck trying to run the clock checks at the grub prompt (a bug in my hasty hack...), but anyway, you need to watch the videos to see the installer time checks:

https://openqa.stg.fedoraproject.org/tests/82967/file/video.ogv (pause around 2:05 to see all the runs)
https://openqa.stg.fedoraproject.org/tests/82965/file/video.ogv (pause around 1:21 to see all the runs)

Oh, and this is the actual kickstart used in the tests:

install
cdrom
bootloader --location=mbr
network --device=link --activate --bootproto=static --ip=10.0.2.101 --netmask=255.255.255.0 --gateway=10.0.2.2 --hostname=client001.domain.local --nameserver=10.0.2.100
lang en_US.UTF-8
keyboard us
timezone --utc America/New_York
clearpart --all
autopart
%packages
@^server-product-environment
%end
rootpw anaconda
reboot
realm join --one-time-password=monkeys ipa001.domain.local

Created attachment 1264908 [details]
/var/log from a Fedora 25 client install (for comparison)

Here's the /var/log tarball from a Fedora 25 client install, for comparison with the Fedora 26 logs; the anaconda logs are there in /var/log/anaconda , might help with figuring out how anaconda manages to screw up the hwclock.

(In reply to Adam Williamson from comment #6)
<snip>
> On 26/27, the *first* time the commands are run, all three commands return
> approximately the same time, and both 'date' and 'date -u' show the timezone
> as UTC, but the time is *not* the correct current UTC time; it's five hours
> behind. The *second* time the command is run, and all subsequent times the
> command is run, 'date' and 'date -u' show the correct current UTC time, but
> 'hwclock' still has the time as five hours earlier.
<snip>

I wonder how likely it is that it's really Anaconda screwing the time configuration if the commands do run a few seconds apart ? 

I wonder if it could be a side effect of calling date/date -u - maybe it touches some time related machinery while finding out the current time, causing the time to change as observed once called again a few seconds later.

No, that really doesn't seem likely at all. a), that doesn't happen on F25. b), running 'date' *certainly* should never touch the hardware clock. c), the bug happens even when I *don't* run date in the installer environment.

I'm really pretty sure anaconda's doing something wrong here.

Oh, sorry, forgot to say: I'm officially removing the 'accepted' status and calling for a re-vote here, now we have more info on the bug. I think just documenting this as a commonbug with 'correct the system time' as the workaround should suffice for Alpha.

-1 blocker +1 FE

-1 Blocker +1 FE

That's 3 +1/-1 votes, so accepting that.

(In reply to Adam Williamson from comment #12)
> Oh, sorry, forgot to say: I'm officially removing the 'accepted' status and
> calling for a re-vote here, now we have more info on the bug. I think just
> documenting this as a commonbug with 'correct the system time' as the
> workaround should suffice for Alpha.

Yeah, that sounds sensible - it looks like something that will require more time to properly investigate and fix.

Still I do think this is likely not caused by Anaconda directly - I've just checked and there have been no relevant changes in how either time or realm-join are handled by Anaconda since F25.

BTW, is it possible to narrow down when the tests started to fail ? That could help pinpoint the cause.

Unfortunately not, because FreeIPA was broken in several other ways up till last week, so we never got to the point of running this test :/ This failure has only become apparent since the underlying FreeIPA issues were fixed.

Looking through my old notes, I'm reminded we had an almost exactly identical bug in F25:

https://bugzilla.redhat.com/show_bug.cgi?id=1367604
https://bugzilla.redhat.com/show_bug.cgi?id=1367647

I'll read back through those bugs on Monday and see if they help with this one.

Probably worth commonbugs'ing this until we figure it out.

FYIO, I experienced the same problem on PowerPC f26 compose 20170406, 
and noticed also the 5 hours differences between the two guests.

As with the F25 case, this actually happens to 'regular' installs too, but it's quietly corrected by chronyd during boot. The difference is that chronyd run as a service will make large adjustments, while ntpd doesn't; you have to run ntpdate directly to make large adjustments. ntpd only expects to have to make *small* adjustments and will just not correct the clock if it's wildly wrong.

Here's some log messages from an F26 install I just did:

/var/log/anaconda/anaconda.log:02:57:53,000 INFO anaconda: System time set to Tue Apr 11 02:57:53 2017 UTC
/var/log/anaconda/anaconda.log:02:57:53,000 INFO anaconda: System time set to Tue Apr 11 02:57:53 2017 UTC
/var/log/anaconda/anaconda.log:02:57:53,000 INFO anaconda: System time set to Tue Apr 11 02:57:53 2017 UTC
/var/log/anaconda/anaconda.log: Task: Save system time to HW clock
/var/log/anaconda/anaconda.log:02:58:18,862 INFO anaconda: Task started: Save system time to HW clock (1/18)
/var/log/anaconda/anaconda.log:02:58:20,501 DEBUG anaconda: Task completed: Save system time to HW clock (1/18) (1.6 s)

The correct UTC time was 20:57 - somehow anaconda got it wrong by 18 hours(!)

Later during the install process, the local time gets corrected by chronyd:

02:59:15,746 DEBUG NetworkManager:<debug> [1491879555.7465] ndisc-lndp[0x80af0150,"ens3"]: processing libndp e
vents
21:00:30,820 INFO chronyd:Selected source 69.87.223.252
21:00:30,821 WARNING chronyd:System clock wrong by 64802.000426 seconds, adjustment started
21:00:30,821 WARNING chronyd:System clock was stepped by 64802.000426 seconds

but as can be seen from the other logs, nothing stores the time to the hardware clock after that, so the hardware clock is still set wrong. Thus, on first boot of the installed system, the system time is wrong, and chronyd corrects it during boot:

Apr 10 22:20:58 localhost.localdomain chronyd[908]: Selected source 199.182.221.110
Apr 10 22:20:58 localhost.localdomain chronyd[908]: System clock wrong by 64801.671236 seconds, adjustment started
Apr 11 16:21:00 localhost.localdomain chronyd[908]: System clock was stepped by 64801.671236 seconds

So there's really nothing specific to the kickstart or domain client or ntpd case here except that ntpd doesn't cover up the problem like chronyd does. The underlying problem looks like it always happens. I'm gonna try and figure out what's actually causing it next.

So far this is looking like basically a re-run of https://bugzilla.redhat.com/show_bug.cgi?id=1367647 . It boils down, again, to the calculated epoch being wrong. I added some logging in an updates.img and compared 25 and 26. The log line in question just logs the 'epoch' value after it's calculated:

    # Calculate the number of seconds between this time and timestamp 0
    epoch = tz.localize(datetime.datetime.fromtimestamp(0))
    log.info("epoch is: %s" % epoch)

Here's the results. 25:

epoch is: 1969-12-31 18:00:00-06:00

26:

epoch is: 1970-01-01 00:00:00-06:00

that's the thing that's throwing off anaconda's calculations.

What I can't account for, this time, is why it's happening. In F25 it was because libtimezonemap had changed, and we fixed the bug by changing it back:

http://pkgs.fedoraproject.org/cgit/rpms/libtimezonemap.git/commit/?id=044b30108b0297d8655111a1663a348a2e6e75c0

but that change hasn't been reverted since, AFAICT. The package has been rebuilt twice since - (once for the mass rebuild, once (for some reason) to disable the test suite - but neither of those changes touched the patch that restores the TZ environment variable setting behaviour.

So, I don't know why this suddenly started happening again. Could the 'thread safety issue' alluded to as the reason for why the TZ setting behaviour was originally changed in the first place be the problem here?

The tests were disabled because it caught an issue with selecting time zones that have a DST offset that is not the usual 60 minutes. This only applies to an island near Australia with a population of about 400, so I decided to ignore it instead of fixing it.

The thread safety thing would only apply if another thread is modifying the environment at the same moment, which is unlikely.

Adam asked me to look at this since I made the patch which fixed this a few releases ago.

After much discussion with Adam it seems like there's a change in Python between F25 and F26 with regard to the TZ environment variable.

This is the patch I would suggest (untested):
diff --git a/pyanaconda/isys/__init__.py b/pyanaconda/isys/__init__.py
index 84d9569..07ed667 100644
--- a/pyanaconda/isys/__init__.py
+++ b/pyanaconda/isys/__init__.py
@@ -130,7 +130,9 @@ def set_system_date_time(year=None, month=None, day=None, hour=None, minute=None
     set_date = tz.localize(datetime.datetime(year, month, day, hour, minute, second))
 
     # Calculate the number of seconds between this time and timestamp 0
-    epoch = tz.localize(datetime.datetime.fromtimestamp(0))
+    # sometimes Python3 decides to change its mind - force the timezone
+    epoch = (datetime.datetime.utcfromtimestamp(0)).astimezone(tz)
+
     timestamp = (set_date - epoch).total_seconds()
 
     set_system_time(int(timestamp))


For long-term stability, I'd also recommend we go a bit further in F27 with this resolution.

The way this is setting the hardware clock is that it passes the difference between epoch and now in seconds to a function defined in isys/isys.c doSetSystemTime which invokes the glibc settimeofday.

It passes the time in seconds and NULL as the timezone; this needs more testing as a quick read of the man page makes it appears as if it should fail if the TimeZone is set to NULL.

All that said - it might be beneficial to update isys.c to be aware of timezones and ensure consistency all the way down the stack.

So I talked this over quite a bit with rmarshall today. We've definitely developed a better understanding of what's going on, but we're still working on what to do about it.

The key discovery is basically this:

[adamw@adam anaconda (time-log %)]$ python35 
Python 3.5.2 (default, Feb 11 2017, 18:09:24) 
[GCC 7.0.1 20170209 (Red Hat 7.0.1-0.7)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> import datetime
>>> os.environ['TZ'] = 'America/Winnipeg'
>>> datetime.datetime.fromtimestamp(0)
datetime.datetime(1969, 12, 31, 18, 0)
>>> os.environ['TZ'] = 'Europe/London'
>>> datetime.datetime.fromtimestamp(0)
datetime.datetime(1970, 1, 1, 1, 0)
>>> 

[adamw@adam anaconda (time-log %)]$ python3
Python 3.6.0 (default, Mar 21 2017, 17:30:34) 
[GCC 7.0.1 20170225 (Red Hat 7.0.1-0.10)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> import datetime
>>> os.environ['TZ'] = 'America/Winnipeg'
>>> datetime.datetime.fromtimestamp(0)
datetime.datetime(1969, 12, 31, 16, 0)
>>> os.environ['TZ'] = 'Europe/London'
>>> datetime.datetime.fromtimestamp(0)
datetime.datetime(1969, 12, 31, 16, 0)
>>> 

With Python 3.5 - i.e. Fedora 25 and earlier - the `datetime.datetime.fromtimestamp(0)` call we use to get a naive datetime object representing the wall clock time of "the epoch" respects the timezone indicated by the 'TZ' environment variable. So if 'TZ' is set to 'America/Winnipeg', we get a datetime object for the date 1969-12-31 18:00 , which is what the local date and time was in Winnipeg at timestamp 0.

Python 3.6 seems to entirely ignore the TZ environment variable in deciding what wall clock time to give you. In my case, Python has decided on some level that the timezone it's going to use is my actual local time zone (which is America/Vancouver), so no matter what I set 'TZ' to, it gives me a datetime object for 1969-12-31 16:00 , which is what the local date and time in Vancouver was at timestamp 0. When I set 'TZ' to London, I don't get the London date and time for timestamp 0, I still get the Vancouver date and time.

In the anaconda environment, it seems that Python decides the 'current timezone' is UTC, so what you get is the wall clock time for timestamp 0 in the UTC timezone, which is 1970-01-01 00:00. Regardless of what the 'TZ' environment var is set to, that's always what we get for our `datetime.datetime.fromtimestamp(0)` call, and that throws off the calculation.

This is what changed between Fedora 25 and 26 and broke the way we do the calculation this time. It also has some other consequences: if you look at the timestamps on anaconda's log files in a Fedora 25 and Fedora 26 install, they're quite different. It seems like whatever logging function we use is hitting the same codepath in Python when it decides what timestamp to put on each log entry; it's trying to use "the wall clock time in the 'current' timezone". Thus in Fedora 25, all the messages after the time/date spoke sets the 'TZ' environment variable have the local time as their timestamp. In Fedora 26, all messages wind up timestamped as whatever the system believes is the current UTC time, as that's what Python decides the 'current timezone' is.

Rob and I discussed various ways we can fix the `set_system_date_time` calculation to work correctly with both Python behaviours - it's not that difficult, it just involves adjusting the 'epoch' calculation somehow to use the timezone that was passed to the function explicitly, rather than relying on Python using that same timezone via the 'TZ' environment variable. He or I will likely send a PR soon. But I am also going to dig into the Python behaviour change a bit, because this change clearly has consequences beyond this particular `set_system_date_time` calculation, and it may be worth looking into those.

I've reported the Python behaviour change upstream: https://bugs.python.org/issue30062

Aha:

https://docs.python.org/3/library/time.html#time.tzset

"Note
Although in many cases, changing the TZ environment variable may affect the output of functions like localtime() without calling tzset(), this behavior should not be relied on."

It seems like we were relying on that, cos there's no calls to `tzset()` anywhere in anaconda.

This change seems, in a quick test, both to fix the 'incorrect system time calculation' bug and result in log timestamps looking more like F25:

----------------

diff --git a/pyanaconda/isys/__init__.py b/pyanaconda/isys/__init__.py
index 84d9569c4..f859f1182 100644
--- a/pyanaconda/isys/__init__.py
+++ b/pyanaconda/isys/__init__.py
@@ -118,6 +118,8 @@ def set_system_date_time(year=None, month=None, day=None, hour=None, minute=None
     if not tz:
         tz = pytz.UTC
 
+    time.tzset()
+
     # get the right values
     now = datetime.datetime.now(tz)
     year = year if year is not None else now.year
diff --git a/pyanaconda/ui/gui/spokes/datetime_spoke.py b/pyanaconda/ui/gui/spokes/datetime_spoke.py
index 1c7dec69d..60c51fc42 100644
--- a/pyanaconda/ui/gui/spokes/datetime_spoke.py
+++ b/pyanaconda/ui/gui/spokes/datetime_spoke.py
@@ -53,6 +53,7 @@ from pyanaconda.threads import threadMgr, AnacondaThread
 import datetime
 import re
 import threading
+import time
 import locale as locale_mod
 import functools
 
@@ -611,6 +612,7 @@ class DatetimeSpoke(FirstbootSpokeMixIn, NormalSpoke):
 
         if is_valid_timezone(self.data.timezone.timezone):
             self._tzmap.set_timezone(self.data.timezone.timezone)
+            time.tzset()
 
         self._update_datetime()
 
@@ -992,9 +994,11 @@ class DatetimeSpoke(FirstbootSpokeMixIn, NormalSpoke):
                 offset = -float(city[3:])
 
             self._tzmap.set_selected_offset(offset)
+            time.tzset()
         else:
             # we don't want the timezone-changed signal to be emitted
             self._tzmap.set_timezone(timezone)
+            time.tzset()
 
         # update "old" values
         self._old_city = city

----------------

Note that *only* doing it in the datetimespoke isn't enough, I suspect because of threading (that thread gets its 'current' timezone updated, but other threads don't). I think doing it in `set_system_date_time` updates the timezone of the main thread, and that really makes things work. I suppose any other threads started before the DatetimeSpoke thread would still have the old timezone, though? Man, I hate threads...

I've tested rmarshall's proposed change from #c24 and it seems to work fine. Want to send a PR, Rob?

I can send a separate PR for the tzset() thing if you think it's a good idea, Martin. Just let us know.

https://github.com/rhinstaller/anaconda/pull/1035
https://github.com/rhinstaller/anaconda/pull/1036

anaconda-26.21.4-1.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2017-f620d8c7c2

anaconda-26.21.4-1.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-f620d8c7c2

anaconda-26.21.4-1.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.