Bug 1127280

Created attachment 924496 [details]
File: anaconda-tb

Created attachment 924497 [details]
File: anaconda.log

Created attachment 924498 [details]
File: environ

Created attachment 924499 [details]
File: journalctl

Created attachment 924500 [details]
File: lsblk_output

Created attachment 924501 [details]
File: nmcli_dev_list

Created attachment 924502 [details]
File: os_info

Created attachment 924503 [details]
File: program.log

Created attachment 924504 [details]
File: storage.log

Created attachment 924505 [details]
File: ifcfg.log

Created attachment 924506 [details]
File: packaging.log

Can't install F21.

Using this image: https://kojipkgs.fedoraproject.org//work/tasks/2896/7242896/Fedora-Live-Workstation-x86_64-21-20140805.iso

From the program.log:
07:12:16,757 INFO program: Running... systemd-machine-id-setup
07:12:16,780 ERR program: Error running systemd-machine-id-setup: No such file or directory

This means that the systemd-machine-id-setup utility is not on the live image and thus also not installed to the machine. This could be an issue in the systemd package no longer providing this utility or the live image is created with a wrong kickstart file removing the utility somehow.

Another user experienced a similar problem:

I started anaconda installation (configured disk layout and everything) and after 10 seconds it crashed.

cmdline:        /usr/bin/python  /sbin/anaconda --liveinst --method=livecd:///dev/mapper/live-base
cmdline_file:   BOOT_IMAGE=vmlinuz0 initrd=initrd0.img root=live:CDLABEL=Fedora-Live-Workstation-x86_64-2 rootfstype=auto ro rd.live.image quiet  rhgb rd.luks=0 rd.md=0 rd.dm=0 
hashmarkername: anaconda
kernel:         3.16.0-1.fc21.x86_64
other involved packages: python-libs-2.7.8-3.fc21.x86_64
package:        anaconda-core-21.48.2-1.fc21.x86_64
product:        Fedora
reason:         OSError: [Errno 2] No such file or directory
release:        Fedora release 21 (Twenty One)
version:        21

Another user experienced a similar problem:

Installation of Workstation compose of 0805 - Anaconda crashes as soon as software installation stage begins.

cmdline:        /usr/bin/python  /sbin/anaconda --liveinst --method=livecd:///dev/mapper/live-base
cmdline_file:   BOOT_IMAGE=vmlinuz0 initrd=initrd0.img root=live:CDLABEL=Fedora-Live-Workstation-x86_64-2 rootfstype=auto ro rd.live.image quiet  rhgb rd.luks=0 rd.md=0 rd.dm=0 
hashmarkername: anaconda
kernel:         3.16.0-1.fc21.x86_64
other involved packages: python-libs-2.7.8-3.fc21.x86_64
package:        anaconda-core-21.48.2-1.fc21.x86_64
product:        Fedora
reason:         OSError: [Errno 2] No such file or directory
release:        Fedora release 21 (Twenty One)
version:        21

It is crashing on the add users spoke. I didn't click on either option in the spoke, just let anaconda do it's thing. It crashes once it reaches the "Software installation 0%" on the status bar.

Another user experienced a similar problem:

Hit during early package install of the 08-05 F21 Workstation nightly, as other QA folks are seeing.

cmdline:        /usr/bin/python  /sbin/anaconda --liveinst --method=livecd:///dev/mapper/live-base
cmdline_file:   BOOT_IMAGE=vmlinuz0 initrd=initrd0.img root=live:CDLABEL=Fedora-Live-Workstation-x86_64-2 rootfstype=auto ro rd.live.image quiet  rhgb rd.luks=0 rd.md=0 rd.dm=0 
hashmarkername: anaconda
kernel:         3.16.0-1.fc21.x86_64
other involved packages: python-libs-2.7.8-3.fc21.x86_64
package:        anaconda-core-21.48.2-1.fc21.x86_64
product:        Fedora
reason:         OSError: [Errno 2] No such file or directory
release:        Fedora release 21 (Twenty One)
version:        21

/usr/bin/systemd-machine-id-setup exists on the live image, so it's not that simple.

The code we're hitting isn't brand new, it's from April:

[adamw@xps13 anaconda (master)]$ git blame pyanaconda/packaging/livepayload.py | grep systemd-machine-id
1b260c0c (Colin Walters      2014-04-22 14:39:26 -0400 162)             iutil.execInSysroot("systemd-machine-id-setup", [])

iutil.execInSysroot is described as "Run an external program in the target root.", so I believe it's executing the command from the installer's environment, not from within the target root. Many calls of it don't provide a path, so I don't *think* the lack of a path is the problem, though we could try changing it to iutil.execInSysroot("/usr/bin/systemd-machine-id-setup", []) just to see if that helps.

It occurs to me that in fact the error might not be that there's a 'no such file' error trying to execute systemd-machine-id-setup, but that the execution of systemd-machine-id-setup *itself* fails with a 'no such file' error and that's just getting passed through into the logs? Here are all the 'opens' from an strace of systemd-machine-id-setup run in the live image itself:

[root@localhost tmp]# grep open smis
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/run/systemd/container", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/proc/cmdline", O_RDONLY|O_CLOEXEC) = 3
open("/etc/machine-id", O_RDWR|O_CREAT|O_NOCTTY|O_CLOEXEC, 0444) = 3

OK, never mind, I was wrong about that. I think I do know what's happening, though.

ultimately execInSysroot causes the command to be executed in a chroot of the 'Sysroot' directory (whatever that is, discovered by findSysroot() ). I'm fairly sure that at this point in time the Sysroot directory is /mnt/sysimage - if you look in program.log , that tree gets populated right before the command is run:

10:48:28,633 INFO program: Running... rsync -pogAXtlHrDx --exclude /dev/ --exclude /proc/ --exclude /sys/ --exclude /run/ --exclude /boot/*rescue* --exclude /etc/machine-id /mnt/install/source/ /mnt/sysimage
10:48:28,684 DEBUG program: Return code: 0
10:48:29,488 INFO program: Running... umount /mnt/install/source
10:48:29,495 INFO program: umount: /mnt/install/source: not mounted
10:48:29,495 DEBUG program: Return code: 32
10:48:29,497 INFO program: Running... systemd-machine-id-setup
10:48:29,504 ERR program: Error running systemd-machine-id-setup: No such file or directory

happily, when you run into this bug, /mnt/sysimage sticks around, you can look in it. And if I look in there, I see:

[liveuser@localhost usr]$ ls /mnt/sysimage/
boot  dev  etc  lost+found  proc  root  run  sys

note: no /bin at all (or /usr, for that matter).

The fact that the umount of /mnt/install/source fails in the logs seems interesting. Perhaps something else is somehow unmounting or removing it while the rsync is still in progress? But the rsync doesn't return an error, so I'm not sure about that.

/mnt/install/source is empty after you hit the bug (at least for me).

OK, we've just traced this one out and figured out the problem comes far earlier. the 'rsync' command is basically the installation process. Note that it takes about 90 microseconds; it does nothing, really. The reason why is pretty simple: /mnt/install/source is not mounted (that's why unmounting it fails). And it's empty because of this:

08:58:16,006 INFO program: Running... mount -t auto -o ro /dev/mapper/live-base /mnt/install/source
08:58:16,022 INFO program: mount: wrong fs type, bad option, bad superblock on /dev/mapper/live-base,
08:58:16,023 INFO program:        missing codepage or helper program, or other error
08:58:16,023 INFO program: 
08:58:16,023 INFO program:        In some cases useful info is found in syslog - try
08:58:16,024 INFO program:        dmesg | tail or so.

obviously trying to populate the sysroot from an empty directory is going to end in failure. We think this is most likely another fallout from the bug with live image compose where the disk image doesn't umount cleanly and then fsck runs and messes with it - sometimes that bug doesn't result in the image failing to compose (it depends on exactly how bad the errors in the image happen to be), and it seems reasonable to believe that this bug is caused by that one in a case where the compose managed to complete.

I'll try to run a test with an image from the same date that's not affected by that bug. If that works, that would be a pretty good indicator we're right about the cause.

Confirmed the bug does not happen with an LXDE image from the same compose run (2014-08-05 F21 x86_64) so this does seem quite likely to be related to the issues with Workstation image compose. For now let's leave it until 1127103 is resolved, then confirm that we don't run into this any more with subsequent images.

Discussed at the 2014-08-13 blocker review meeting:
http://meetbot.fedoraproject.org/fedora-blocker-review/2014-08-13/

This is blocked by bug 1127103, so we will consider this one once it is resolved, at the moment it seems directly caused by it. Punting for the moment.

Discussed at 2014-08-27 blocker review meeting. Seems no-one has run into this recently, indicating it was indeed a disguised consequence of #1127103: closing.

Another user experienced a similar problem:

during installation of fedora 21

cmdline:        /usr/bin/python  /sbin/anaconda --liveinst --method=livecd:///dev/mapper/live-base
cmdline_file:   BOOT_IMAGE=vmlinuz0 initrd=initrd0.img root=live:CDLABEL=Fedora-Live-WS-x86_64-21-5 rootfstype=auto ro rd.live.image quiet  rhgb rd.luks=0 rd.md=0 rd.dm=0 
hashmarkername: anaconda
kernel:         3.17.4-301.fc21.x86_64
other involved packages: python-libs-2.7.8-7.fc21.x86_64
package:        anaconda-core-21.48.21-1.fc21.x86_64
product:        Fedora"
reason:         OSError: [Errno 2] No existe el fichero o el directorio
release:        Fedora release 21 (Twenty One)
version:        Fedora