2059641 – "dm_report_field_percent: percentage too large" leads to lvmdbus KeyError: 'seg_pe_ranges' traceback when vdo is auto resizing

Bug 2059641 - "dm_report_field_percent: percentage too large" leads to lvmdbus KeyError: 'seg_pe_ranges' traceback when vdo is auto resizing [NEEDINFO]

Summary: "dm_report_field_percent: percentage too large" leads to lvmdbus KeyError: '...

Keywords:
Status:	NEW
Alias:	None
Product:	Red Hat Enterprise Linux 9
Classification:	Red Hat
Component:	lvm2
Sub Component:
Version:	9.0
Hardware:	x86_64
OS:	Linux
Priority:	unspecified
Severity:	low
Target Milestone:	rc
Target Release:	---
Assignee:	Zdenek Kabelac
QA Contact:	cluster-qe
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2022-03-01 15:31 UTC by Corey Marthaler
Modified:	2023-08-10 15:40 UTC (History)
CC List:	8 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:
Flags:	zkabelac: needinfo? (cmarthal)

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Issue Tracker	RHELPLAN-114133	0	None	None	None	2022-03-01 15:45:28 UTC

Description Corey Marthaler 2022-03-01 15:31:11 UTC

Description of problem:
I started seeing this over and over when testing the auto pool extend functionality of vdo volumes.



Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: 2108:2114 - CMD= /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,vdo_operating_mode,vdo_compression_state,vdo_index_state,vdo_used_size,vdo_saving_percent --configreport seg -o seg_pe_ranges,segtype,lv_uuid,vdo_compression,vdo_deduplication,vdo_use_metadata_hints,vdo_minimum_io_size,vdo_block_map_cache_size,vdo_block_map_era_length,vdo_use_sparse_index,vdo_index_memory_size,vdo_slab_size,vdo_ack_threads,vdo_bio_threads,vdo_bio_rotation,vdo_cpu_threads,vdo_hash_zone_threads,vdo_logical_threads,vdo_physical_threads,vdo_max_discard,vdo_write_policy,vdo_header_size --configreport pvseg -o pvseg_start,pvseg_size,segtype,pv_uuid,lv_uuid,pv_name --reportformat json --config global/notify_dbus=0
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: 2108:2114 - EC= 5
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: 2108:2114 - STDOUT=
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:   {
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:      "report": [
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:          {
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              "vg": [
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "vg_fmt":"lvm2", "vg_size":"13998879670272", "vg_free":"13991254425600", "vg_sysid":"", "vg_extent_size":"4194304", "vg_extent_count":"3337593", "vg_free_count":"3335775", "vg_profile":"", "max_lv":"0", "max_pv":"0", "pv_count":"7", "lv_count":"2", "snap_count":"0", "vg_seqno":"4", "vg_mda_count":"7", "vg_mda_free":"518144", "vg_mda_size":"1044480", "vg_mda_used_count":"7", "vg_attr":"wz--n-", "vg_tags":""}
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              ]
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              ,
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              "pv": [
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sdc1", "pv_uuid":"VOkuSX-qoBq-KYF5-hR29-0Wiw-0TMH-GWIFPV", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1992214708224", "pv_used":"7625244672", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"1818", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""},
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sde1", "pv_uuid":"hQ6HHO-4zYB-2HVm-DDDq-DR1I-6uxv-AwrKdh", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1999839952896", "pv_used":"0", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""},
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sdd1", "pv_uuid":"pHgnc6-exmn-jCod-q4kv-FF8y-Lnbu-GPNopR", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1999839952896", "pv_used":"0", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""},
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sdf1", "pv_uuid":"fkjJUU-tg25-0X51-eZPC-CbcH-u4DF-87C4k2", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1999839952896", "pv_used":"0", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""},
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sdg1", "pv_uuid":"3IFY4V-m4rE-d0Sh-jG6s-qigD-lAyw-ul2FgY", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1999839952896", "pv_used":"0", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""},
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sdh1", "pv_uuid":"EPIUsj-S0pi-N08A-WqHn-kTIC-5cIN-3qNgIU", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1999839952896", "pv_used":"0", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""},
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"pv_name":"/dev/sdi1", "pv_uuid":"Lq1UvT-dmQx-EFkb-qzTa-kxOh-nYBD-K3L7LO", "pv_fmt":"lvm2", "pv_size":"1999839952896", "pv_free":"1999839952896", "pv_used":"0", "dev_size":"1999844106240", "pv_mda_size":"1044480", "pv_mda_free":"518144", "pv_ba_start":"0", "pv_ba_size":"0", "pe_start":"1048576", "pv_pe_count":"476799", "pv_pe_alloc_count":"0", "pv_attr":"a--", "pv_tags":"", "vg_name":"vdo_sanity", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "pv_missing":""}
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              ]
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              ,
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              "lv": [
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:                  {"lv_uuid":"U7tZDg-QCtb-ZLbG-fSFn-nNTQ-N8OS-2Ypoox", "lv_name":"[vdo_pool_vdata]", "lv_path":"", "lv_size":"7625244672", "vg_name":"vdo_sanity", "pool_lv_uuid":"", "pool_lv":"", "origin_uuid":"", "origin":"", "data_percent":"", "lv_attr":"Dwi-ao----", "lv_tags":"", "vg_uuid":"gGiEcu-Em6j-l5Wb-5r0l-dWsZ-VBfU-nXEfQX", "lv_active":"active", "data_lv":"", "metadata_lv":"", "lv_parent":"", "lv_role":"private,vdo,pool,data", "lv_layout":"linear", "snap_percent":"", "metadata_percent":"", "copy_percent":"", "sync_percent":"", "lv_metadata_size":"", "move_pv":"", "move_pv_uuid":"", "vdo_operating_mode":"", "vdo_compression_state":"", "vdo_index_state":"", "vdo_used_size":"", "vdo_saving_percent":""}
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:              ]
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:          }
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:      ]
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  }
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: 2108:2114 - STDERR=
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:   dm_report_field_percent: percentage too large.
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  _do_report_object: report function failed for field vdo_saving_percent
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  dm_report_field_percent: percentage too large.
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  _do_report_object: report function failed for field vdo_saving_percent
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: 2108:2114 - update_thread exception:
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: Traceback (most recent call last):
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  File "/usr/lib/python3.9/site-packages/lvmdbusd/fetch.py", line 167, in update_thread
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:    num_changes = load(refresh, emit_signal, cache_refresh, log,
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  File "/usr/lib/python3.9/site-packages/lvmdbusd/fetch.py", line 80, in load
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:    cfg.db.refresh(log)
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  File "/usr/lib/python3.9/site-packages/lvmdbusd/lvmdb.py", line 434, in refresh
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:    self.pv_lvs, self.lv_pvs = self._parse_pv_in_lvs()
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  File "/usr/lib/python3.9/site-packages/lvmdbusd/lvmdb.py", line 366, in _parse_pv_in_lvs
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:    segs = self._build_segments(i['seg_pe_ranges'], i['segtype'])
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]: KeyError: 'seg_pe_ranges'


Version-Release number of selected component (if applicable):
kernel-5.14.0-58.el9    BUILT: Thu Feb 10 11:18:21 AM CST 2022
lvm2-2.03.14-4.el9    BUILT: Wed Feb 16 06:01:21 AM CST 2022
lvm2-libs-2.03.14-4.el9    BUILT: Wed Feb 16 06:01:21 AM CST 2022
lvm2-dbusd-2.03.14-4.el9    BUILT: Wed Feb 16 07:23:08 AM CST 2022

Comment 2 Tony Asleson 2022-03-01 18:38:43 UTC

This doesn't look like a lvmdbusd issue.  Lvm isn't returning a column that was requested `seg_pe_ranges`.

Additionally, lvm looks like internally it is running into issues:

Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:   dm_report_field_percent: percentage too large.
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  _do_report_object: report function failed for field vdo_saving_percent
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  dm_report_field_percent: percentage too large.
Mar  1 09:12:05 hayes-02 lvmdbusd[2108]:  _do_report_object: report function failed for field vdo_saving_percent

Also, an exported VG is present as the exit code is 5.

Comment 3 Zdenek Kabelac 2022-08-10 13:04:17 UTC

Can we get please attached results of:

lvs -a

dmsetup table

dmsetup status 

grep -r "" /sys/block/dm*/vdo/statistics


once this case happens?

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