Bug 1657950 - lvmdbusd traceback when reshaping raid volumes
Summary: lvmdbusd traceback when reshaping raid volumes
Keywords:
Status: ON_QA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: lvm2
Version: 8.0
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: 8.0
Assignee: Marian Csontos
QA Contact: cluster-qe@redhat.com
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-12-10 19:48 UTC by Corey Marthaler
Modified: 2020-01-08 08:35 UTC (History)
7 users (show)

Fixed In Version: lvm2-2.03.02-1.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)

Description Corey Marthaler 2018-12-10 19:48:47 UTC
Description of problem:

[root@hayes-02 ~]# vgcreate VG /dev/sd[bcdefgh]1
  Physical volume "/dev/sdb1" successfully created.
  Physical volume "/dev/sdc1" successfully created.
  Physical volume "/dev/sdd1" successfully created.
  Physical volume "/dev/sde1" successfully created.
  Physical volume "/dev/sdf1" successfully created.
  Physical volume "/dev/sdg1" successfully created.
  Physical volume "/dev/sdh1" successfully created.
  Volume group "VG" successfully created

[root@hayes-02 ~]# lvcreate  --type raid6_rs_6 -R 512.00k -i 3 -n takeover -L 2.75G VG
  Using default stripesize 64.00 KiB.
  Rounding size 2.75 GiB (704 extents) up to stripe boundary size 2.75 GiB(705 extents).
  Logical volume "takeover" created.

[root@hayes-02 ~]# lvs -a -o +devices
  LV                  VG Attr       LSize    Cpy%Sync Devices
  takeover            VG rwi-a-r---   2.75g  33.17    takeover_rimage_0(0),takeover_rimage_1(0),takeover_rimage_2(0),takeover_rimage_3(0),takeover_rimage_4(0)
  [takeover_rimage_0] VG Iwi-aor--- 940.00m           /dev/sdb1(1)
  [takeover_rimage_1] VG Iwi-aor--- 940.00m           /dev/sdc1(1)
  [takeover_rimage_2] VG Iwi-aor--- 940.00m           /dev/sdd1(1)
  [takeover_rimage_3] VG Iwi-aor--- 940.00m           /dev/sde1(1)
  [takeover_rimage_4] VG Iwi-aor--- 940.00m           /dev/sdf1(1)
  [takeover_rmeta_0]  VG ewi-aor---   4.00m           /dev/sdb1(0)
  [takeover_rmeta_1]  VG ewi-aor---   4.00m           /dev/sdc1(0)
  [takeover_rmeta_2]  VG ewi-aor---   4.00m           /dev/sdd1(0)
  [takeover_rmeta_3]  VG ewi-aor---   4.00m           /dev/sde1(0)
  [takeover_rmeta_4]  VG ewi-aor---   4.00m           /dev/sdf1(0)
[root@hayes-02 ~]# lvs -a -o +devices
  LV                  VG Attr       LSize    Cpy%Sync Devices
  takeover            VG rwi-a-r---   2.75g  100.00   takeover_rimage_0(0),takeover_rimage_1(0),takeover_rimage_2(0),takeover_rimage_3(0),takeover_rimage_4(0)
  [takeover_rimage_0] VG iwi-aor--- 940.00m           /dev/sdb1(1)
  [takeover_rimage_1] VG iwi-aor--- 940.00m           /dev/sdc1(1)
  [takeover_rimage_2] VG iwi-aor--- 940.00m           /dev/sdd1(1)
  [takeover_rimage_3] VG iwi-aor--- 940.00m           /dev/sde1(1)
  [takeover_rimage_4] VG iwi-aor--- 940.00m           /dev/sdf1(1)
  [takeover_rmeta_0]  VG ewi-aor---   4.00m           /dev/sdb1(0)
  [takeover_rmeta_1]  VG ewi-aor---   4.00m           /dev/sdc1(0)
  [takeover_rmeta_2]  VG ewi-aor---   4.00m           /dev/sdd1(0)
  [takeover_rmeta_3]  VG ewi-aor---   4.00m           /dev/sde1(0)
  [takeover_rmeta_4]  VG ewi-aor---   4.00m           /dev/sdf1(0)

[root@hayes-02 ~]# lvconvert --force --yes   --type raid10_near VG/takeover
  Using default stripesize 64.00 KiB.
  Replaced LV type raid10_near (same as raid10) with possible type raid6_n_6.
  Repeat this command to convert to raid10_near after an interim conversion has finished.
  Converting raid6_rs_6 LV VG/takeover to raid6_n_6.
  Logical volume VG/takeover successfully converted.



Dec 10 13:37:19 hayes-02 dmeventd[32808]: No longer monitoring RAID device VG-takeover for events.
Dec 10 13:37:19 hayes-02 lvm[32808]: Monitoring RAID device VG-takeover for events.
Dec 10 13:37:20 hayes-02 kernel: md/raid:mdX: device dm-1 operational as raid disk 0
Dec 10 13:37:20 hayes-02 kernel: md/raid:mdX: device dm-3 operational as raid disk 1
Dec 10 13:37:20 hayes-02 kernel: md/raid:mdX: device dm-5 operational as raid disk 2
Dec 10 13:37:20 hayes-02 kernel: md/raid:mdX: device dm-7 operational as raid disk 3
Dec 10 13:37:20 hayes-02 kernel: md/raid:mdX: device dm-9 operational as raid disk 4
Dec 10 13:37:20 hayes-02 kernel: md/raid:mdX: raid level 6 active with 5 out of 5 devices, algorithm 5
Dec 10 13:37:20 hayes-02 dmeventd[32808]: No longer monitoring RAID device VG-takeover for events.
Dec 10 13:37:20 hayes-02 lvm[32808]: Monitoring RAID device VG-takeover for events.
Dec 10 13:37:20 hayes-02 lvm[32808]: raid6_n_6 array, VG-takeover, is not in-sync.
Dec 10 13:37:20 hayes-02 kernel: md: reshape of RAID array mdX
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: 2208:2208 - MThreadRunner: exception
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: Traceback (most recent call last):
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 630, in _run
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    self.rc = self.f(*self.args)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 34, in _main_thread_load
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    cache_refresh=False)[1]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/lv.py", line 101, in load_lvs
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    lv_name, object_path, refresh, emit_signal, cache_refresh)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/loader.py", line 68, in common
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    num_changes += dbus_object.refresh(object_state=o)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/automatedproperties.py", line 186, in refresh
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    n_prop = get_properties(self)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 114, in get_properties
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    interfaces[interface][1][p] = getattr(f, p)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/lv.py", line 361, in Health
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    return dbus.Struct((self.state.Attr[8], type_map[self.state.Attr[8]]),
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: KeyError: 's'
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: 2208:2208 - Exception will be raised in calling thread!
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: 2208:2216 - update_thread exception:
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: Traceback (most recent call last):
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 129, in update_thread
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    need_main_thread)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 46, in load
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    rc = MThreadRunner(_main_thread_load, refresh, emit_signal).done()
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 624, in done
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    raise self.exception
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 630, in _run
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    self.rc = self.f(*self.args)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 34, in _main_thread_load
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    cache_refresh=False)[1]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/lv.py", line 101, in load_lvs
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    lv_name, object_path, refresh, emit_signal, cache_refresh)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/loader.py", line 68, in common
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    num_changes += dbus_object.refresh(object_state=o)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/automatedproperties.py", line 186, in refresh
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    n_prop = get_properties(self)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 114, in get_properties
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    interfaces[interface][1][p] = getattr(f, p)
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  File "/usr/lib/python3.6/site-packages/lvmdbusd/lv.py", line 361, in Health
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:    return dbus.Struct((self.state.Attr[8], type_map[self.state.Attr[8]]),
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: KeyError: 's'
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: 2208:2216 - LVM dbus flight recorder START
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: 2208:2216 - EC= 0 for ['/usr/sbin/lvm', 'fullreport', '--noheading', '--separator', '{|}', '--nosuffix', '--unbuffered', '--units', 'b', '-a', '--configreport', 'pv', '-o', 'pv_name,pv_uuid,pv_fmt,pv_size,pv_free,pv_used,dev_size,pv_mda_size,pv_mda_free,pv_ba_start,pv_ba_size,pe_start,pv_pe_count,pv_pe_alloc_count,pv_attr,pv_tags,vg_name,vg_uuid,pv_missing', '--configreport', 'vg', '-o', 'vg_name,vg_uuid,vg_fmt,vg_size,vg_free,vg_sysid,vg_extent_size,vg_extent_count,vg_free_count,vg_profile,max_lv,max_pv,pv_count,lv_count,snap_count,vg_seqno,vg_mda_count,vg_mda_free,vg_mda_size,vg_mda_used_count,vg_attr,vg_tags', '--configreport', 'lv', '-o', 'lv_uuid,lv_name,lv_path,lv_size,vg_name,pool_lv_uuid,pool_lv,origin_uuid,origin,data_percent,lv_attr,lv_tags,vg_uuid,lv_active,data_lv,metadata_lv,lv_parent,lv_role,lv_layout,snap_percent,metadata_percent,copy_percent,sync_percent,lv_metadata_size,move_pv,move_pv_uuid', '--configreport', 'seg', '-o', 'seg_pe_ranges,segtype,lv_uuid', '--configreport', 'pvseg', '-o', 'pvseg_start,pvseg_size,segtype,pv_uuid,lv_uuid,pv_name', '--reportformat', 'json', '--config', 'global/notify_dbus=0']
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: STARTED: 1544247893.149155, ENDED: 1544247893.238178
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: STDOUT=  {
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:      "report": [
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:          {
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              "vg": [
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "vg_fmt":"lvm2", "vg_size":"12324438016000", "vg_free":"12324438016000", "vg_sysid":"", "vg_extent_size":"4194304", "vg_extent_count":"2938375", "vg_free_count":"2938375", "vg_profile":"", "max_lv":"0", "max_pv":"0", "pv_count":"10", "lv_count":"0", "snap_count":"0", "vg_seqno":"16", "vg_mda_count":"10", "vg_mda_free":"518656", "vg_mda_size":"1044480", "vg_mda_used_count":"10", "vg_attr":"wz--n-", "vg_tags":""}
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ,
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              "pv": [
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV10", "pv_uuid":"kfOVcc-3zTo-0k4w-xSbb-KHs8-QDdY-gxmeDe", "pv_fmt":"lvm2", "pv_size":"1991203880960", "pv_free":"1991203880960", "pv_used":"0", "dev_size":"1991206338560", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"474740", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV11", "pv_uuid":"qZ6mZB-Njqe-4bsB-A7cC-nSYP-ajB3-vpw2L7", "pv_fmt":"lvm2", "pv_size":"473683722240", "pv_free":"473683722240", "pv_used":"0", "dev_size":"473688129536", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"112935", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"A", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV12", "pv_uuid":"CexY6F-6ECZ-Ovpt-XBwm-oZmK-mkqP-rtxPz1", "pv_fmt":"lvm2", "pv_size":"473683722240", "pv_free":"473683722240", "pv_used":"0", "dev_size":"473688129536", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"112935", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV13", "pv_uuid":"1c1Q1R-Hv0Q-WTQh-sOoH-o35c-hg1Z-p6z5Pj", "pv_fmt":"lvm2", "pv_size":"473683722240", "pv_free":"473683722240", "pv_used":"0", "dev_size":"473688129536", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"112935", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV14", "pv_uuid":"c91ASG-KUfj-ocVI-JVvc-Z9Aa-njTp-BzzPro", "pv_fmt":"lvm2", "pv_size":"473683722240", "pv_free":"473683722240", "pv_used":"0", "dev_size":"473688129536", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"112935", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV15", "pv_uuid":"niXX35-aTFY-nFIe-rbUt-u78e-cPGw-a22Tvy", "pv_fmt":"lvm2", "pv_size":"473683722240", "pv_free":"473683722240", "pv_used":"0", "dev_size":"473688129536", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"112935", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV6", "pv_uuid":"qU5iAB-pfRx-TWTZ-8Yw4-qqaL-hfd5-wjS4nE", "pv_fmt":"lvm2", "pv_size":"1991203880960", "pv_free":"1991203880960", "pv_used":"0", "dev_size":"1991206338560", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"474740", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV7", "pv_uuid":"rvVD7S-t8lC-U1XD-wfb3-mUGW-xmNN-3NCptf", "pv_fmt":"lvm2", "pv_size":"1991203880960", "pv_free":"1991203880960", "pv_used":"0", "dev_size":"1991206338560", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"474740", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"A", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV8", "pv_uuid":"BdymWA-Jyob-dwPW-hKHS-zX2p-ZyuH-xuon21", "pv_fmt":"lvm2", "pv_size":"1991203880960", "pv_free":"1991203880960", "pv_used":"0", "dev_size":"1991206338560", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"474740", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pv_name":"/dev/mapper/vPV9", "pv_uuid":"MN6GyW-lhvq-zSFZ-uOY1-j7bv-UKKS-B3B1RD", "pv_fmt":"lvm2", "pv_size":"1991203880960", "pv_free":"1991203880960", "pv_used":"0", "dev_size":"1991206338560", "pv_mda_size":"1044480", "pv_mda_free":"518656", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"474740", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"mirror_sanity", "vg_uuid":"1bQxY6-A0Bz-Z8Wv-kdiL-hZ36-UV0B-8gFWyP", "pv_missing":""}
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ,
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              "lv": [
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ,
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              "pvseg": [
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"474740", "segtype":"free", "pv_uuid":"kfOVcc-3zTo-0k4w-xSbb-KHs8-QDdY-gxmeDe", "lv_uuid":"", "pv_name":"/dev/mapper/vPV10"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"112935", "segtype":"free", "pv_uuid":"qZ6mZB-Njqe-4bsB-A7cC-nSYP-ajB3-vpw2L7", "lv_uuid":"", "pv_name":"/dev/mapper/vPV11"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"112935", "segtype":"free", "pv_uuid":"CexY6F-6ECZ-Ovpt-XBwm-oZmK-mkqP-rtxPz1", "lv_uuid":"", "pv_name":"/dev/mapper/vPV12"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"112935", "segtype":"free", "pv_uuid":"1c1Q1R-Hv0Q-WTQh-sOoH-o35c-hg1Z-p6z5Pj", "lv_uuid":"", "pv_name":"/dev/mapper/vPV13"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"112935", "segtype":"free", "pv_uuid":"c91ASG-KUfj-ocVI-JVvc-Z9Aa-njTp-BzzPro", "lv_uuid":"", "pv_name":"/dev/mapper/vPV14"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"112935", "segtype":"free", "pv_uuid":"niXX35-aTFY-nFIe-rbUt-u78e-cPGw-a22Tvy", "lv_uuid":"", "pv_name":"/dev/mapper/vPV15"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"474740", "segtype":"free", "pv_uuid":"qU5iAB-pfRx-TWTZ-8Yw4-qqaL-hfd5-wjS4nE", "lv_uuid":"", "pv_name":"/dev/mapper/vPV6"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"474740", "segtype":"free", "pv_uuid":"rvVD7S-t8lC-U1XD-wfb3-mUGW-xmNN-3NCptf", "lv_uuid":"", "pv_name":"/dev/mapper/vPV7"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"474740", "segtype":"free", "pv_uuid":"BdymWA-Jyob-dwPW-hKHS-zX2p-ZyuH-xuon21", "lv_uuid":"", "pv_name":"/dev/mapper/vPV8"},
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:                  {"pvseg_start":"0", "pvseg_size":"474740", "segtype":"free", "pv_uuid":"MN6GyW-lhvq-zSFZ-uOY1-j7bv-UKKS-B3B1RD", "lv_uuid":"", "pv_name":"/dev/mapper/vPV9"}
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ,
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              "seg": [
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:              ]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:          }
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:      ]
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]:  }
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: STDERR=
Dec 10 13:37:20 hayes-02 lvmdbusd[2208]: 2208:2216 - EC= 0 for ['/usr/sbin/lvm', 'fullreport', '--noheading', '--separator', '{|}', '--nosuffix', '--unbuffered', '--units', 'b', '-a', '--configreport', 'pv', '-o', 'pv_name,pv_uuid,pv_fmt,pv_size,pv_free,pv_used,dev_size,pv_mda_size,pv_mda_free,pv_ba_start,pv_ba_size,pe_start,pv_pe_count,pv_pe_alloc_count,pv_attr,pv_tags,vg_name,vg_uuid,pv_missing', '--configreport', 'vg', '-o', 'vg_name,vg_uuid,vg_fmt,vg_size,vg_free,vg_sysid,vg_extent_size,vg_extent_count,vg_free_count,vg_profile,max_lv,max_pv,pv_count,lv_count,snap_count,vg_seqno,vg_mda_count,vg_mda_free,vg_mda_size,vg_mda_used_count,vg_attr,vg_tags', '--configreport', 'lv', '-o', 'lv_uuid,lv_name,lv_path,lv_size,vg_name,pool_lv_uuid,pool_lv,origin_uuid,origin,data_percent,lv_attr,lv_tags,vg_uuid,lv_active,data_lv,metadata_lv,lv_parent,lv_role,lv_layout,snap_percent,metadata_percent,copy_percent,sync_percent,lv_metadata_size,move_pv,move_pv_uuid', '--configreport', 'seg', '-o', 'seg_pe_ranges,segtype,lv_uuid', '--configreport', 'pvseg', '-o', 'pvseg_start,pvseg_size,segtype,pv_uuid,lv_uuid,pv_name', '--reportformat', 'json', '--config', 'global/notify_dbus=0']


Version-Release number of selected component (if applicable):
kernel-4.18.0-48.el8    BUILT: Sat Dec  1 19:25:48 CST 2018
lvm2-2.03.01-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
lvm2-libs-2.03.01-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
lvm2-dbusd-2.03.01-1.el8    BUILT: Thu Nov  1 04:31:09 CDT 2018
lvm2-lockd-2.03.01-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
boom-boot-0.9-5.el8    BUILT: Wed Sep 19 16:56:59 CDT 2018
cmirror-2.03.01-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
device-mapper-1.02.153-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
device-mapper-libs-1.02.153-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
device-mapper-event-1.02.153-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
device-mapper-event-libs-1.02.153-1.el8    BUILT: Thu Nov  1 04:29:08 CDT 2018
device-mapper-persistent-data-0.7.6-1.el8    BUILT: Sun Aug 12 04:21:55 CDT 2018


How reproducible:
Everytime

Comment 1 Tony Asleson 2018-12-10 22:29:17 UTC
I reproduced this on a local VM running F28.  The lvmdbusd daemon outputs the flight recorder from oldest to latest, thus the data I was looking for is not included in this BZ.  I'll change that as it should likely be most newest to oldest as the last one that was executed will most likely contain the information of interest.

The reason for this exception is that lvm returns the following in lv_attr

"lv_attr":"rwi-a-r-s-"

and the daemon is using a hash to convey what the health status is (bit 9) which is a 's'.  lvmdbusd doesn't have an entry for 's' and we hit the exception:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 129, in update_thread
    need_main_thread)
  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 46, in load
    rc = MThreadRunner(_main_thread_load, refresh, emit_signal).done()
  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 624, in done
    raise self.exception
  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 630, in _run
    self.rc = self.f(*self.args)
  File "/usr/lib/python3.6/site-packages/lvmdbusd/fetch.py", line 34, in _main_thread_load
    cache_refresh=False)[1]
  File "/usr/lib/python3.6/site-packages/lvmdbusd/lv.py", line 101, in load_lvs
    lv_name, object_path, refresh, emit_signal, cache_refresh)
  File "/usr/lib/python3.6/site-packages/lvmdbusd/loader.py", line 68, in common
    num_changes += dbus_object.refresh(object_state=o)
  File "/usr/lib/python3.6/site-packages/lvmdbusd/automatedproperties.py", line 186, in refresh
    n_prop = get_properties(self)
  File "/usr/lib/python3.6/site-packages/lvmdbusd/utils.py", line 114, in get_properties
    interfaces[interface][1][p] = getattr(f, p)
  File "/usr/lib/python3.6/site-packages/lvmdbusd/lv.py", line 362, in Health
    return dbus.Struct((self.state.Attr[8], type_map[self.state.Attr[8]]),
KeyError: 's'


At the moment I have no idea what the 's' signifies as it's not in the man page.

Additionally, when I encountered this error we ended up in a loop, that also needs to be understood and corrected.  For all of these cases where we interpret attribute bits we should handle the case when we don't a key entry and log the issue, and set the value to some sane value which denotes unknown so that the dbus API continues to function.

Comment 2 Tony Asleson 2018-12-11 15:27:12 UTC
The loop occurs because the lv_attr gets stored in the logical volume instance so when we update the state again we try to do an object difference between old and new state.  In this process we compare the properties of old and new.  When we try to get the values of the old which contains the lv_attr health bit which we don't understand, we raise the exception and the process repeats over and over again as the state update runs in a separate thread looping.

Comment 4 Marian Csontos 2019-02-12 16:12:22 UTC
The commit is already present in LVM 2.03.02 which is shipped with RHEL-8.


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