Bug 1657950
Summary: | lvmdbusd traceback when reshaping raid volumes | ||
---|---|---|---|
Product: | Red Hat Enterprise Linux 8 | Reporter: | Corey Marthaler <cmarthal> |
Component: | lvm2 | Assignee: | Marian Csontos <mcsontos> |
lvm2 sub component: | lvmdbusd | QA Contact: | cluster-qe <cluster-qe> |
Status: | CLOSED ERRATA | Docs Contact: | |
Severity: | medium | ||
Priority: | unspecified | CC: | agk, heinzm, jbrassow, msnitzer, prajnoha, tasleson, zkabelac |
Version: | 8.0 | ||
Target Milestone: | rc | ||
Target Release: | 8.0 | ||
Hardware: | x86_64 | ||
OS: | Linux | ||
Whiteboard: | |||
Fixed In Version: | lvm2-2.03.02-1.el8 | Doc Type: | If docs needed, set a value |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2020-04-28 16:58:57 UTC | Type: | Bug |
Regression: | --- | Mount Type: | --- |
Documentation: | --- | CRM: | |
Verified Versions: | Category: | --- | |
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
Cloudforms Team: | --- | Target Upstream Version: | |
Embargoed: |
Description
Corey Marthaler
2018-12-10 19:48:47 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. 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. Correction posted upstream: https://sourceware.org/git/?p=lvm2.git;a=commitdiff;h=51f08efaa700550740254093bacea270325f2ccf The commit is already present in LVM 2.03.02 which is shipped with RHEL-8. Fix verified in the latest rpms. kernel-4.18.0-179.el8 BUILT: Fri Feb 14 17:03:01 CST 2020 lvm2-2.03.08-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 lvm2-libs-2.03.08-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 lvm2-dbusd-2.03.08-2.el8 BUILT: Mon Feb 24 11:24:10 CST 2020 lvm2-lockd-2.03.08-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 boom-boot-1.0-1.el8 BUILT: Fri Nov 29 05:18:30 CST 2019 device-mapper-1.02.169-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 device-mapper-libs-1.02.169-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 device-mapper-event-1.02.169-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 device-mapper-event-libs-1.02.169-2.el8 BUILT: Mon Feb 24 11:21:38 CST 2020 [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 Pool Origin Data% Meta% Move Log Cpy%Sync Convert 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/sdc1(1) [takeover_rimage_1] VG iwi-aor--- 940.00m /dev/sdd1(1) [takeover_rimage_2] VG iwi-aor--- 940.00m /dev/sde1(1) [takeover_rimage_3] VG iwi-aor--- 940.00m /dev/sdf1(1) [takeover_rimage_4] VG iwi-aor--- 940.00m /dev/sdg1(1) [takeover_rmeta_0] VG ewi-aor--- 4.00m /dev/sdc1(0) [takeover_rmeta_1] VG ewi-aor--- 4.00m /dev/sdd1(0) [takeover_rmeta_2] VG ewi-aor--- 4.00m /dev/sde1(0) [takeover_rmeta_3] VG ewi-aor--- 4.00m /dev/sdf1(0) [takeover_rmeta_4] VG ewi-aor--- 4.00m /dev/sdg1(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. bus.ObjectPath('/com/redhat/lvmdbus1/HiddenLv/18'), dbus.ObjectPath('/com/redhat/lvmdbus1/HiddenLv/19')], signature=dbus.Signature('o')), 'Devices': dbus.Array([], signature=dbus.Signature('(oa(tts))')), 'PoolLv': dbus.ObjectPath('/'), 'OriginLv': dbus.ObjectPath('/'), 'Vg': dbus.ObjectPath('/com/redhat/lvmdbus1/Vg/0'), 'SegType': dbus.Array([dbus.String('raid6_rs_6')], signature=dbus.Signature('s')), 'SizeBytes': dbus.UInt64(2956984320), 'Path': dbus.String('/dev/VG/takeover'), 'Name': dbus.String('takeover'), 'Uuid': dbus.String('USjHDK-6ERd-Jlpk-qFfN-310j-D29N-wX7Wcs')}, 'com.redhat.lvmdbus1.Lv': {}}) Feb 25 11:31:49.233698: 436565:436573 - Method complete: <function _udev_event at 0x7fe84d45e400> Feb 25 11:31:49.233898: 436565:436573 - Method start: <function _udev_event at 0x7fe84d45e400> with args () (callback = None) Feb 25 11:31:49.234062: 436565:436573 - Processing udev event Feb 25 11:31:49.234281: 436565:436574 - lvmdb - refresh entry Feb 25 11:31:49.310574: 436565:436574 - lvmdb - refresh exit Feb 25 11:31:49.322612: 436565:436573 - Method complete: <function _udev_event at 0x7fe84d45e400> Feb 25 11:32:24.684392: 436565:436573 - Method start: <function _udev_event at 0x7fe84d45e400> with args () (callback = None) Feb 25 11:32:24.684583: 436565:436573 - Processing udev event Feb 25 11:32:24.684840: 436565:436574 - lvmdb - refresh entry Feb 25 11:32:26.210281: 436565:436574 - lvmdb - refresh exit Feb 25 11:32:26.211851: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Pv/0, com.redhat.lvmdbus1.Pv, {'PeSegments': dbus.Array([('0', '1'), ('1', '236'), ('237', '476437')], signature=dbus.Signature('(tt)')), 'Lv': dbus.Array([('/com/redhat/lvmdbus1/HiddenLv/10', [('0', '0', 'linear')]), ('/com/redhat/lvmdbus1/HiddenLv/11', [('1', '236', 'linear')])], signature=dbus.Signature('(oa(tts))')), 'PeAllocCount': dbus.UInt64(237), 'UsedBytes': dbus.UInt64(994050048), 'FreeBytes': dbus.UInt64(1998321614848)}, []) Feb 25 11:32:26.212449: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Pv/1, com.redhat.lvmdbus1.Pv, {'PeSegments': dbus.Array([('0', '1'), ('1', '236'), ('237', '476437')], signature=dbus.Signature('(tt)')), 'Lv': dbus.Array([('/com/redhat/lvmdbus1/HiddenLv/12', [('0', '0', 'linear')]), ('/com/redhat/lvmdbus1/HiddenLv/13', [('1', '236', 'linear')])], signature=dbus.Signature('(oa(tts))')), 'PeAllocCount': dbus.UInt64(237), 'UsedBytes': dbus.UInt64(994050048), 'FreeBytes': dbus.UInt64(1998321614848)}, []) Feb 25 11:32:26.212964: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Pv/2, com.redhat.lvmdbus1.Pv, {'PeSegments': dbus.Array([('0', '1'), ('1', '236'), ('237', '476437')], signature=dbus.Signature('(tt)')), 'Lv': dbus.Array([('/com/redhat/lvmdbus1/HiddenLv/14', [('1', '236', 'linear')]), ('/com/redhat/lvmdbus1/HiddenLv/15', [('0', '0', 'linear')])], signature=dbus.Signature('(oa(tts))')), 'PeAllocCount': dbus.UInt64(237), 'UsedBytes': dbus.UInt64(994050048), 'FreeBytes': dbus.UInt64(1998321614848)}, []) Feb 25 11:32:26.213499: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Pv/3, com.redhat.lvmdbus1.Pv, {'PeSegments': dbus.Array([('0', '1'), ('1', '236'), ('237', '476437')], signature=dbus.Signature('(tt)')), 'Lv': dbus.Array([('/com/redhat/lvmdbus1/HiddenLv/16', [('1', '236', 'linear')]), ('/com/redhat/lvmdbus1/HiddenLv/17', [('0', '0', 'linear')])], signature=dbus.Signature('(oa(tts))')), 'PeAllocCount': dbus.UInt64(237), 'UsedBytes': dbus.UInt64(994050048), 'FreeBytes': dbus.UInt64(1998321614848)}, []) Feb 25 11:32:26.214020: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Pv/4, com.redhat.lvmdbus1.Pv, {'PeSegments': dbus.Array([('0', '1'), ('1', '236'), ('237', '476437')], signature=dbus.Signature('(tt)')), 'Lv': dbus.Array([('/com/redhat/lvmdbus1/HiddenLv/18', [('1', '236', 'linear')]), ('/com/redhat/lvmdbus1/HiddenLv/19', [('0', '0', 'linear')])], signature=dbus.Signature('(oa(tts))')), 'PeAllocCount': dbus.UInt64(237), 'UsedBytes': dbus.UInt64(994050048), 'FreeBytes': dbus.UInt64(1998321614848)}, []) Feb 25 11:32:26.215812: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Vg/0, com.redhat.lvmdbus1.Vg, {'Seqno': dbus.UInt64(304), 'FreeCount': dbus.UInt64(3812207), 'FreeBytes': dbus.UInt64(15989555068928)}, []) Feb 25 11:32:26.219152: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/HiddenLv/11, com.redhat.lvmdbus1.LvCommon, {'Devices': dbus.Array([(dbus.ObjectPath('/com/redhat/lvmdbus1/Pv/0'), [(dbus.UInt64(1), dbus.UInt64(236), dbus.String('linear'))])], signature=dbus.Signature('(oa(tts))')), 'SizeBytes': dbus.UInt64(989855744)}, []) Feb 25 11:32:26.219804: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/HiddenLv/13, com.redhat.lvmdbus1.LvCommon, {'Devices': dbus.Array([(dbus.ObjectPath('/com/redhat/lvmdbus1/Pv/1'), [(dbus.UInt64(1), dbus.UInt64(236), dbus.String('linear'))])], signature=dbus.Signature('(oa(tts))')), 'SizeBytes': dbus.UInt64(989855744)}, []) Feb 25 11:32:26.220474: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/HiddenLv/14, com.redhat.lvmdbus1.LvCommon, {'Devices': dbus.Array([(dbus.ObjectPath('/com/redhat/lvmdbus1/Pv/2'), [(dbus.UInt64(1), dbus.UInt64(236), dbus.String('linear'))])], signature=dbus.Signature('(oa(tts))')), 'SizeBytes': dbus.UInt64(989855744)}, []) Feb 25 11:32:26.221125: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/HiddenLv/16, com.redhat.lvmdbus1.LvCommon, {'Devices': dbus.Array([(dbus.ObjectPath('/com/redhat/lvmdbus1/Pv/3'), [(dbus.UInt64(1), dbus.UInt64(236), dbus.String('linear'))])], signature=dbus.Signature('(oa(tts))')), 'SizeBytes': dbus.UInt64(989855744)}, []) Feb 25 11:32:26.221762: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/HiddenLv/18, com.redhat.lvmdbus1.LvCommon, {'Devices': dbus.Array([(dbus.ObjectPath('/com/redhat/lvmdbus1/Pv/4'), [(dbus.UInt64(1), dbus.UInt64(236), dbus.String('linear'))])], signature=dbus.Signature('(oa(tts))')), 'SizeBytes': dbus.UInt64(989855744)}, []) Feb 25 11:32:26.224633: 436565:436565 - SIGNAL: PropertiesChanged(/com/redhat/lvmdbus1/Lv/1, com.redhat.lvmdbus1.LvCommon, {'Health': dbus.Struct(('s', 'reshaping'), signature=dbus.Signature('(ss)')), 'Attr': dbus.String('rwi-a-r-s-'), 'SegType': dbus.Array([dbus.String('raid6_n_6')], signature=dbus.Signature('s'))}, []) Feb 25 11:32:26.225688: 436565:436573 - Method complete: <function _udev_event at 0x7fe84d45e400> Feb 25 11:32:26.225834: 436565:436573 - Method start: <function _udev_event at 0x7fe84d45e400> with args () (callback = None) Feb 25 11:32:26.225953: 436565:436573 - Processing udev event Feb 25 11:32:26.226187: 436565:436574 - lvmdb - refresh entry Feb 25 11:32:26.305937: 436565:436574 - lvmdb - refresh exit Feb 25 11:32:26.317584: 436565:436573 - Method complete: <function _udev_event at 0x7fe84d45e400> Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHEA-2020:1881 |