Bug 1562185 - All Rawhide image composes fail with "Anaconda DBus modules failed to start on time"
Summary: All Rawhide image composes fail with "Anaconda DBus modules failed to start o...
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: anaconda
Version: rawhide
Hardware: All
OS: Linux
unspecified
urgent
Target Milestone: ---
Assignee: Anaconda Maintenance Team
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: AcceptedBlocker
Depends On:
Blocks: F29BetaBlocker
TreeView+ depends on / blocked
 
Reported: 2018-03-29 17:50 UTC by Adam Williamson
Modified: 2018-05-01 23:41 UTC (History)
11 users (show)

Fixed In Version: anaconda-29.7-1.fc29
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-04-29 22:12:13 UTC


Attachments (Terms of Use)

Description Adam Williamson 2018-03-29 17:50:45 UTC
Since anaconda-29.6-1.fc29 landed in Rawhide, all live and disk image composes are failing with errors like this:

2018-03-29 11:06:19,944 INFO livemedia-creator: 11:06:19 Anaconda DBus modules failed to start on time.
2018-03-29 11:06:19,945 INFO livemedia-creator: 11:06:19 Anaconda DBus modules failed to start on time.

See e.g. https://pagure.io/dusty/failed-composes/issue/114 for task links, with anaconda logs (in the live media tasks, you won't find any in the image build tasks). anaconda.dbus.log seems to contain a traceback:

Traceback (most recent call last):
  File "/usr/lib64/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib64/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/storage/__main__.py", line 4, in <module>
    from pyanaconda.modules.storage.storage import StorageModule
  File "/usr/lib64/python3.6/site-packages/pyanaconda/modules/storage/storage.py", line 23, in <module>
    from pyanaconda.modules.storage.disk_initialization import DiskInitializationModule
ModuleNotFoundError: No module named 'pyanaconda.modules.storage.disk_initialization'

This is an automatic F29 Beta blocker, as it prevents the compose of many release-blocking images: https://fedoraproject.org/wiki/QA:SOP_blocker_bug_process#Automatic_blockers

Comment 1 Adam Williamson 2018-03-29 17:58:30 UTC
I think this is a Makefile issue; the module's in git master, but doesn't get into the tarball or the package. We just need to add the right bits to get it into the tarball. I'll send a PR soon.

Comment 3 Martin Kolman 2018-03-29 18:23:56 UTC
(In reply to Adam Williamson from comment #2)
> vponkovca and mkolman beat me to it:
> 
> https://github.com/rhinstaller/anaconda/commit/
> 9892d86f5401af671d07234a6dcac93b1fd20ac3
> https://github.com/rhinstaller/anaconda/commit/
> b1f579a7b725fe6ced3b6ecf8dcb03b333e24ef2
> 
> This will be fixed in 29.7.

Yep & already built: https://koji.fedoraproject.org/koji/taskinfo?taskID=26044096

Comment 4 Adam Williamson 2018-04-29 22:12:13 UTC
We have had Rawhide composes since then, so let's close this.

Comment 5 Torgeir Veimo 2018-05-01 11:09:34 UTC
I see this on fedora 27 and fedora 28 beta 1.3 and beta nightly as of 20180429, thus I'm completely unable to install fedora. Which iso can I use to install which doesn't have this problem?

Comment 6 Adam Williamson 2018-05-01 15:19:52 UTC
I don't think you could possibly be seeing this on Fedora 27. The code that results in this error (and the error itself) do not exist in F27. It is new code in F28.

Comment 7 Torgeir Veimo 2018-05-01 15:25:33 UTC
Ok, I'll try another F27 install to check if I remember correctly. I see F28 was just released. Is there any build that contains this fix, nightly, rawhide etc that I can try out?

Comment 8 Adam Williamson 2018-05-01 15:28:37 UTC
No F27 or F28 build was ever affected by this, AFAIK. If you're having problems with F27 or F28 installs, none of them are this. You must be hitting some other bug. I can't help you with that until I have any kind of information at all that might indicate what bug that might be.

F28 does have the "Anaconda DBus modules failed to start on time" error, so you could possibly be seeing that error on F28 (not F27). But if so, the cause must be something else. It's a fairly generic error message, it could appear for various reasons.

Comment 9 Torgeir Veimo 2018-05-01 15:50:06 UTC
Ok, I guess I was wrong on F27. The installer silently fails. If I do sudo -i and run anaconda manually, I get an encoding error. https://pastebin.com/qZWiXxWw

Comment 10 Torgeir Veimo 2018-05-01 16:32:08 UTC
Just tested F28 now, with the same result. Running the installer from the drawer / activities doesn't work, without any error message. Running in a terminal after sudo -i results in the same errors, 

Anaconda DBus modules failed to start on time. 

There's no other error details. Should I open another bug with details?

Comment 11 Torgeir Veimo 2018-05-01 16:33:49 UTC
I do see the 'utf-8' codec can't decode byte 0xc0 in position 0 in the logs as well on F28, am wondering if that can be the underlying issue?

Comment 12 Adam Williamson 2018-05-01 19:35:05 UTC
Torgeir: yes, almost certainly it is. Basically it looks like this is causing blivet, which acts as the storage backend for anaconda, to fall over when examining udev info for storage devices as part of storage initialization; in F28 and later anaconda was modularized to some extent, so this is manifesting as the storage initializing 'module' failing to start up. It's almost certainly the same basic bug.

I'm gonna repaste your traceback here, as it'll expire from pastebin at some point:

[root@hackintosh ~]# anaconda --loglevel debug
Starting installer, one moment...
anaconda 27.20.4-1 for anaconda bluesky (pre-release) started.
 * installation log files are stored in /tmp during the installation
 * shell is available on TTY2 and in second TMUX pane (ctrl+b, then press 2)
 * when reporting a bug add logs from /tmp as separate text/plain attachments
Traceback (most recent call last):
  File "/sbin/anaconda", line 658, in <module>
    matched = device_matches("LABEL=OEMDRV", disks_only=True)
  File "/usr/lib64/python3.6/site-packages/pyanaconda/storage_utils.py", line 897, in device_matches
    single_spec_matches = udev.resolve_glob(full_spec)
  File "/usr/lib/python3.6/site-packages/blivet/udev.py", line 155, in resolve_glob
    for dev in get_devices():
  File "/usr/lib/python3.6/site-packages/blivet/udev.py", line 73, in get_devices
    dev = device_to_dict(device)
  File "/usr/lib/python3.6/site-packages/blivet/udev.py", line 48, in device_to_dict
    result = dict(device.properties)
  File "/usr/lib/python3.6/site-packages/pyudev/device/_device.py", line 1085, in __getitem__
    return ensure_unicode_string(value)
  File "/usr/lib/python3.6/site-packages/pyudev/_util.py", line 67, in ensure_unicode_string
    value = value.decode(sys.getfilesystemencoding())
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xc0 in position 0: invalid start byte
[root@hackintosh ~]#

From that traceback, this actually looks like it's in pyudev, so can you please file a new bug against 'python-pyudev' to report this? However, I think we're going to need to figure out what the actual device is, and what property of the device pyudev is choking on; clearly what's going on here is it's encountering a rather unusual value as a property of a udev device (one that's not, apparently, valid UTF-8).

Thanks!

Comment 13 Torgeir Veimo 2018-05-01 23:41:19 UTC
Ok, bug id is 1573555.


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