Bug 1126227

Created attachment 923665 [details]
File: anaconda-tb

Created attachment 923666 [details]
File: anaconda.log

Created attachment 923667 [details]
File: environ

Created attachment 923668 [details]
File: lsblk_output

Created attachment 923669 [details]
File: nmcli_dev_list

Created attachment 923670 [details]
File: os_info

Created attachment 923671 [details]
File: program.log

Created attachment 923672 [details]
File: storage.log

Created attachment 923673 [details]
File: syslog

Created attachment 923674 [details]
File: ifcfg.log

Created attachment 923675 [details]
File: packaging.log

Does this still occur with F21? I think this should be fixed by some changes that were made to mounting and unmounting repo sources.

I'll try to install Fedora 21 on hercules emulator.

With the DVD from http://s390.koji.fedoraproject.org/test/21/fedora/s390x/iso/Fedora-DVD-s390x-21.iso I get this error:

   876.985013! dasdconf.sh Warning: 0.0.0120 is already online, not configuring
   877.162739! dasdconf.sh Warning: 0.0.0180 is already online, not configuring
   877.284100! dasdconf.sh Warning: 0.0.0160 is already online, not configuring
   878.032872! net slccw0.0.0600: Connected with remote side
  1781.520163! dracut-initqueue 714!: Warning: Could not boot.
   Starting Dracut Emergency Shell...

Generating "/run/initramfs/rdsosreport.txt"

Entering emergency mode. Exit the shell to continue.
Type "journalctl" to view system logs.

You might want to save "/run/initramfs/rdsosreport.txt" to a USB stick or /boot
after mounting them and attach it to a bug report.

see attached hercules log file with output of dmesg, rdsosreport.txt and mount.

Created attachment 966542 [details]
hercules console output/log

okay, above crash in dracut initqueue processing happend because I specified ip=xxx,ctc0. It seems as the network device in Fedora 21 get renamed to something different. testing with boot command line "ro ramdisk_size=40000 rd.dasd=0.0.0120 rd.dasd=0.0.0160 rd.dasd=0.0.0180  root=live:/dev/dasdc plymouth.enable=0 selinux=0 text repo=cdrom:/dev/dasdb ip=192.168.5.3:192.168.5.4:192.168.5.4:32:s390x.example.com:slccw0.0.0600:none rd.znet=ctc,0.0.0600,0.0.0601,protocol=0" now.

and yes in anaconda the same crash happens with the Fedora 21 install DVD for s390x:

Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/pyanaconda/threads.py", line 227, in run
    threading.Thread.run(self, *args, **kwargs)
  File "/usr/lib64/python2.7/threading.py", line 766, in run
    Please make your choice from above: self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/ui/tui/spokes/source.py", line 78, in _initialize
    threadMgr.wait(THREAD_PAYLOAD)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/threads.py", line 112, in wait
    self.raise_if_error(name)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/threads.py", line 227, in run
    threading.Thread.run(self, *args, **kwargs)
  File "/usr/lib64/python2.7/threading.py", line 766, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/__init__.py", line 1246, in _runThread
    payload.updateBaseRepo(fallback=fallback, checkmount=checkmount)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/yumpayload.py", line 139, in inner_method
    ret = method(yum_payload, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/yumpayload.py", line 509, in updateBaseRepo
    url, mirrorlist, sslverify = self._setupInstallDevice(self.storage, checkmount)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/__init__.py", line 967, in _setupInstallDevice
    self.install_device = opticalInstallMedia(storage.devicetree)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/image.py", line 215, in opticalInstallMedia
    dev.format.unmount()
  File "/usr/lib/python2.7/site-packages/blivet/formats/fs.py", line 696, in unmount
    raise FSError("umount failed")
blivet.errors.FSError: umount failed

anaconda seems to want to umount the iso DVD device:

-> raise FSError("umount failed")
(Pdb) p self
Iso9660FS instance (0x3fff1b193c8) object id 9--
  type = iso9660  name = iso9660  status = True
  device = /dev/dasdb  uuid = 2014-12-08-19-10-18-00  exists = True
  options = ro  supported = True  formattable = False  resizable = False
  mountpoint = None  mountopts = None
  label = Fedora-21-s390x  size = 0 B  targetSize = 0 B

-> /dev/dasdb

but this device isn't mounted currently:

# mount | grep dasd
/dev/dasdc on /run/initramfs/live type squashfs (ro,relatime)

so what makes anaconda assume that above device should be mounted?

boot command line contains:
"repo=cdrom:/dev/dasdb root=live:/dev/dasdc"

I found this in the log /tmp/anaconda-tb-XXX log file:
19:21:40,838 INFO program: Running... udevadm settle --timeout=300
19:21:41,136 DEBUG program: Return code: 0
19:22:17,239 INFO program: Running... udevadm settle --timeout=300
19:22:17,880 DEBUG program: Return code: 0
19:22:18,435 INFO program: Running... mount -t iso9660 -o ro /dev/dasdb /tmp/tmpuzVXKH
19:22:20,561 DEBUG program: Return code: 0
19:22:20,893 INFO program: Running... udevadm settle --timeout=300
19:22:21,367 DEBUG program: Return code: 0
19:22:21,402 INFO program: Running... umount /tmp/tmpuzVXKH
19:22:22,124 DEBUG program: Return code: 0
19:22:22,176 INFO program: Running... mount -t iso9660 -o ro /dev/dasdb /mnt/install/source
19:22:22,573 DEBUG program: Return code: 0
19:22:22,839 INFO program: Running... umount /mnt/install/source
19:22:23,392 DEBUG program: Return code: 0
19:22:34,635 INFO program: Running... udevadm settle --timeout=300
19:22:35,753 DEBUG program: Return code: 0
19:22:36,330 INFO program: Running... udevadm settle --timeout=300
19:22:36,797 DEBUG program: Return code: 0
19:22:36,823 INFO program: Running... umount /mnt/install/source
19:22:37,151 INFO program: umount: /mnt/install/source: not mounted
19:22:37,180 DEBUG program: Return code: 32
19:22:37,214 INFO program: Running... lsof /mnt/install/source
19:22:40,686 DEBUG program: Return code: 1

So first /dev/dasdb is mounted on /mnt/install/source and then unmounted which works correclty but then unmounted again, which leads to this crash

This bug looks like a race condition between two thread in anaconda.

When I uncomment the lines in the blivet module (blivet/formats/fs.py) which throw above error:

    def unmount(self):
[...]
        udev.settle()
        rc = util.umount(self._mountpoint)
->      #if rc:
->      #    # try and catch whatever is causing the umount problem
->      #    util.run_program(["lsof", self._mountpoint])
->      #    raise FSError("umount failed")

        self._mountpoint = None

the installation doesn't crash any more, but anaconda fails to recognise the installation DVD.

Above race bug is most-likely exposed because I run the whole installation on the hercules emulator running on my slow laptop, so the time corridor of the race is probably huge compared to real hardware.

Luckily in anaconda there is this check in pyanaconda/packaging/__init__.py

        elif method.method == "cdrom" or (checkmount and not method.method):
            # Did dracut leave the DVD or NFS mounted for us?
->          device = blivet.util.get_mount_device(DRACUT_REPODIR)

            # Check for valid optical media if we didn't boot from one
            if not verifyMedia(DRACUT_REPODIR):
                self.install_device = opticalInstallMedia(storage.devicetree)

DRACUT_REPODIR is /run/install/repo.

So when anaconda is still in the startup phase I can switch to the shell and mount the installation DVD to /run/install/repo.
After that anaconda recognises the installation DVD and the installation of Fedora works correctly on the hercules s390 emulator!

The funny thing is that the current git version of dracut seems to do nothing with either DRACUT_REPODIR or DRACUT_ISODIR. both directories look like a leftover in anaconda and were probably removed in dracut, but luckily for me those were in anaconda!
DRACUT_REPODIR = "/run/install/repo"
DRACUT_ISODIR = "/run/install/source"

And this is what a cpuinfo looks like on s390 :-)

$ cat /proc/cpuinfo 
vendor_id       : IBM/S390
# processors    : 2
bogomips per cpu: 228.00
features	: esan3 zarch stfle msa ldisp eimm dfp edat etf3eh highgprs 
cache0          : level=1 type=Data scope=Private size=512K line_size=256 associativity=-1
cache1          : level=1 type=Instruction scope=Private size=512K line_size=256 associativity=-1
processor 0: version = 00,  identification = 002623,  machine = 2064
processor 1: version = 00,  identification = 102623,  machine = 2064

This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. 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 EOL if it remains open with a Fedora  'version'
of '20'.

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.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 20 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 this bug is closed as described in the policy above.

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 20 changed to end-of-life (EOL) status on 2015-06-23. Fedora 20 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.