Worth noting, I'm in the Pacific time zone, whose offset to UTC is...-0800 (well, PST's offset is -0800 anyway; PDT's is -0700). So my first theory is that anaconda is somehow trying to adjust for timezones and making a mess of it. I'll try doing an install with the time zone set to something else, and see if the system clock comes up wrong by a different amount...

Ah, so there's a pretty clear smoking gun here. In the Fedora 25 anaconda.log:

21:42:03,000 INFO anaconda: System time set to Tue Aug 16 21:42:03 2016 UTC
21:42:03,000 INFO anaconda: System time set to Tue Aug 16 21:42:03 2016 UTC
21:42:03,000 INFO anaconda: System time set to Tue Aug 16 21:42:03 2016 UTC

That was definitely not the correct time in UTC. I believe it's what the installer thought was the current time in the *specified timezone* - Pacific. It was actually even wrong about that, because the correct time was 22:42, not 21:42 (seems like a daylight savings error somewhere).

In the Fedora 24 anaconda.log:

22:42:44,000 INFO anaconda: System time set to Wed Aug 17 05:42:44 2016 UTC
22:42:44,000 INFO anaconda: System time set to Wed Aug 17 05:42:44 2016 UTC
22:42:44,000 INFO anaconda: System time set to Wed Aug 17 05:42:44 2016 UTC

it seems that Fedora 24 actually had the current local time correct (22:42) and also calculated the correct current UTC time (05:42).

I strongly suspect this commit:

https://github.com/rhinstaller/anaconda/commit/b3096e797a3b76862f94662a865c6a83854f45c4

since it affects `set_system_date_time()` , which calls `set_system_time()`, which logs those tell-tale 'System time set to...' messages. CCing Robert (author of that commit).

Note that 1367604 is currently considered an Alpha release blocker. We *maaay* be able to fudge that, but still, urgent attention would be appreciated (I'll probably try and figure this one out myself, but no guarantees...)

Still researching this. The problematic call to `set_system_date_time()` - which causes the system clock to be set to the correct UTC time in Fedora 24 but to the current *local* time in Fedora 25 - is this one:

https://github.com/rhinstaller/anaconda/blob/master/pyanaconda/ui/gui/spokes/datetime_spoke.py#L790

For debugging I added a log line just before that call which logs the minutes and seconds and timezone; that confirms that it's really that call we're hitting, and tells us what values the spoke is passing to the function.

Just adding that log line shows that there is no apparent difference in the spoke's behaviour between F24 and F25: what it passes to the function is the current *local* time (not UTC time), and the currently-configured timezone. So, right now, it's 23:56 Pacific time where I am; the logs show that in both F24 and F25, the spoke calls `set_system_date_time()` with hours 23, minutes 56, tz America/Vancouver.

Somehow, in F25, that results in the system clock being set to 23:56 UTC today, which is wrong. In F24 it results in the system clock being set to 06:52 UTC tomorrow, which is correct. Subsequently calling 'date' from a console shows the time in UTC, but anaconda somehow still knows what timezone it's in - anaconda.log timestamps continue to match the local time, not UTC time.

I think I was wrong to suspect b3096e797a3b76862f94662a865c6a83854f45c4 , because now I realize that commit actually landed in Fedora 24 as well. There is no difference in the `set_system_date_time()` or `set_system_time()` functions between Fedora 24 and Fedora 25. So my next guess is that the behaviour of pytz or datetime has changed between F24 and F25...

So...I've traced this down a bit farther. At least part of the problem seems to be the calculation of the epoch in `set_system_date_time()`:


    # Calculate the number of seconds between this time and timestamp 0
    epoch = tz.localize(datetime.datetime.fromtimestamp(0))

if you log the value of 'epoch' after that, it comes out different. Further, if you log the result of just calling `datetime.datetime.fromtimestamp(0)` at that point in the code, that result is different too. I tested with this:

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

on Fedora 24, we get:

01:05:22,081 INFO anaconda: datetime0: 1969-12-31 16:00:00
01:05:22,082 INFO anaconda: set_date: 2016-08-17 01:05:22-07:00
01:05:22,082 INFO anaconda: epoch: 1969-12-31 16:00:00-08:00
01:05:22,082 INFO anaconda: tz: America/Vancouver
01:05:22,000 INFO anaconda: System time set to Wed Aug 17 08:05:22 2016 UTC
01:05:22,001 INFO anaconda: datetime0: 1969-12-31 16:00:00
01:05:22,001 INFO anaconda: set_date: 2016-08-17 01:05:22-07:00
01:05:22,002 INFO anaconda: epoch: 1969-12-31 16:00:00-08:00
01:05:22,002 INFO anaconda: tz: America/Vancouver
01:05:22,000 INFO anaconda: System time set to Wed Aug 17 08:05:22 2016 UTC
01:05:22,001 INFO anaconda: datetime0: 1969-12-31 16:00:00
01:05:22,001 INFO anaconda: set_date: 2016-08-17 01:05:22-07:00
01:05:22,001 INFO anaconda: epoch: 1969-12-31 16:00:00-08:00
01:05:22,002 INFO anaconda: tz: America/Vancouver
01:05:22,000 INFO anaconda: System time set to Wed Aug 17 08:05:22 2016 UTC
01:05:22,000 INFO anaconda: Thread Done: AnaDateTimeThread (140176785712896)

On Fedora 25, we get:

08:05:23,513 INFO anaconda: datetime0: 1970-01-01 00:00:00
08:05:23,518 INFO anaconda: set_date: 2016-08-17 01:05:23-07:00
08:05:23,518 INFO anaconda: epoch: 1970-01-01 00:00:00-08:00
08:05:23,518 INFO anaconda: tz: America/Vancouver
00:05:23,000 INFO anaconda: System time set to Wed Aug 17 00:05:23 2016 UTC
00:05:23,001 INFO anaconda: datetime0: 1970-01-01 00:00:00
00:05:23,001 INFO anaconda: set_date: 2016-08-17 01:05:23-07:00
00:05:23,002 INFO anaconda: epoch: 1970-01-01 00:00:00-08:00
00:05:23,002 INFO anaconda: tz: America/Vancouver
00:05:23,000 INFO anaconda: System time set to Wed Aug 17 00:05:23 2016 UTC
00:05:23,001 INFO anaconda: datetime0: 1970-01-01 00:00:00
00:05:23,005 INFO anaconda: set_date: 2016-08-17 01:05:23-07:00
00:05:23,005 INFO anaconda: epoch: 1970-01-01 00:00:00-08:00
00:05:23,005 INFO anaconda: tz: America/Vancouver
00:05:23,000 INFO anaconda: System time set to Wed Aug 17 00:05:23 2016 UTC
00:05:23,001 INFO anaconda: Thread Done: AnaDateTimeThread (140500485011200)

note that datetime0 and epoch are different. Also note that on Fedora 24 the timestamps on all three sets of log messages (it seems `set_system_date_time` gets called three times, for some reason) are the same (they are, in fact, the correct current time in the local time zone - it was 01:05 when I ran the test), while on Fedora 25 the timestamps on the first set of log messages are not adjusted, while the timestamps on the second two *are* adjusted (to a time one hour out from the correct local time)...but all three calls seem to result in the same 'datetime0' and 'epoch'.

Rather bizarre...but I think we may be looking at a difference in what Python thinks the time is when we call `datetime.datetime.fromtimestamp(0)`.

I may just have been staring at this for too long, but it looks rather a lot to me like this code is badly wrong and F24 just happens to get things right more or less by dumb luck...

as I noted before, logging seems to show pretty clearly that the datetime spoke passes the current *local* time to `set_system_date_time()`. But then `set_system_date_time()` goes ahead and calls `tz.localize` on it...which seems clearly wrong, since you're supposed to use `tz.localize` to convert a UTC time to the current timezone (the docs say 'naive time', but what it basically does is apply the current timezones offset to the specified time).

It then does another thing which seems pretty clearly wrong per the 'datetime' docs - that is, this:

epoch = tz.localize(datetime.datetime.fromtimestamp(0))

the problem there is that datetime.fromtimestamp is documented as *already* attempting to adjust for the local timezone:

https://docs.python.org/3/library/datetime.html#datetime.datetime.fromtimestamp

"Return the local date and time corresponding to the POSIX timestamp"

so once again it winds up adjusting for local time *twice*.

All this would make sense if the date/time spoke passed a *UTC* time to `set_system_date_time()`, but it clearly does not. In Fedora 24 this seems to wind up actually giving the right delta in seconds, since both times are doubly adjusted, but in Fedora 25 it seems datetime.datetime.fromtimestamp(0) does not actually return the epoch in the local time zone, it returns the epoch in UTC. So the epoch gets singly adjusted but the current date/time gets doubly adjusted, and we wind up with a delta that's too short.

And jesus christ I'm too tired for this mess. I'm going to bed. Someone else figure it out.

Hmm, no, I was misunderstanding `localize()` there. It doesn't *change* the time you give it exactly, just turns it from a naive into an aware datetime object; I think it's actually correct. The real problem here is just that the datetime.datetime.fromtimestamp(0) call is not giving us the correct result, I think. It should be giving us a naive datetime object which is the date of the epoch with the correct offset for the current timezone - so for Pacific time it should give 1969-12-31 at 16:00 . Then when we run `localize` on it that turns it into an aware object with the correct timezone, thus unambiguously representing the epoch. In F24 it does this, in F25 it does not, it gives us a naive datetime object for 1970-01-01 at 00:00 - i.e. the epoch in UTC.

I believe I have a way to work around the problem:

diff --git a/pyanaconda/isys/__init__.py b/pyanaconda/isys/__init__.py
index 84d9569..ce7fcab 100644
--- a/pyanaconda/isys/__init__.py
+++ b/pyanaconda/isys/__init__.py
@@ -130,7 +130,7 @@ 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))
+    epoch = tz.fromutc(datetime.datetime.utcfromtimestamp(0))
     timestamp = (set_date - epoch).total_seconds()
 
     set_system_time(int(timestamp))


in a quick smoke test, this works...at least, it causes the system time to be set to the correct UTC time, and the date/time spoke now shows the correct local time (without my fix it shows a wrong local time). But it's more of a dodge than a fix; it doesn't explain what changed such that `datetime.datetime.fromtimestamp()` no longer does the right thing. I suspect there's actually a bug in setting the current timezone - so Python returns the 'wrong' date for the epoch because the system timezone is not actually set to Pacific. So now I guess I go to look at what does that and what's going wrong with it.

This bug seems to have shown up between 2016-06-16 and 2016-07-08 (that's the smallest delta I could find in the nightlies I have lying around). A 2016-06-16 nightly behaves like F24: the system clock is set to the correct time in UTC, and subsequent anaconda log messages have the correct local time as their timestamp. A 2016-07-08 nightly behaves like F25: the system clock is set to the wrong time in UTC.

My next suspect is this libtimezone update by David Shea:

http://koji.fedoraproject.org/koji/buildinfo?buildID=776644

I'm *suspecting* it may possibly have somehow resulted in the timezone so far as anaconda/python is concerned not being set when the timezone is changed in anaconda's configuration (either interactively by the user, or automatically by the geolocation stuff that runs on startup). That would explain all the symptoms: the way datetime.datetime.fromtimestamp() seems to think the system timezone is UTC, and the way anaconda log messages get whatever the system thinks the current UTC time is as their timestamp (they don't get a timezone adjustment).

It's pretty much a guess, but possibly this patch:

http://pkgs.fedoraproject.org/cgit/rpms/libtimezonemap.git/tree/0006-Do-not-use-tz_location_get_utc_offset.patch

could be to blame - perhaps anaconda was actually relying on the bug that fixed?

So I think I confirmed that it's something in libtimezonemap . I made some logging changes:

diff --git a/pyanaconda/isys/__init__.py b/pyanaconda/isys/__init__.py
index 84d9569..32f6d0f 100644
--- a/pyanaconda/isys/__init__.py
+++ b/pyanaconda/isys/__init__.py
@@ -29,6 +29,7 @@ import blivet.arch
 import time
 import datetime
 import pytz
+import os
 
 import logging
 log = logging.getLogger("anaconda")
@@ -130,6 +131,10 @@ 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
+    log.info("time.tzname: %s", ' '.join(time.tzname))
+    log.info("datetime0: %s", datetime.datetime.fromtimestamp(0))
+    log.info("datetimenow: %s", datetime.datetime.now())
+    log.info("env TZ: %s", os.getenv('TZ', 'not set'))
     epoch = tz.localize(datetime.datetime.fromtimestamp(0))
     timestamp = (set_date - epoch).total_seconds()
 
then built an updates.img with the older libtimezonemap package in it:

./scripts/makeupdates -t anaconda-25.20-1 -a /tmp/libtimezonemap-0.4.5-2.fc24.x86_64.rpm

booting Fedora 25 with that updates.img , everything behaves like Fedora 24: datetime0 is correctly adjusted to local time (1969-12-31 16:00:00), the system clock is set to the correct current time in UTC, and the anaconda log timestamps after the time is adjusted are correct.

So I started fiddling with the libtimezonemap patch set. The smallest change I can make to drop the patch I suspect - 0006-Do-not-use-tz_location_get_utc_offset.patch - also involves dropping 0013-Fix-the-calculation-of-time-zone-offsets.patch , 0018-Improve-the-location-selected-when-setting-the-timez.patch and 0022-Fix-compiler-warnings.patch , which all follow on from patch6 in some way. With those four patches dropped, but all others since 0.4.5-2 still applied, the bug is not present. The scratch build for that is http://koji.fedoraproject.org/koji/taskinfo?taskID=15287464 . The updates.img (against anaconda-25.20-1) is https://www.happyassassin.net/updates/1367647.tzmap04531.img .

Looking at it the other way, the smallest possible change I can make from 0.4.5-2 in order to produce the bug seems to be to include just Patch6 (slightly modified to account for the lack of Patch2) and Patch13 (which fixes an error in Patch6's math). With just those two patches included, the bug occurs. The scratch build for that is http://koji.fedoraproject.org/koji/taskinfo?taskID=15287614 . The updates.img is https://www.happyassassin.net/updates/1367647.tzmap04532.img .

So far my suspicion is that anaconda actually turns out to be relying on the behaviour that Patch6 fixes - the setting of the 'TZ' environment variable. This *does* seem to affect the output of timedate.timedate.fromtimestamp() in testing; if you fiddle with the value of os.environ['TZ'] and run timedate.timedate.fromtimestamp(0) , you can get different values. However, it's not totally clear-cut...the updates images also have the logging lines, and the logged result of os.getenv('TZ', 'not set') is never anything but 'not set'. I was expecting it to be set when the bug did not occur, and not set when the bug did occur...

Ok.

libtimezonemap-0.4.5-4.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2016-8988869509

built an update to test that:

https://www.happyassassin.net/updates/1367647.tzmap0454.img

and it seems to work; the behaviour returns to match F24's, the installed system's time is pretty much correct at boot. I can't confirm yet that it fixes 1367604 for stupid reasons I won't go into, but I'm pretty sure it should. Thanks.

libtimezonemap-0.4.5-4.fc25 has been pushed to the Fedora 25 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-2016-8988869509

libtimezonemap-0.4.5-4.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

What looks like the exact same bug is back in F26:

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

but the libtimezonemap 'fix' is still there. So I'm not sure why it's suddenly started happening again.