Bug 1099299

Also, to separate this from bug 1095891, this is real hardware, an i5 laptop (cat /proc/cpuinfo shows 4 processors).

Linux localhost.localdomain 3.14.4-200.fc20.x86_64 #1 SMP Tue May 13 13:51:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Created attachment 897495 [details]
screenshot

If the upgrade gets stuck after the reboot, then the packages on your system aren't really relevant; the important question is what packages were used when building upgrade.img.

'journalctl -b' output would help here, but I'd guess this is just a duplicate of bug 1095891.

Created attachment 897798 [details]
journalctl -b output

Same problem here on Acer TravelMate 8202WLMi today.

I did a yum update, then 
fedup --network rawhide --nogpgcheck --instrepo http://download.fedoraproject.org/pub/fedora/linux/development/rawhide/i386/os/

(Also had to refresh grub manually to get the feddup menu item to show up)

Experiencing same problem on freshly installed F20 as well, nothing done except a yum update -y and reboot before running fedup. Hardware is a Thinkpad T410 if it helps.

hi, 
I got same problem : stops at a start job is running for udev Kernel device manager .
with fedup-0.8.1-1.fc20 and doing:
fedup --network 21 --initrepo http://mirrors.eu.kernel.org/fedora/development/21/x86_64/os/

but switch to tty2 with crtl + alt + F2 and do 

systemctl stop systemd-udevd systemd-udevd-control.socket systemd-udevd-kernel.socket 

fedup performs the upgrade , although doesn't wrote almost anything in console , I just knew that is performing the upgrade following process and observing that hd is working hard , as usual in this situations .

Add me to the list.  I have the very same issue trying to upgrade F20 to rawhide/branched (F21).  Infinite loop involving udev/systemd.  Started process. Went to bed. After several hours the process still is looped from failure to failure and system isn't upgraded.  It is a fresh, bare metal install using btrfs.

Forgot to list Fedup version.

fedup-0.8.1-1.fc20.noarch

Upgraded to Fedup-0.8.1-2.fc21 but the failure continues.  About to attempt it again, using:

fedup --network 21 --instrepo http://dl.fedoraproject.org/pub/fedora/linux/development/21/x86_64/os/ --nogpgcheck

Thanks Sergio that workaround worked for me...

The journal service kept continuously restarting itself during the upgrade and journalctl -b states there are no journal files...

This is on an i3 laptop.

That workaround in comment 7 also worked for me on a Dell Inspiron 560 desktop.

Created attachment 929266 [details]
dmesg output

I'm experiencing the same issues.
Here is my dmesg output for further debugging.

(In reply to James Hogarth from comment #11)
> and journalctl -b states there are no journal files...

I have that problem too , I find out /var/log doesn't exist , so make something like mkdir /var/log ( I don't remember) puts journalctl -b  working 


(In reply to Simon Gerhards from comment #13)
> Created attachment 929266 [details]
> dmesg output
> 
> I'm experiencing the same issues.
> Here is my dmesg output for further debugging.

File /var/log/journal/df0e93939e8049039c89dc73e551dd64/system.journal corrupted or uncleanly shut down, renaming and replacing.

is the same problem /var/log doesn't exist .

The issue still happens when trying to upgrade from F20 to F21 Alpha RC1.

Comment 7 helps to solve the issue.

+1, this happened to me as well. Comment 7 worked around it.

*** Bug 1146219 has been marked as a duplicate of this bug. ***

Proposing as a Beta blocker, https://fedoraproject.org/wiki/Fedora_21_Beta_Release_Criteria#Upgrade_requirements :

"For each one of the release-blocking package sets, it must be possible to successfully complete an upgrade from a fully updated installation of the previous stable Fedora release with that package set installed."

also, we should commonbugs this for now.

OK I think I understand the issue here.  The error messages indicated and issue with /dev/log.  Under rawhide this is a symlink, in fedora 20 it is not.

Fedora20:

[wag@server ~]$ ls -l /dev/log
srw-rw-rw-. 1 root root 0 Sep 27 07:58 /dev/log

Rawhide:

[wag@rawhide-maine ~]$ ls -l /dev/log
lrwxrwxrwx. 1 root root 28 Sep 27 02:32 /dev/log -> /run/systemd/journal/dev-log

(In reply to Bill Gianopoulos from comment #19)
> OK I think I understand the issue here.  The error messages indicated and
> issue with /dev/log.  Under rawhide this is a symlink, in fedora 20 it is
> not.

I don't think this is the root cause of the hang, although it is what's causing the logging problems.

F20 systemd (v205) has `systemd-journald.socket`, which creates /dev/log.
F21 systemd (v215) has `systemd-journald-dev-log.socket`, which creates /run/systemd/journal/dev-log and symlinks /dev/log to it.
So when we switch from F20 to F21, systemd-journald-dev-log.socket fails because it can't make the symlink.

But fixing the sockets doesn't make the upgrade start, so I'm pretty sure this is a separate problem, and will need to be tracked in a separate bug.

As far as I can tell, the problem is that systemd never gets notification that udevd (and/or journald?) have started - which is why systemd keeps trying to restart it.

strace shows that udevd is unlinking /run/udev/queue and doing epoll_wait(), so it's definitely gotten into the mainloop. But systemctl shows the status as "activating (start)", which I'm pretty sure means it's still waiting for the sd_notify(1, "READY=1")..

But then eventually the watchdog timeout hits, and systemd kills the existing job and tries to restart udevd. Hence the loop.

Dupe of bug 1146140 ?

rather the other way around, as this one is four months older and has much more detail and corroboration. I will close that as a dupe of this.

*** Bug 1146140 has been marked as a duplicate of this bug. ***

but had I asked on the other bug, I'm not sure somebody would have confirmed ;-) either way doesn't matter.

Discussed at 2014-10-03 blocker review meeting: http://meetbot.fedoraproject.org/fedora-blocker-review/2014-10-03/f21-blocker-review.2014-10-03-15.58.log.txt . Accepted as a blocker, this clearly violates the criteria as cited in c#18.

Ping systemd devs - are you aware this is a Beta release blocker and needs attention with priority? Thanks!

Sorry, I somehow missed this bug. I'll look into it.

(In reply to Will Woods from comment #20)
> (In reply to Bill Gianopoulos from comment #19)
> > OK I think I understand the issue here.  The error messages indicated and
> > issue with /dev/log.  Under rawhide this is a symlink, in fedora 20 it is
> > not.
> 
> I don't think this is the root cause of the hang, although it is what's
> causing the logging problems.
> 
> F20 systemd (v205) has `systemd-journald.socket`, which creates /dev/log.
> F21 systemd (v215) has `systemd-journald-dev-log.socket`, which creates
> /run/systemd/journal/dev-log and symlinks /dev/log to it.
> So when we switch from F20 to F21, systemd-journald-dev-log.socket fails
> because it can't make the symlink.
> 
> But fixing the sockets doesn't make the upgrade start, so I'm pretty sure
> this is a separate problem, and will need to be tracked in a separate bug.
Yep, it seems your analysis is right. I'll add a ExecStartPre=/bin/rm -f /dev/log to the socket unit. This should be enough to fix the socket issue.

But as you say, this is a side thing, not the root cause of problems.

> (In reply to Will Woods from comment #21)
> As far as I can tell, the problem is that systemd never gets notification
> that udevd (and/or journald?) have started - which is why systemd keeps
> trying to restart it.
systemd notify socket is not opened properly. From the attached logs:

May 21 03:38:59 localhost.localdomain systemd[1]: bind() failed: Address already in use

I think that this is the real problem. Most likely, the notify socket is serialized but not deserialized properly, so the second systemd has it open but is not aware of it. The code seems correct (and also seems to function correctly most of the time), so I'm really at loss what could be going on
here.

I'll apply a big hammer here and unlink the socket path and attempt to bind again. This might cause a loss of some notify messages, but we should survive that.

> strace shows that udevd is unlinking /run/udev/queue and doing epoll_wait(),
> so it's definitely gotten into the mainloop. But systemctl shows the status
> as "activating (start)", which I'm pretty sure means it's still waiting for
> the sd_notify(1, "READY=1")..
> 
> But then eventually the watchdog timeout hits, and systemd kills the
> existing job and tries to restart udevd. Hence the loop.
This is consistent with systemd not receiving notify messages.

(In reply to Zbigniew Jędrzejewski-Szmek from comment #29)
> > (In reply to Will Woods from comment #21)
> > As far as I can tell, the problem is that systemd never gets notification
> > that udevd (and/or journald?) have started - which is why systemd keeps
> > trying to restart it.
> systemd notify socket is not opened properly. From the attached logs:
> 
> May 21 03:38:59 localhost.localdomain systemd[1]: bind() failed: Address
> already in use
> 
> I think that this is the real problem. Most likely, the notify socket is
> serialized but not deserialized properly, so the second systemd has it open
> but is not aware of it. The code seems correct (and also seems to function
> correctly most of the time), so I'm really at loss what could be going on
> here.

Keep in mind that upgrades involve two versions of systemd - the initramfs is F21 (systemd v215ish) but the system root has systemd v205 (or older), and that's what's doing the deserialization.

Is it possible there have been changes to that code since v205? Or maybe other system changes that would make the bind() fail? Different socket paths? SELinux policy changes?

> I'll apply a big hammer here and unlink the socket path and attempt to bind
> again. This might cause a loss of some notify messages, but we should
> survive that.

If I can help find a more precise fix, let me know.. but otherwise.. hammer away! And thanks for looking into this.

(In reply to Will Woods from comment #30)
> Keep in mind that upgrades involve two versions of systemd - the initramfs
> is F21 (systemd v215ish) but the system root has systemd v205 (or older),
> and that's what's doing the deserialization.
I was think so too, but actually in the posted logs both versions are the
same (212). The location of the socket and other things changed in between
systemd version, but I don't think this is relevant here.

Right, but the logs might not be reliable - aren't we not getting logs from v205 because of the /dev/log funnies? The entire process goes:

F21 initramfs -> F20 system (bring up disks) -> F21 initramfs (start upgrade)

So we'd normally expect to see v212 starting up twice with v205 in the middle, but if v205 can't log properly..

A test build is here http://koji.fedoraproject.org/koji/taskinfo?taskID=7889255.

So, systemd that has issues is the one from the fedup initramfs. I'm not sure how to test that this now. Normal F21 installation boots fine with this update, so I'd be inclined to just push it and assume that it fixes this bug. It only contains for patches, one to increase logging, one for the /dev/log issue from this bug, and two for other issues. Please advise.

(In reply to Zbigniew Jędrzejewski-Szmek from comment #33)
> A test build is here
> http://koji.fedoraproject.org/koji/taskinfo?taskID=7889255.
> 
> So, systemd that has issues is the one from the fedup initramfs. I'm not
> sure how to test that this now. Normal F21 installation boots fine with this
> update, so I'd be inclined to just push it and assume that it fixes this
> bug. It only contains for patches, one to increase logging, one for the
> /dev/log issue from this bug, and two for other issues. Please advise.

What are two other issues? Just to avoid surprises if it's anything bigger that can affect Beta. And thanks for attention to this bug!

From the attached logs:

From this bug:
May 21 03:38:59 localhost.localdomain systemd[1]: bind() failed: Address already in use

Patch #1 removes the notification socket and binds again.

From 1146140 (one of the duplicates):

Jan 13 20:37:03 raptor systemd[1]: Switching root.
Jan 13 20:37:03 raptor systemd[1]: Failed to umount old root dir /system-upgrade-root/mnt: No such file or directory
Jan 13 20:37:03 raptor systemd[1]: Failed to switch root, ignoring: No such file or directory

Patch #2 only warns about the unmount failing and continues to boot from the new root.

From comment #20:
F20 systemd (v205) has `systemd-journald.socket`, which creates /dev/log.
F21 systemd (v215) has `systemd-journald-dev-log.socket`, which creates /run/systemd/journal/dev-log and symlinks /dev/log to it.
So when we switch from F20 to F21, systemd-journald-dev-log.socket fails because it can't make the symlink.

Patch #3 removes /dev/log before attempting to create the symlink.

Patch #4 replaces some log_debug with log_warning.

releng should be able to build a test upgrade image for us, I believe, if we ask. CCing releng folks.

changing version to 21, as the fix needs to go in 21/Rawhide AIUI, not 20.

(In reply to Adam Williamson (Red Hat) from comment #36)
> releng should be able to build a test upgrade image for us, I believe, if we
> ask. CCing releng folks.

I think the easiest way to test this would be to submit an update with the fix, and add a buildroot override, then check the next days nightly compose. I think the compose should use the buildroot override version and you should be able to test the upgrade.img there.

I tried testing this with a locally-built upgrade.img but it segfaults, I'm guessing I just don't have a full/clean creation environment. zbysek, could you just submit the build as an update and we'll run the next TC/RC build with it and hope it does the job? Thanks.

initscripts-9.56.1-2.fc21, systemd-216-5.fc21 has been submitted as an update for Fedora 21.
https://admin.fedoraproject.org/updates/FEDORA-2014-12688/initscripts-9.56.1-2.fc21,systemd-216-5.fc21

Package initscripts-9.56.1-2.fc21, systemd-216-5.fc21:
* should fix your issue,
* was pushed to the Fedora 21 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing initscripts-9.56.1-2.fc21 systemd-216-5.fc21'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2014-12688/initscripts-9.56.1-2.fc21,systemd-216-5.fc21
then log in and leave karma (feedback).

I'm confused about how to test it. The problem is that fedup won't upgrade from 20 to 21, and I'm still on 20. I don't see how I can install initscripts and systemd from 21's updates-testing repository when I'm not on 21.

When updates systemd is in upgrade.img, the upgrade should succeed. So the test is to wait for upgrade.img to be released and then try to upgrade. I'm not sure when the updated upgrade.img will be crated.

There will be an updated upgrade.img as part of the 21 Beta RC1 compose, inside the 21 Beta RC1 tree in stage/. The upgrade.img in the development/21 tree on the mirrors will get the change once it reaches stable. Assuming the fix works, the /releases/test/21-Beta tree on the mirrors will also contain a fixed upgrade.img when it comes into being (at the release of Beta).

I confirmed this is fixed with Beta RC1. A fedup run against the Beta_RC1 tree works successfully.

initscripts-9.56.1-2.fc21, systemd-216-5.fc21 has been pushed to the Fedora 21 stable repository.  If problems still persist, please make note of it in this bug report.

This bug need to be reopened until you are either willing or able to provide a fedup command that will actually work.  The one I complained about in bug 1146219 still fails with the same issue.

Oh and the one you suggested does not work either because the repository does not exist.

I don;t intend to be a hard-ass about this but it is close to beta release and I could test this on various platforms if you would explain exactly how that is actually possible.

I submitted Bug 1158246 on this issue.

fedup --network 21 --instrepo https://dl.fedoraproject.org/pub/alt/stage/21_Beta_RC1/Server/x86_64/os/

Note that if you try that and have any issue *other* than the loop when starting udev, that is not the same bug as this one. There are some other known issues in fedup at present that are not this issue:

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

if you hit one of those, please follow that report. If you hit something else, please check https://bugz.fedoraproject.org/fedup and if you don't see it there, file a new report. Thanks.

OK no that is what I would have liked to have seen in the bug close report.  Going to beta in a week need to get enough info to people like me to test before then.  Just tying to say, this is an open source project with an open attitude towards who can contribute. Especially in a situation where we took more time for this release than normal and the release is months behind.  now that we are within a week of the release better to get input than to look really stupid.

Oh just to give a frame of reference I do work on another open source project where we also look stupid  in this same manner.  just trying to say we need to try to avoid this issue.

The fedup test cases do actually include the instructions:

https://fedoraproject.org/wiki/QA:Testcase_upgrade_fedup_cli_previous_desktop

I did use the instructions here and that worked for me.  But I do feel that my bug 1146219 was duped to this and therefore closed without what I feel was an adequate answer.  You can easily disagree but my feeling is this is an open source project and if people complain about an issue and are trying to help get things resolved before beta you should help instead of hinder their efforts.

 Just my opinion,  I am probably wrong!

I'm sorry, but I don't know what 'adequate answer' you were expecting - that bug is clearly the same bug as this bug, I thought that was sufficiently self-evident not to need a comment.

I confirm that this specific problem has been addressed. It lead to a bunch of others, but that's another story.

(In reply to Adam Williamson (Red Hat) from comment #57)
> I'm sorry, but I don't know what 'adequate answer' you were expecting - that
> bug is clearly the same bug as this bug, I thought that was sufficiently
> self-evident not to need a comment.

I apologize.  I had misread a comment and thought this was also fixed in the current test/21-Alpha build.

Reopening, this bug is still/again in F21 Beta RC2 (encountered with colleague on bare metal and virtualized).

Created attachment 951811 [details]
Fedup log

Created attachment 951812 [details]
Photo of fail messages

(In reply to Lukas Brabec from comment #62)
> Created attachment 951812 [details]
> Photo of fail messages
It's the old systemd that is failing, I guess when it switches back to F20 system to mount stuff. It seems that I should do an update for F20 with those patches which were applied to F21. Should be ready tonight.

It turns out the problem here was a SNAFU in RC2 compose: due to an unfortunate timing overlap, RC2 got the old systemd / initscripts builds without the fix for this. There's no work to do for the devs here, we just need to spin a new RC with the fix properly included.

'fedup --network 21 --instrepo ...RC4/...' seems to work fine.

It works for me with RC4. I tried fedup 0.9.