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...
: 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
Type: ---
Embargoed:


Attachments (Terms of Use)
File: anaconda-tb (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: anaconda.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: dnf.librepo.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: environ (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: hawkey.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: lorax-packages.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: lsblk_output (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: lvm.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: nmcli_dev_list (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: os_info (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: program.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: storage.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: syslog (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: ifcfg.log (deleted)
2018-06-05 15:15 UTC, Paul Whalen
no flags Details
File: packaging.log (deleted)
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.