Bug 873468

I guessed this might  be somehow related to the fix for 871129. http://jkeating.fedorapeople.org/updates.img has that fix reverted, so it'd be interesting for someone who can reproduce this more than I can to try some boots with that updates.img and see if the problem still occurs. Of course, the updates.img loading process itself may affect the bug :(

Tom Lane reckons this may be related to https://bugzilla.redhat.com/show_bug.cgi?id=870570 ...I'm not so sure. That bug is why *working around* this problem is a pain, but I'm not sure it causes this bug to happen in the first place.

Log files for this bug pulled from /tmp are being attached. One screenshot is also attached which shows the pre-hub network connection screen although it shows that the network is already connected.

Additional details:

Wired Connection, DHCP, anaconda 18.24 on TC7 image written to a USB drive using dd.

No additional parameters at boot time.

Created attachment 639062 [details]
pre-hub network connection screen showing connected.

Created attachment 639063 [details]
anaconda.log

Created attachment 639064 [details]
program.log

Created attachment 639065 [details]
syslog

Created attachment 639066 [details]
X.log

Created attachment 639067 [details]
ifcfg.log

Created attachment 639068 [details]
packaging.log

Created attachment 639069 [details]
anaconda-yum.conf

This is a race caused by slower DHCP and our poorer event logic.

DHCP default auto connection is run by NM.

1) connection is checked to decide if pre-hub network spoke should be used
2) DHCP may succeed now (e.g. while in language pre-hub spoke, or while initializing network pre-hub spoke)
3) pre-hub network spoke is displayed (may be in "Connected" as in comment #4 because DHCP succeeded in 2))
4) connection is checked
5) DHCP may succeed now (or a connection can be activated now in pre-hub network spoke by user)
6) Source spoke is updated if now there is connection and there was not connection in 4)

There are at least two issues rising from this logic:
A) pre-hub network spoke can be displayed in "Connected" state (see 3) above)
B) Source spoke is not updated because in 4) there was a connection. The workaround described in 3rd paragraph of description is needed.

A) is something that I'd leave to a separate bug. We'd need to check connection when the spoke is actually displayed (not just when all spokes are gathered) and skip the spoke in this case. This might also require better logic or connected event handling for Source spoke refresh.
B) can be fixed in some cases by moving the check from 4) (very close) to 1). 

Sending a patch for B) to anaconda-patches.

For a), I actually filed a bug on that (well, what's probably that) already:

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

I doubt this changes your diagnosis, but I just noticed, when this bug happens, in packaging.log, I see three messages of the form:

'failed to grab repo metadata for (repo): Cannot retrieve metalink for repository: (repo)/18/x86_64. Please verify its path and try again'

for fedora, updates, and updates-testing.

anaconda-18.27-1.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/anaconda-18.27-1.fc18

Package anaconda-18.27-1.fc18:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing anaconda-18.27-1.fc18'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-17823/anaconda-18.27-1.fc18
then log in and leave karma (feedback).

Package anaconda-18.28-1.fc18:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing anaconda-18.28-1.fc18'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-17823/anaconda-18.28-1.fc18
then log in and leave karma (feedback).

I just hit this bug, somehow, with 18.29. I think it may have something to do with sitting at the language screen for a long time, as I've seen it happen in that case before. This was with an image built for me by tflink with 18.29 - http://dl.fedoraproject.org/pub/alt/qa/18/20121115_f18b-systemd.noudevkill.x86_64.boot.iso .

Created attachment 645935 [details]
anaconda.log from 18.29 fail

Created attachment 645938 [details]
ifcfg.log from 18.29 fail

Created attachment 645944 [details]
packaging.log from 18.29 fail

Created attachment 645950 [details]
program.log from 18.29 fail

Created attachment 645952 [details]
storage.log from 18.29 fail

Created attachment 645953 [details]
X.log from 18.29 fail

Adam, would you remember if you went through pre-hub network spoke?

In TC9, with (1) pre-hub network spoke displayed *and* (2) waiting for connection to succed before continuing, it works for me.

Also I'd like to see syslog or anaconda.syslog byt I suppose it is gone.

ad (2): Leaving the spoke without waiting for connection really leads to Nothing selected, but this belongs to a wider issue of update of source spoke after connecting to network in hub. I'd prefer not to do this automatically. It's too much of guessing (i.e. you might want to connect because of ntp server, network storage, ...)

ad (1): If the spoke was *not* displayed you are probably hitting another race: dhcp is too slow to be available when payload (source) is fetched in payloadInitialize run from anaconda script before UI, but it is fast enough to succeed before checking network status for the pre-hub spoke - so it wouldn't be displayed (as in 1) from comment #12).

This doesn't seem easy, CCing Chris, he might have ideas to solve the issue in more generic way. I'll attach a patch for one approach I was poking around.

[1]
commit 605f7999294267e1d7c7dbfd90bf5ba4007ecf12
commit 2d39ad12dbf4e388da5576bf61ed2e00634e9166

Created attachment 646430 [details]
a patch for issues from comment #24

(In reply to comment #25)

> Created attachment 646430 [details]
> a patch for issues from comment #24

updates image with the patch for TC9 (anaconda 18.29)
http://rvykydal.fedorapeople.org/updates.payloadrace.img

radek: the last few times I've reproduced this, no, I did not go through pre-hub network spoke. it's been happening when I boot an image to test something and then switch context for a bit, so it sits at the language selection screen for a while. I hit it like five times in a row yesterday, so I may well be able to reproduce it today. if I do hit it I'll grab the syslog.

Created attachment 646651 [details]
syslog from fail with 18.29 (TC9)

Hit the bug first boot of TC9 on my RAID test config today. Here's syslog. I'll try it with the updates.img a few times later and see how it goes.

Adam thanks for your update and log. If you hit the bug again, please attach both anaconda.log and syslog from the installation so that I can compare timestamps to see if it is really the race condition I am suspecting. I am still unable to hit the contidion on my side (except for hacking anaconda with a sleep).

Will do, sorry, didn't realize you needed both from a single install.

Sorry, forgot to attach logs for this, but I've still been seeing it. I'll try and remember the logs next time.

Should be fixed in anaconda-18.32-1 (post Beta).

anaconda-18.32-1.fc18 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/anaconda-18.32-1.fc18

Package anaconda-18.32-1.fc18, pykickstart-1.99.22-1.fc18:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing anaconda-18.32-1.fc18 pykickstart-1.99.22-1.fc18'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-19380/pykickstart-1.99.22-1.fc18,anaconda-18.32-1.fc18
then log in and leave karma (feedback).

pykickstart-1.99.22-1.fc18, anaconda-18.35-1.fc18 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.

I have reproduced this bug with anaconda 18.37.5. It happens on every try. Because the workaround isn't easy to find (for general user this is show stopper) I propose this bug as blocker.

Created attachment 666694 [details]
Output from 'journalctl -a'

Created attachment 666695 [details]
anaconda.log

Created attachment 666696 [details]
ifcfg.log

Created attachment 666697 [details]
program.log

I have not seen this at all in recent tries...

This concerns waiting (or not doing so in this case) for slow dhcp. I am suspecting that fix bug 830434 is causing that NM considers connection waiting for dhcp as connected (via ipv6).
This updates image contains patch (for 18.37-5 but should work with later) that could confirm my assessment:
http://rvykydal.fedorapeople.org/updates.ipv6_873468.img

Discussed at 2012-12-21 blocker review meeting: http://meetbot.fedoraproject.org/fedora-bugzappers/2012-12-21/f18final-blocker-review-7.2012-12-21-18.33.log.txt . We think this case isn't likely to be very common, so for now, rejected as blocker but accepted as NTH: if further testing shows this happening frequently, we can re-consider.

I have not seen this in recent installation attempts using TC3. I think this could be considered fixed (?).

yeah, I haven't seen it either. Petr?

I can still reproduce it with 18.37.11. I run netinst written with dd on usb on UEFI.

this perhaps related to Bug 888946 ?

This message is a reminder that Fedora 18 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 18. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '18'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 18's end of life.

Thank you for reporting this issue and we are sorry that we may not be 
able to fix it before Fedora 18 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior to Fedora 18's end of life.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Fedora 18 changed to end-of-life (EOL) status on 2014-01-14. Fedora 18 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.