Version-Release number of selected component: anaconda-25.20.1-1 Additional info: reporter: libreport-2.8.0 addons: com_redhat_docker, com_redhat_kdump cmdline: /usr/bin/python3 /sbin/anaconda cmdline_file: BOOT_IMAGE=vmlinuz initrd=initrd.img inst.stage2=hd:LABEL=Fedora-S-dvd-x86_64-25 quiet executable: /sbin/anaconda hashmarkername: anaconda kernel: 4.8.0-0.rc6.git0.1.fc25.x86_64 product: Fedora release: Cannot get release name. type: anaconda version: 25 Truncated backtrace: Traceback (most recent call last): File "/usr/lib64/python3.5/site-packages/gi/overrides/BlockDev.py", line 420, in wrapped ret = orig_obj(*args, **kwargs) File "/usr/lib64/python3.5/site-packages/gi/overrides/BlockDev.py", line 228, in lvm_thpoolcreate return _lvm_thpoolcreate(vg_name, lv_name, size, md_size, chunk_size, profile) GLib.GError: g-io-error-quark: Failed to call the 'LvCreateLinear' method on the '/com/redhat/lvmdbus1/Vg/0' object: Timeout was reached (24) During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib64/python3.5/site-packages/pyanaconda/threads.py", line 251, in run threading.Thread.run(self, *args, **kwargs) File "/usr/lib64/python3.5/threading.py", line 862, in run self._target(*self._args, **self._kwargs) File "/usr/lib64/python3.5/site-packages/pyanaconda/install.py", line 204, in doInstall turn_on_filesystems(storage, mount_only=flags.flags.dirInstall, callbacks=callbacks_reg) File "/usr/lib/python3.5/site-packages/blivet/osinstall.py", line 1112, in turn_on_filesystems storage.do_it(callbacks) File "/usr/lib/python3.5/site-packages/blivet/threads.py", line 45, in run_with_lock return m(*args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/blivet.py", line 163, in do_it self.devicetree.actions.process(callbacks=callbacks, devices=self.devices) File "/usr/lib/python3.5/site-packages/blivet/actionlist.py", line 48, in wrapped_func return func(obj, *args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/actionlist.py", line 322, in process action.execute(callbacks) File "/usr/lib/python3.5/site-packages/blivet/threads.py", line 45, in run_with_lock return m(*args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/deviceaction.py", line 318, in execute self.device.create() File "/usr/lib/python3.5/site-packages/blivet/threads.py", line 45, in run_with_lock return m(*args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/devices/storage.py", line 443, in create self._create() File "/usr/lib/python3.5/site-packages/blivet/threads.py", line 45, in run_with_lock return m(*args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/devices/lvm.py", line 1792, in decorated found, ret = self._try_specific_call(meth.__name__, *args, **kwargs) # pylint: disable=no-member File "/usr/lib/python3.5/site-packages/blivet/threads.py", line 45, in run_with_lock return m(*args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/devices/lvm.py", line 1777, in _try_specific_call ret = getattr(cls, name)(self, *args, **kwargs) File "/usr/lib/python3.5/site-packages/blivet/devices/lvm.py", line 1526, in _create profile=profile_name) File "/usr/lib64/python3.5/site-packages/gi/overrides/BlockDev.py", line 441, in wrapped raise transform[1](msg) gi.overrides.BlockDev.LVMError: Failed to call the 'LvCreateLinear' method on the '/com/redhat/lvmdbus1/Vg/0' object: Timeout was reached
Created attachment 1204229 [details] File: anaconda-tb
Created attachment 1204230 [details] File: anaconda.log
Created attachment 1204231 [details] File: backtrace
Created attachment 1204232 [details] File: description
Created attachment 1204233 [details] File: dnf.librepo.log
Created attachment 1204234 [details] File: environ
Created attachment 1204235 [details] File: hawkey.log
Created attachment 1204236 [details] File: ifcfg.log
Created attachment 1204237 [details] File: lsblk_output
Created attachment 1204238 [details] File: lvm.log
Created attachment 1204239 [details] File: nmcli_dev_list
Created attachment 1204240 [details] File: packaging.log
Created attachment 1204241 [details] File: program.log
Created attachment 1204242 [details] File: storage.log
Created attachment 1204243 [details] File: syslog
This looks like a bug in the lvmdbus1 service, but I'll let you be the judge of that. Also adding Tony since it may end up on his plate.
In lvm dbus we never return an actual timeout. You can specify a timeout length until a job object path is returned. For Vg.LvCreateLinear parameter 4 is the timeout until a job is created. timeout value has the following meaning: -1 == Wait forever until we get a result or error 0 == Return a job immediately >0 == Number of seconds we wait before we return a job However, all client dbus libraries have a timeout value and it's very important that the client library timeout > what you pass as an argument to lvm dbus. Default is usually ~25 seconds. Otherwise the client will timeout waiting before the operation is complete or a job is returned. Based on the above debug message it looks like a client side timeout occurred.
So just for a bit of background info for the newcomers: we use an automated system called openQA for testing Fedora: https://openqa.fedoraproject.org/ It runs a bunch of tests, many of which are installation tests, and of course almost all of those (except the ones which specifically test non-LVM installs) create LVM setups. It runs a little over 100 tests on each Fedora compose (we get two composes nightly - one for Branched (i.e. F25), one for Rawhide), probably 60-70 of those involve an installation. Around once in every, oh, 1.5 composes or so - so about 1 in every 100 install tests, give or take - we run into this error. It doesn't happen reliably in any specific test. It's probably more just a case of the host where the test is being run getting really busy with I/O or something. Each test runs in a VM, and we have four systems hosting test VMs (two production, two staging); three of them run up to four test VMs simultaneously, the fourth (which has more CPU cores) runs up to ten test VMs simultaneously. Each of these 'worker hosts' uses spinning rust storage, I think. So I guess the ten worker host, especially, could be working its disks pretty hard if all/most of the tests it happens to be running at any given time happen to be at a point where they're generating a lot of I/O.
A PR with what I believe causes the issue: https://github.com/rhinstaller/libblockdev/pull/123
(In reply to Vratislav Podzimek from comment #19) > A PR with what I believe causes the issue: > https://github.com/rhinstaller/libblockdev/pull/123 Merged.
libblockdev-1.9-3.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-9305da925f
libblockdev-1.9-4.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.
Saw a similar traceback on Rawhide in openQA stg today: https://openqa.stg.fedoraproject.org/tests/63334 gi.overrides.BlockDev.LVMError: Failed to call the 'LvCreate' method on the '/com/redhat/lvmdbus1/Vg/0' object: Timeout was reached
(In reply to Adam Williamson from comment #23) > Saw a similar traceback on Rawhide in openQA stg today: > > https://openqa.stg.fedoraproject.org/tests/63334 > > gi.overrides.BlockDev.LVMError: Failed to call the 'LvCreate' method on the > '/com/redhat/lvmdbus1/Vg/0' object: Timeout was reached Interesting. But unless something has changed in lvmdbusd, the libblockdev's side should be okay, because it tells lvmdbusd to return a job object path in a second which is definitely shorter than the DBus timeout. Looks like lvmdbusd failed to provide the answer. If this appears more than once we definitely need to debug the issue more thoroughly.
(In reply to Vratislav Podzimek from comment #24) > Interesting. But unless something has changed in lvmdbusd, the libblockdev's > side should be okay, because it tells lvmdbusd to return a job object path > in a second which is definitely shorter than the DBus timeout. Looks like > lvmdbusd failed to provide the answer. If this appears more than once we > definitely need to debug the issue more thoroughly. It looks like the timeout is set to 5000 or 5 seconds for the client library and the API timeout == 1 second. This should be plenty of time when accounting for the imprecise nature of the lvmdbusd timeout implementation. Is blivet running multiple operations concurrently to configure the storage or is it sequentially making changes? Trying to understand any contributing factors.
(In reply to Tony Asleson from comment #25) > (In reply to Vratislav Podzimek from comment #24) > > Interesting. But unless something has changed in lvmdbusd, the libblockdev's > > side should be okay, because it tells lvmdbusd to return a job object path > > in a second which is definitely shorter than the DBus timeout. Looks like > > lvmdbusd failed to provide the answer. If this appears more than once we > > definitely need to debug the issue more thoroughly. > > It looks like the timeout is set to 5000 or 5 seconds for the client library > and the API timeout == 1 second. This should be plenty of time when > accounting for the imprecise nature of the lvmdbusd timeout implementation. > > Is blivet running multiple operations concurrently to configure the storage > or is it sequentially making changes? Trying to understand any contributing > factors. All blivet operations are running in a single thread. It's a "worker" thread of anaconda (the main thread runs the UI), but blivet itself runs everything sequentially.