Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
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...
: 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
Type: ---
Embargoed:

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
View All

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.