Bug 1379357 - gi.overrides.BlockDev.LVMError: Failed to call the 'PvScan' method on the '/com/redhat/lvmdbus1/Manager' object: GDBus.Error:org.freedesktop.DBus.Python.KeyError: Traceback (most recent call last):
Summary: gi.overrides.BlockDev.LVMError: Failed to call the 'PvScan' method on the '/c...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: LVM and device-mapper
Classification: Community
Component: lvm2
Version: 2.02.165
Hardware: x86_64
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: ---
Assignee: LVM and device-mapper development team
QA Contact: Tony Asleson
URL:
Whiteboard: abrt_hash:adc0ad632be80d4de0155aff741...
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-09-26 12:56 UTC by Jiri Konecny
Modified: 2017-09-13 15:47 UTC (History)
13 users (show)

Fixed In Version: 2.02.166
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-09-13 15:47:40 UTC
Embargoed:
rule-engine: lvm-technical-solution?
rule-engine: lvm-test-coverage?


Attachments (Terms of Use)
File: anaconda-tb (524.46 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: anaconda.log (41.80 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: dnf.librepo.log (11.59 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: environ (482 bytes, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: hawkey.log (900 bytes, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: ks.cfg (1.60 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: lsblk_output (1.59 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: lvm.log (88.81 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: nmcli_dev_list (1.60 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: os_info (451 bytes, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: storage.log (146.61 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: syslog (81.69 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: ifcfg.log (1.67 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: packaging.log (3.93 KB, text/plain)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details
File: program.log (34.81 KB, application/octet-stream)
2016-09-26 12:56 UTC, Jiri Konecny
no flags Details

Description Jiri Konecny 2016-09-26 12:56:28 UTC
Description of problem:
Run automatic kickstart installation with autopart. It's failing on about three different issue and one of them is this one.

How reproducible:
It looks like race condition

Actual result:
Traceback on "Setting up the installation environment"

Expected result:
Succesful installation

Additional information:
This can be reproduced by repeating installation.

Version-Release number of selected component:
anaconda-26.4-1

The following was filed automatically by anaconda:
anaconda 26.4-1 exception report
Traceback (most recent call first):
  File "/usr/lib64/python3.5/site-packages/gi/overrides/BlockDev.py", line 441, in wrapped
    raise transform[1](msg)
  File "/tmp/updates/blivet/formats/lvmpv.py", line 137, in _destroy
    blockdev.lvm.pvscan(self.device)
  File "/tmp/updates/blivet/threads.py", line 45, in run_with_lock
    return m(*args, **kwargs)
  File "/tmp/updates/blivet/formats/__init__.py", line 546, in destroy
    self._destroy(**kwargs)
  File "/tmp/updates/blivet/threads.py", line 45, in run_with_lock
    return m(*args, **kwargs)
  File "/tmp/updates/blivet/deviceaction.py", line 696, in execute
    self.format.destroy()
  File "/tmp/updates/blivet/threads.py", line 45, in run_with_lock
    return m(*args, **kwargs)
  File "/tmp/updates/blivet/actionlist.py", line 325, in process
    action.execute(callbacks)
  File "/tmp/updates/blivet/actionlist.py", line 48, in wrapped_func
    return func(obj, *args, **kwargs)
  File "/tmp/updates/blivet/blivet.py", line 163, in do_it
    self.devicetree.actions.process(callbacks=callbacks, devices=self.devices)
  File "/tmp/updates/blivet/threads.py", line 45, in run_with_lock
    return m(*args, **kwargs)
  File "/tmp/updates/blivet/osinstall.py", line 1112, in turn_on_filesystems
    storage.do_it(callbacks)
  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/lib64/python3.5/threading.py", line 862, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib64/python3.5/site-packages/pyanaconda/threads.py", line 251, in run
    threading.Thread.run(self, *args, **kwargs)
gi.overrides.BlockDev.LVMError: Failed to call the 'PvScan' method on the '/com/redhat/lvmdbus1/Manager' object: GDBus.Error:org.freedesktop.DBus.Python.KeyError: Traceback (most recent call last):
  File "/usr/lib/python3.5/site-packages/lvmdbusd/request.py", line 66, in run_cmd
    result = self.method(*self.arguments)
  File "/usr/lib/python3.5/site-packages/lvmdbusd/manager.py", line 205, in _pv_scan
    cfg.load()
  File "/usr/lib/python3.5/site-packages/lvmdbusd/fetch.py", line 24, in load
    cache_refresh=False)[1]
  File "/usr/lib/python3.5/site-packages/lvmdbusd/pv.py", line 48, in load_pvs
    emit_signal, cache_refresh)
  File "/usr/lib/python3.5/site-packages/lvmdbusd/loader.py", line 80, in common
    cfg.om.remove_object(cfg.om.get_object_by_path(k), True)
  File "/usr/lib/python3.5/site-packages/lvmdbusd/objectmanager.py", line 153, in remove_object
    self._lookup_remove(path)
  File "/usr/lib/python3.5/site-packages/lvmdbusd/objectmanager.py", line 97, in _lookup_remove
    del self._id_to_object_path[lvm_id]
KeyError: '[unknown]'


Additional info:
addons:         com_redhat_kdump, com_redhat_docker
cmdline:        /usr/bin/python3  /sbin/anaconda
cmdline_file:   initrd=/test/rawhide/initrd.img nokill resolution=1024x768 inst.repo=ftp://cobra02/rawhide/ ks=http://cobra02/ks/jk/testing.ks updates=http://cobra02/ks/jk/master_updates.img BOOT_IMAGE=/test/rawhide/vmlinuz 
executable:     /sbin/anaconda
hashmarkername: anaconda
kernel:         4.8.0-0.rc7.git4.1.fc26.x86_64
product:        Fedora
release:        Cannot get release name.
type:           anaconda
version:        rawhide

Comment 1 Jiri Konecny 2016-09-26 12:56:34 UTC
Created attachment 1204817 [details]
File: anaconda-tb

Comment 2 Jiri Konecny 2016-09-26 12:56:36 UTC
Created attachment 1204818 [details]
File: anaconda.log

Comment 3 Jiri Konecny 2016-09-26 12:56:38 UTC
Created attachment 1204819 [details]
File: dnf.librepo.log

Comment 4 Jiri Konecny 2016-09-26 12:56:39 UTC
Created attachment 1204820 [details]
File: environ

Comment 5 Jiri Konecny 2016-09-26 12:56:41 UTC
Created attachment 1204821 [details]
File: hawkey.log

Comment 6 Jiri Konecny 2016-09-26 12:56:42 UTC
Created attachment 1204822 [details]
File: ks.cfg

Comment 7 Jiri Konecny 2016-09-26 12:56:43 UTC
Created attachment 1204823 [details]
File: lsblk_output

Comment 8 Jiri Konecny 2016-09-26 12:56:45 UTC
Created attachment 1204824 [details]
File: lvm.log

Comment 9 Jiri Konecny 2016-09-26 12:56:47 UTC
Created attachment 1204825 [details]
File: nmcli_dev_list

Comment 10 Jiri Konecny 2016-09-26 12:56:48 UTC
Created attachment 1204826 [details]
File: os_info

Comment 11 Jiri Konecny 2016-09-26 12:56:50 UTC
Created attachment 1204827 [details]
File: storage.log

Comment 12 Jiri Konecny 2016-09-26 12:56:52 UTC
Created attachment 1204828 [details]
File: syslog

Comment 13 Jiri Konecny 2016-09-26 12:56:54 UTC
Created attachment 1204829 [details]
File: ifcfg.log

Comment 14 Jiri Konecny 2016-09-26 12:56:55 UTC
Created attachment 1204830 [details]
File: packaging.log

Comment 15 Jiri Konecny 2016-09-26 12:56:57 UTC
Created attachment 1204831 [details]
File: program.log

Comment 16 Vratislav Podzimek 2016-09-26 13:06:55 UTC
According to the traceback this looks like an issue in the lvmdbusd daemon.

Comment 17 Tony Asleson 2016-09-26 16:46:29 UTC
It appears that the lvm dbus code is throwing an exception, because multiple devices have a device path of '[unknown]'.  The lvm dbus service keeps look up tables (hash table) which provides look up capabilities so that users can look up based on uuid or lvm id (pv device path, full lv name, vg name etc.).  If multiple pv entries have the same pv device path the code gets confused as we have 2 or more pv objects which are using the same "lvm id" look up.  So if 1 of them changes from unknown -> /dev/vdb1 then that unknown entry gets removed so we then have 1 or more object entries which no longer have a "lvm id" entry which will raise an exception when we try to delete a non-existent look up entry.

Will add checks to handle this situation and accommodate non-unique pv device paths.

Comment 19 Tony Asleson 2016-09-27 19:11:14 UTC
This issue was re-created by creating 2 loopback block devices and a third regular disk, creating a VG that utilized all three devices and then disconnected the loopback devices and then add them back one by one.

Comment 20 Vratislav Podzimek 2016-09-28 07:31:07 UTC
(In reply to Tony Asleson from comment #18)
> Correct upstream with:
> https://git.fedorahosted.org/cgit/lvm2.git/commit/
> ?id=063265eacda95dbc1567e647734a000c8d68c8b7

Are you sure about this weird-looking comparison of a boolean value and a function?

+				if path_create == pv_obj_path_generate and \
+						lvm_id == '[unknown]':

Otherwise the fix looks good to me.

Comment 21 Tony Asleson 2016-09-28 14:27:01 UTC
(In reply to Vratislav Podzimek from comment #20)
> (In reply to Tony Asleson from comment #18)
> > Correct upstream with:
> > https://git.fedorahosted.org/cgit/lvm2.git/commit/
> > ?id=063265eacda95dbc1567e647734a000c8d68c8b7
> 
> Are you sure about this weird-looking comparison of a boolean value and a
> function?
> 
> +				if path_create == pv_obj_path_generate and \
> +						lvm_id == '[unknown]':
> 
> Otherwise the fix looks good to me.

Unfortunately the method documentation is incorrect, I will fix that shortly.  The variable 'path_create' is actually the function pointer and gen_new is the boolean, eg.

337# We have exhausted all lookups, let's create if we can
338    if gen_new:
339        path = path_create()
340        self._lookup_add(None, path, lvm_id, uuid)

I will double check all the places get_object_path_by_uuid_lvm_id it's being called and if it looks good, I'm going to remove gen_new and just use the fact that if 'path_create' is not None that it's OK to create a new object path.

Thanks for pointing this out!

Comment 22 Tony Asleson 2016-09-28 15:10:33 UTC
Need to correct as the '[unknown]' device path may take different forms.  Need to use the missing field on the PV


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