Bug 1586148 - gi.overrides.BlockDev.LVMError: Failed to call the 'PvCreate' method on the '/com/redhat/lvmdbus1/Manager' object: Timeout was reached
Summary: gi.overrides.BlockDev.LVMError: Failed to call the 'PvCreate' method on the '...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: libblockdev
Version: 29
Hardware: All
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Vojtech Trefny
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: abrt_hash:ac3a5a376448154f356e5bd9748...
: 1588697 1589871 (view as bug list)
Depends On:
Blocks: ARMTracker
TreeView+ depends on / blocked
 
Reported: 2018-06-05 15:15 UTC by Paul Whalen
Modified: 2018-09-12 11:01 UTC (History)
17 users (show)

Fixed In Version: libblockdev-2.19-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-09-10 10:48:27 UTC


Attachments (Terms of Use)
File: anaconda-tb (700.22 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: anaconda.log (35.20 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: dnf.librepo.log (11.76 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: environ (637 bytes, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: hawkey.log (3.01 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: lorax-packages.log (24.55 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: lsblk_output (1.88 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: lvm.log (29.84 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: nmcli_dev_list (2.14 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: os_info (556 bytes, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: program.log (32.65 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: storage.log (91.42 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: syslog (282.86 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: ifcfg.log (1.59 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: packaging.log (7.67 KB, text/plain)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details

Description Paul Whalen 2018-06-05 15:15:17 UTC
Description of problem:
Attempt F29 installation with encrypted root on armhfp

Version-Release number of selected component:
anaconda-29.15

The following was filed automatically by anaconda:
anaconda 29.15 exception report
Traceback (most recent call first):
  File "/usr/lib/python3.6/site-packages/gi/overrides/BlockDev.py", line 869, in wrapped
    raise transform[1](msg)
  File "/usr/lib/python3.6/site-packages/blivet/formats/lvmpv.py", line 125, in _create
    blockdev.lvm.pvcreate(self.device, data_alignment=self.data_alignment)
  File "/usr/lib/python3.6/site-packages/blivet/threads.py", line 53, in run_with_lock
    return m(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/blivet/formats/__init__.py", line 513, in create
    self._create(**kwargs)
  File "/usr/lib/python3.6/site-packages/blivet/threads.py", line 53, in run_with_lock
    return m(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/blivet/deviceaction.py", line 616, in execute
    options=self.device.format_args)
  File "/usr/lib/python3.6/site-packages/blivet/threads.py", line 53, in run_with_lock
    return m(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/blivet/actionlist.py", line 327, in process
    action.execute(callbacks)
  File "/usr/lib/python3.6/site-packages/blivet/actionlist.py", line 48, in wrapped_func
    return func(obj, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/blivet/blivet.py", line 135, in do_it
    self.devicetree.actions.process(callbacks=callbacks, devices=self.devices)
  File "/usr/lib/python3.6/site-packages/blivet/threads.py", line 53, in run_with_lock
    return m(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/pyanaconda/storage/osinstall.py", line 1222, in do_it
    super().do_it(callbacks=callbacks)
  File "/usr/lib/python3.6/site-packages/blivet/threads.py", line 53, in run_with_lock
    return m(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/pyanaconda/storage/osinstall.py", line 2142, in turn_on_filesystems
    storage.do_it(callbacks)
  File "/usr/lib/python3.6/site-packages/pyanaconda/installation_tasks.py", line 438, in run_task
    self._task(*self._task_args, **self._task_kwargs)
  File "/usr/lib/python3.6/site-packages/pyanaconda/installation_tasks.py", line 472, in start
    self.run_task()
  File "/usr/lib/python3.6/site-packages/pyanaconda/installation_tasks.py", line 304, in start
    item.start()
  File "/usr/lib/python3.6/site-packages/pyanaconda/installation_tasks.py", line 304, in start
    item.start()
  File "/usr/lib/python3.6/site-packages/pyanaconda/installation.py", line 369, in doInstall
    installation_queue.start()
  File "/usr/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.6/site-packages/pyanaconda/threading.py", line 291, in run
    threading.Thread.run(self)
gi.overrides.BlockDev.LVMError: Failed to call the 'PvCreate' method on the '/com/redhat/lvmdbus1/Manager' object: Timeout was reached

Additional info:
addons:         com_redhat_kdump, com_redhat_docker
blivet-gui-utils.log: 
cmdline:        /usr/bin/python3  /sbin/anaconda
cmdline_file:   ip=eth0:dhcp inst.repo=https://kojipkgs.fedoraproject.org/compose/rawhide//Fedora-Rawhide-20180603.n.1/compose/Everything/armhfp/os/ inst.stage2=nfs://192.168.0.99:/srv/fedora/fedora-release/Fedora-Rawhide-20180603.n.1/everything/armhfp/
executable:     /sbin/anaconda
hashmarkername: anaconda
kernel:         4.17.0-0.rc7.git2.1.fc29.armv7hl
product:        Fedora
release:        Cannot get release name.
type:           anaconda
version:        rawhide

Comment 1 Paul Whalen 2018-06-05 15:15:37 UTC
Created attachment 1447890 [details]
File: anaconda-tb

Comment 2 Paul Whalen 2018-06-05 15:15:38 UTC
Created attachment 1447891 [details]
File: anaconda.log

Comment 3 Paul Whalen 2018-06-05 15:15:40 UTC
Created attachment 1447892 [details]
File: dnf.librepo.log

Comment 4 Paul Whalen 2018-06-05 15:15:41 UTC
Created attachment 1447893 [details]
File: environ

Comment 5 Paul Whalen 2018-06-05 15:15:43 UTC
Created attachment 1447894 [details]
File: hawkey.log

Comment 6 Paul Whalen 2018-06-05 15:15:44 UTC
Created attachment 1447895 [details]
File: lorax-packages.log

Comment 7 Paul Whalen 2018-06-05 15:15:46 UTC
Created attachment 1447896 [details]
File: lsblk_output

Comment 8 Paul Whalen 2018-06-05 15:15:47 UTC
Created attachment 1447897 [details]
File: lvm.log

Comment 9 Paul Whalen 2018-06-05 15:15:48 UTC
Created attachment 1447898 [details]
File: nmcli_dev_list

Comment 10 Paul Whalen 2018-06-05 15:15:50 UTC
Created attachment 1447899 [details]
File: os_info

Comment 11 Paul Whalen 2018-06-05 15:15:52 UTC
Created attachment 1447900 [details]
File: program.log

Comment 12 Paul Whalen 2018-06-05 15:15:53 UTC
Created attachment 1447901 [details]
File: storage.log

Comment 13 Paul Whalen 2018-06-05 15:15:56 UTC
Created attachment 1447902 [details]
File: syslog

Comment 14 Paul Whalen 2018-06-05 15:15:57 UTC
Created attachment 1447903 [details]
File: ifcfg.log

Comment 15 Paul Whalen 2018-06-05 15:15:59 UTC
Created attachment 1447904 [details]
File: packaging.log

Comment 16 Martin Kolman 2018-06-05 15:40:58 UTC
Looks like some issue with the LVM DBUS API Blivet uses, so reassigning to Blivet for further triage.

Comment 17 Paul Whalen 2018-06-11 15:03:51 UTC
*** Bug 1589871 has been marked as a duplicate of this bug. ***

Comment 18 Paul Whalen 2018-06-11 17:05:01 UTC
Happens on low end systems with 2048M RAM when doing graphical or VNC installs. Reproduced on x86_64 and aarch64

Comment 19 Brian Clark 2018-07-06 18:39:09 UTC
Similar problem has been detected:

Tried to run rawhide server iso created on July 2, 2018.  Pretty much default settings.

addons:         com_redhat_docker, com_redhat_kdump
blivet-gui-utils.log: 
cmdline:        /usr/bin/python3  /sbin/anaconda
cmdline_file:   BOOT_IMAGE=vmlinuz initrd=initrd.img inst.stage2=hd:LABEL=Fedora-S-dvd-x86_64-rawh rd.live.check quiet
hashmarkername: anaconda
kernel:         4.18.0-0.rc2.git4.1.fc29.x86_64
package:        anaconda-29.19
product:        Fedora
reason:         gi.overrides.BlockDev.LVMError: Failed to call the 'PvCreate' method on the '/com/redhat/lvmdbus1/Manager' object: Timeout was reached
release:        Cannot get release name.
version:        rawhide

Comment 20 Brian Clark 2018-07-06 19:05:00 UTC
I tried with the Basic graphical option under the troubleshooting' menu during the boot process.  For me it seems to be installing normally now.  I am running this installation on VirtualBox and it is configure with less than 2GB of RAM.  I am not using a encrypted Hard Drive.

Comment 21 Tony Asleson 2018-07-10 20:41:18 UTC
I tried to duplicate this with Virtualbox  using the following install images:

Fedora-Server-netinst-x86_64-Rawhide-20180710.n.0.iso
Fedora-Workstation-Live-x86_64-Rawhide-20180710.n.0.iso
Fedora-Workstation-netinst-x86_64-Rawhide-20180710.n.0.iso

Note: Fedora-Workstation-Live-x86_64-Rawhide-20180710.n.0.iso does not appear to have /usr/sbin/lvmdbusd available, so unable to test.

I used 1024 memory, which resulted in a failure to exec `udevadm settle` with an out of memory error.  I then tried 2048 & 1536 MiB with default encrypted disk layout, and the storage setup worked.


Would it be possible to get lvmdbusd started with--debug added during install?  Just need to add to lvm2-lvmdbusd.service.


Looking at the available logs, I don't see anything obvious.  Libblockdev is setting a 5 second socket timeout and passing a 1 second API timeout to the lvmdbusd service.  So the service should be returning a job object if it takes longer than 1 second.  However, I don't know how accurate the timer support is in python when running in a VM or on ARM hardware, but I would think that we could get back to the caller within 5 seconds.

Comment 22 Vojtech Trefny 2018-07-25 08:40:32 UTC
Actually the problem is that lvmdbusd takes too long to start -- the PvCreate call is the first use of the API so the service is not running and it takes 8 seconds to start.

--------
13:12:49,171 INFO dbus-daemon:[system] Activating via systemd: service name='com.redhat.lvmdbus1' unit='lvm2-lvmdbusd.service' requested by ':1.7' (uid=0 pid=1673 comm="/usr/bin/python3 /sbin/anaconda " label="system_u:system_r:initrc_t:s0")
13:12:49,336 INFO systemd:Starting LVM2 D-Bus service...
13:12:57,934 INFO dbus-daemon:[system] Successfully activated service 'com.redhat.lvmdbus1'
13:12:57,960 NOTICE audit:SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-lvmdbusd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
13:12:57,976 INFO systemd:Started LVM2 D-Bus service.
--------

Comment 23 Vojtech Trefny 2018-07-27 08:47:21 UTC
Upstream PR: https://github.com/storaged-project/libblockdev/pull/375

Comment 24 Jan Kurik 2018-08-14 11:13:48 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 29 development cycle.
Changing version to '29'.

Comment 25 Vojtech Trefny 2018-09-12 11:01:00 UTC
*** Bug 1588697 has been marked as a duplicate of this bug. ***


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