Bug 1126227 - FSError: umount failed
Summary: FSError: umount failed
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: anaconda
Version: 20
Hardware: s390x
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Anaconda Maintenance Team
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: abrt_hash:b309427c6eb461704e3a78abb5a...
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-08-03 19:17 UTC by Thomas Meyer
Modified: 2015-06-29 21:55 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-06-29 21:55:31 UTC


Attachments (Terms of Use)
File: anaconda-tb (107.16 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: anaconda.log (4.67 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: environ (394 bytes, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: lsblk_output (1.44 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: nmcli_dev_list (2.04 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: os_info (375 bytes, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: program.log (23.02 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: storage.log (39.30 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: syslog (19.78 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: ifcfg.log (1.55 KB, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
File: packaging.log (827 bytes, text/plain)
2014-08-03 19:17 UTC, Thomas Meyer
no flags Details
hercules console output/log (24.12 KB, text/plain)
2014-12-09 22:56 UTC, Thomas Meyer
no flags Details

Description Thomas Meyer 2014-08-03 19:17:30 UTC
Description of problem:


Version-Release number of selected component:
anaconda-20.25.15-1

The following was filed automatically by anaconda:
anaconda 20.25.15-1 exception report
Traceback (most recent call first):
  File "/usr/lib/python2.7/site-packages/blivet/formats/fs.py", line 626, in unmount
    raise FSError("umount failed")
  File "/usr/lib64/python2.7/site-packages/pyanaconda/image.py", line 212, in opticalInstallMedia
    dev.format.unmount()
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/__init__.py", line 875, in _setupInstallDevice
    self.install_device = opticalInstallMedia(storage.devicetree)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/yumpayload.py", line 500, in updateBaseRepo
    url, mirrorlist, sslverify = self._setupInstallDevice(self.storage, 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 204, in setup
    self.updateBaseRepo(fallback=not flags.automatedInstall)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/packaging/__init__.py", line 895, in payloadInitialize
    payload.setup(storage)
  File "/usr/lib64/python2.7/threading.py", line 764, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/threads.py", line 192, in run
    threading.Thread.run(self, *args, **kwargs)
FSError: umount failed

Additional info:
cmdline:        /usr/bin/python  /sbin/anaconda
cmdline_file:   ro ramdisk_size=40000 rd.dasd=0.0.0120 rd.dasd=0.0.0160 rd.dasd=0.0.0180 ip=192.168.5.3:192.168.5.4:192.168.5.4:32:s390x.example.com:ctc0:none rd.znet=ctc,0.0.0600,0.0.0601,protocol=0 root=live:/dev/dasdc plymouth.enable=0 selinux=0 text repo=cdrom:/dev/dasdb
executable:     /sbin/anaconda
hashmarkername: anaconda
kernel:         3.11.10-301.fc20.s390x
product:        Fedora
release:        Cannot get release name.
type:           anaconda
version:        20

Comment 1 Thomas Meyer 2014-08-03 19:17:34 UTC
Created attachment 923665 [details]
File: anaconda-tb

Comment 2 Thomas Meyer 2014-08-03 19:17:36 UTC
Created attachment 923666 [details]
File: anaconda.log

Comment 3 Thomas Meyer 2014-08-03 19:17:37 UTC
Created attachment 923667 [details]
File: environ

Comment 4 Thomas Meyer 2014-08-03 19:17:39 UTC
Created attachment 923668 [details]
File: lsblk_output

Comment 5 Thomas Meyer 2014-08-03 19:17:41 UTC
Created attachment 923669 [details]
File: nmcli_dev_list

Comment 6 Thomas Meyer 2014-08-03 19:17:42 UTC
Created attachment 923670 [details]
File: os_info

Comment 7 Thomas Meyer 2014-08-03 19:17:44 UTC
Created attachment 923671 [details]
File: program.log

Comment 8 Thomas Meyer 2014-08-03 19:17:47 UTC
Created attachment 923672 [details]
File: storage.log

Comment 9 Thomas Meyer 2014-08-03 19:17:49 UTC
Created attachment 923673 [details]
File: syslog

Comment 10 Thomas Meyer 2014-08-03 19:17:50 UTC
Created attachment 923674 [details]
File: ifcfg.log

Comment 11 Thomas Meyer 2014-08-03 19:17:52 UTC
Created attachment 923675 [details]
File: packaging.log

Comment 12 David Shea 2014-12-08 22:07:28 UTC
Does this still occur with F21? I think this should be fixed by some changes that were made to mounting and unmounting repo sources.

Comment 13 Thomas Meyer 2014-12-08 22:58:44 UTC
I'll try to install Fedora 21 on hercules emulator.

Comment 14 Thomas Meyer 2014-12-09 22:56:17 UTC
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.

Comment 15 Thomas Meyer 2014-12-09 22:56:50 UTC
Created attachment 966542 [details]
hercules console output/log

Comment 16 Thomas Meyer 2014-12-29 13:21:41 UTC
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.

Comment 17 Thomas Meyer 2014-12-29 19:03:49 UTC
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

Comment 18 Thomas Meyer 2014-12-29 19:40:45 UTC
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"

Comment 19 Thomas Meyer 2014-12-29 19:50:16 UTC
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

Comment 20 Thomas Meyer 2014-12-31 10:31:43 UTC
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

Comment 21 Fedora End Of Life 2015-05-29 12:33:17 UTC
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.

Comment 22 Fedora End Of Life 2015-06-29 21:55:31 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.