+++ This bug is a downstream clone. The original bug is: +++ +++ bug 1450132 +++ ====================================================================== Description of problem: Additional logging of LVM commands in VDSM code is being requested. Version-Release number of selected component (if applicable): RHV 4.1 How reproducible: Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info: (Originally by Gordon Watson)
Verified with the following code: --------------------------------------- ovirt-engine-4.2.0-0.0.master.20170523140304.git04be891.el7.centos.noarch vdsm-4.20.0-886.gitf9accf8.el7.centos.x86_64 Verified with the following scenario: --------------------------------------- - create domain - create vm - run vm - stop vm - delete vm - delete domain There are now plentiful logs entries for storage.LVM Moving to VERIFIED! vdsm.logs ---------------------------------- grep "storage.LVM" vdsm.log |grep -v Refresh 2017-06-05 17:01:35,308+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=metadata, size=512m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:36,164+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=outbox, size=16m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:36,344+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=xleases, size=1024m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:36,666+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=leases, size=2048m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:36,967+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=ids, size=8m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:37,502+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=inbox, size=16m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:37,784+0300 INFO (jsonrpc/0) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=master, size=1024m, activate=True, contiguous=False, initialTags=()) (lvm:1144) 2017-06-05 17:01:39,448+0300 INFO (jsonrpc/0) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['master'] (lvm:1303) 2017-06-05 17:01:40,985+0300 INFO (jsonrpc/0) [storage.LVM] Changing VG tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, delTags=[], addTags=['MDT_PHYBLKSIZE=512', 'MDT_ROLE=Regular', 'MDT_POOL_UUID=', 'MDT_LEASERETRIES=3', 'MDT_CLASS=Data', 'MDT_IOOPTIMEOUTSEC=10', 'MDT_LOCKRENEWALINTERVALSEC=5', 'MDT_LOGBLKSIZE=512', 'MDT__SHA_CKSUM=bfa4e6d6c135aa659c732549c63db7b838bca3a2', 'MDT_DESCRIPTION=block55', 'MDT_LEASETIMESEC=60', 'MDT_SDUUID=013d24ae-7688-4f26-969f-45cd0a276f5c', 'MDT_PV0=pv:3514f0c5a516003f0&44&uuid:9poidM-Bf4i-5ohS-G0VN-3OUp-MUij-SvP2yW&44&pestart:0&44&pecount:277&44&mapoffset:0', 'MDT_VGUUID=vIM4r8-NE1s-4Ro6-uSWg-WBTq-c5uj-69Twno', 'MDT_TYPE=ISCSI', 'MDT_VERSION=4', 'MDT_LOCKPOLICY=']) (lvm:1404) 2017-06-05 17:01:41,118+0300 INFO (jsonrpc/0) [storage.LVM] Changing VG tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, delTags=['RHAT_storage_domain_UNREADY'], addTags=['RHAT_storage_domain']) (lvm:1404) 2017-06-05 17:01:42,561+0300 INFO (jsonrpc/0) [storage.LVM] Activating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['master'] (lvm:1295) 2017-06-05 17:02:22,645+0300 INFO (jsonrpc/2) [storage.LVM] Changing VG tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, delTags=['MDT__SHA_CKSUM=bfa4e6d6c135aa659c732549c63db7b838bca3a2', 'MDT_POOL_UUID='], addTags=['MDT__SHA_CKSUM=a767862c5577c80b66986e092f68e6e49abafc31', 'MDT_POOL_UUID=00000001-0001-0001-0001-000000000311']) (lvm:1404) 2017-06-05 17:05:04,806+0300 INFO (tasks/7) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=0ffbbb9c-0c8e-4bb0-931d-845162963573, size=5120m, activate=True, contiguous=False, initialTags=('OVIRT_VOL_INITIALIZING',)) (lvm:1144) 2017-06-05 17:05:05,207+0300 INFO (tasks/7) [storage.LVM] Change LV tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=0ffbbb9c-0c8e-4bb0-931d-845162963573, delTags=['OVIRT_VOL_INITIALIZING'], addTags=['MD_4', 'PU_00000000-0000-0000-0000-000000000000', 'IU_92a4ff3a-43bf-4a4f-adcb-b2c1926702be']) (lvm:1344) 2017-06-05 17:05:05,461+0300 INFO (tasks/7) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['0ffbbb9c-0c8e-4bb0-931d-845162963573'] (lvm:1303) 2017-06-05 17:08:46,091+0300 INFO (vm/0c4b4baf) [storage.LVM] Activating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['0ffbbb9c-0c8e-4bb0-931d-845162963573'] (lvm:1295) 2017-06-05 17:11:39,596+0300 INFO (jsonrpc/2) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['0ffbbb9c-0c8e-4bb0-931d-845162963573'] (lvm:1303) 2017-06-05 17:16:25,186+0300 INFO (tmap/0) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['0ffbbb9c-0c8e-4bb0-931d-845162963573']) (lvm:1179) 2017-06-05 17:16:25,186+0300 WARN (tmap/0) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/0ffbbb9c-0c8e-4bb0-931d-845162963573 (lvm:1186) 2017-06-05 17:17:57,778+0300 INFO (tasks/3) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=1ab3c5ca-2ccb-41c5-8337-d8e878489385, size=128m, activate=True, contiguous=False, initialTags=('OVIRT_VOL_INITIALIZING',)) (lvm:1144) 2017-06-05 17:17:58,204+0300 INFO (tasks/3) [storage.LVM] Change LV tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=1ab3c5ca-2ccb-41c5-8337-d8e878489385, delTags=['OVIRT_VOL_INITIALIZING'], addTags=['MD_4', 'PU_00000000-0000-0000-0000-000000000000', 'IU_fc00624d-fb1b-49b8-911f-07be7066fd30']) (lvm:1344) 2017-06-05 17:17:58,470+0300 INFO (tasks/3) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['1ab3c5ca-2ccb-41c5-8337-d8e878489385'] (lvm:1303) 2017-06-05 17:18:01,067+0300 INFO (tasks/7) [storage.LVM] Creating LV (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=362cdc1f-9dd4-4c4f-bc03-539df510c493, size=128m, activate=True, contiguous=False, initialTags=('OVIRT_VOL_INITIALIZING',)) (lvm:1144) 2017-06-05 17:18:01,478+0300 INFO (tasks/7) [storage.LVM] Change LV tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lv=362cdc1f-9dd4-4c4f-bc03-539df510c493, delTags=['OVIRT_VOL_INITIALIZING'], addTags=['MD_5', 'PU_00000000-0000-0000-0000-000000000000', 'IU_fac92f0a-ea5d-4023-a8cd-ce4a21cbe6ad']) (lvm:1344) 2017-06-05 17:18:01,715+0300 INFO (tasks/7) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['362cdc1f-9dd4-4c4f-bc03-539df510c493'] (lvm:1303) 2017-06-05 17:18:20,866+0300 INFO (tasks/9) [storage.LVM] Activating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['362cdc1f-9dd4-4c4f-bc03-539df510c493'] (lvm:1295) 2017-06-05 17:18:21,012+0300 INFO (tasks/9) [storage.LVM] Extending LV 013d24ae-7688-4f26-969f-45cd0a276f5c/362cdc1f-9dd4-4c4f-bc03-539df510c493 to 1 megabytes (lvm:1210) 2017-06-05 17:18:21,537+0300 INFO (tasks/9) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['362cdc1f-9dd4-4c4f-bc03-539df510c493'] (lvm:1303) 2017-06-05 17:18:24,373+0300 INFO (tasks/6) [storage.LVM] Activating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['1ab3c5ca-2ccb-41c5-8337-d8e878489385'] (lvm:1295) 2017-06-05 17:18:24,521+0300 INFO (tasks/6) [storage.LVM] Extending LV 013d24ae-7688-4f26-969f-45cd0a276f5c/1ab3c5ca-2ccb-41c5-8337-d8e878489385 to 1 megabytes (lvm:1210) 2017-06-05 17:18:25,017+0300 INFO (tasks/6) [storage.LVM] Deactivating lvs: vg=013d24ae-7688-4f26-969f-45cd0a276f5c lvs=['1ab3c5ca-2ccb-41c5-8337-d8e878489385'] (lvm:1303) 2017-06-05 17:20:13,457+0300 INFO (jsonrpc/5) [storage.LVM] Changing VG tags (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, delTags=['MDT__SHA_CKSUM=a767862c5577c80b66986e092f68e6e49abafc31', 'MDT_POOL_UUID=00000001-0001-0001-0001-000000000311'], addTags=['MDT__SHA_CKSUM=bfa4e6d6c135aa659c732549c63db7b838bca3a2', 'MDT_POOL_UUID=']) (lvm:1404) 2017-06-05 17:21:01,835+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['metadata']) (lvm:1179) 2017-06-05 17:21:01,836+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/metadata (lvm:1186) 2017-06-05 17:21:01,990+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['362cdc1f-9dd4-4c4f-bc03-539df510c493']) (lvm:1179) 2017-06-05 17:21:02,259+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['xleases']) (lvm:1179) 2017-06-05 17:21:02,259+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/xleases (lvm:1186) 2017-06-05 17:21:02,507+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['master']) (lvm:1179) 2017-06-05 17:21:02,508+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/master (lvm:1186) 2017-06-05 17:21:02,769+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['inbox']) (lvm:1179) 2017-06-05 17:21:02,770+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/inbox (lvm:1186) 2017-06-05 17:21:03,036+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['1ab3c5ca-2ccb-41c5-8337-d8e878489385']) (lvm:1179) 2017-06-05 17:21:03,263+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['leases']) (lvm:1179) 2017-06-05 17:21:03,264+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/leases (lvm:1186) 2017-06-05 17:21:03,494+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['ids']) (lvm:1179) 2017-06-05 17:21:03,495+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/ids (lvm:1186) 2017-06-05 17:21:03,853+0300 INFO (jsonrpc/5) [storage.LVM] Removing LVs (vg=013d24ae-7688-4f26-969f-45cd0a276f5c, lvs=['outbox']) (lvm:1179) 2017-06-05 17:21:03,854+0300 WARN (jsonrpc/5) [storage.LVM] Removing active volume 013d24ae-7688-4f26-969f-45cd0a276f5c/outbox (lvm:1186) Also from vdsm.log ------------------------------ 2017-06-05 17:24:06,870+0300 INFO (jsonrpc/5) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:06,871+0300 INFO (jsonrpc/5) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:08,095+0300 INFO (jsonrpc/4) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:08,095+0300 INFO (jsonrpc/4) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:19,303+0300 INFO (jsonrpc/0) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:19,303+0300 INFO (jsonrpc/0) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:20,219+0300 INFO (jsonrpc/3) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:20,219+0300 INFO (jsonrpc/3) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:31,328+0300 INFO (jsonrpc/5) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:31,328+0300 INFO (jsonrpc/5) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:32,513+0300 INFO (jsonrpc/4) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:32,513+0300 INFO (jsonrpc/4) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:33,457+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing lvs: vg=69d75227-8aa8-47d7-a110-6365c385f17d lvs=['metadata'] (lvm:1291) 2017-06-05 17:24:33,457+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing LVs (vg=69d75227-8aa8-47d7-a110-6365c385f17d, lvs=['metadata']) (lvm:1319) 2017-06-05 17:24:33,809+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing lvs: vg=69d75227-8aa8-47d7-a110-6365c385f17d lvs=['ids'] (lvm:1291) 2017-06-05 17:24:33,810+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing LVs (vg=69d75227-8aa8-47d7-a110-6365c385f17d, lvs=['ids']) (lvm:1319) 2017-06-05 17:24:33,920+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing lvs: vg=69d75227-8aa8-47d7-a110-6365c385f17d lvs=['leases'] (lvm:1291) 2017-06-05 17:24:33,921+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing LVs (vg=69d75227-8aa8-47d7-a110-6365c385f17d, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:34,095+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing lvs: vg=69d75227-8aa8-47d7-a110-6365c385f17d lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1291) 2017-06-05 17:24:34,096+0300 INFO (monitor/69d7522) [storage.LVM] Refreshing LVs (vg=69d75227-8aa8-47d7-a110-6365c385f17d, lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master']) (lvm:1319) 2017-06-05 17:24:43,718+0300 INFO (jsonrpc/3) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:43,718+0300 INFO (jsonrpc/3) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:44,904+0300 INFO (jsonrpc/2) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:44,904+0300 INFO (jsonrpc/2) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:56,130+0300 INFO (jsonrpc/6) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:56,131+0300 INFO (jsonrpc/6) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:24:57,514+0300 INFO (jsonrpc/1) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:24:57,515+0300 INFO (jsonrpc/1) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319) 2017-06-05 17:25:08,749+0300 INFO (jsonrpc/4) [storage.LVM] Refreshing lvs: vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a lvs=['leases'] (lvm:1291) 2017-06-05 17:25:08,749+0300 INFO (jsonrpc/4) [storage.LVM] Refreshing LVs (vg=5f6e0626-3a8c-41ed-b843-7a9290a4db5a, lvs=['leases']) (lvm:1319)
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-2017:1696