Hide Forgot
Created attachment 1668671 [details] manager log file Description of problem: "WARNING: Logical volume Bug/worker-006-000001 not zeroed" message while running extend.py script Version-Release number of selected component (if applicable): vdsm-4.40.0-164.git38a19bb.el8ev.x86_64 rhv-release-4.4.0-13-999.noarch redhat-release-8.2-0.7.el8.x86_64 python2-subprocess32-3.2.6-14.el7.x86_64 How reproducible: While trying to reproduce Bug1553133 on RHEL8.2, running extend.py script on 2 hosts. (Create, Extend & Remove LV) Steps to Reproduce: 1. Copy the script from: https://github.com/oVirt/vdsm/blob/master/tests/storage/stress/extend.py 2. On the first host: python2 extend.py create-vg <VG_NAME> /dev/mapper/<LUN_ID> firewall-cmd --add-port=8000/tcp python2 extend.py run-manager -p 8000 <VG_NAME> /dev/mapper/<LUN_ID> 2>1_run-manager.log 3. On the second host: python2 extend.py run-regular -p 8000 <First Host hostnae/IP> <VG_NAME> /dev/mapper/<LUN_ID> 2>1_run-regular.log Actual results: LV commands create, extend and remove - run successfully. lvcreate command --> WARNING: Logical volume Bug/worker-006-000001 not zeroed.\n' Expected results: LV commands create, extend and remove - run successfully. "not zeroed" should not be display Additional info:
I don't find anything wrong with that, it's a script used as a reproducer and the message doesn't seem to be problematic, Nir anything you want to add?
(In reply to Tal Nisan from comment #1) > I don't find anything wrong with that, it's a script used as a reproducer > and the message doesn't seem to be problematic, Nir anything you want to add? The issue is not the stress test. We will probably have the same warnings in vdsm, and these warnings will be logged as WARN log message. Warnings in our logs are bad, causing users and QE to open unhelpful bugs about them. We need to: - Check if the warnings appear in vdsm logs on rhel 8.2 - Check why the warning is logged by lvm, maybe they should stop logging it - If this is not a real warning suppress it in vdsm until lvm stop to log it.
David, Ilan, please take a RHV 4.4 run on the tiers and on scale testing and run a grep on the logs for this warning, let us know please if you found it or not and we'll know how to proceed
Have no RHV4.4 now I'm going to install 4.4 latest. It will take time until we can start the testing
There are no warnings logged by VDSM upon creating or extending logical volume. The warning comes from lvm when device is not zeroed. There are some defaults and flag relations at play: The reason for warning presence when running extend.py reproducer script is that it runs lvcreate with "--activate n". Which (in lvm) defaults to "--zero n" and warning is shown. VDSM on the other hand does not use activation flag so lvm defaults to "--activate y" which behind the scenes defaults to "--zero y" (see 'man 8 lvcreate' for details). When running create and extend operations via VDSM I was not able to observe any warnings. CREATE: 2021-02-11 08:59:10,079-0500 INFO (jsonrpc/0) [vdsm.api] START createVolume(sdUUID='40b0c8e1-e646-4e56-8420-827252743f93', spUUID='4fc1c8aa-6245-11eb-83ae-525400ea2c38', imgUUID='9e2c562e-1351-4111-affc-a28ac85daf46', size='10737418240', volFormat=4, preallocate=2, diskType='DATA', volUUID='67629d7b-38ce-4f91-83ee-35698716d4f6', desc='{"DiskAlias":"vm1","DiskDescription":""}', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000', initialSize=None, addBitmaps=False) from=::ffff:192.168.122.156,49800, flow_id=55bae408-29b7-4ec5-b80d-257f2d377e3e, task_id=9433aa55-a4b4-4597-a7c1-642d874b9191 (api:48) 2021-02-11 08:59:10,080-0500 DEBUG (jsonrpc/0) [storage.ResourceManager] Trying to register resource '00_storage.40b0c8e1-e646-4e56-8420-827252743f93' for lock type 'shared' (resourceManager:474) 2021-02-11 08:59:10,081-0500 DEBUG (jsonrpc/0) [storage.ResourceManager] Resource '00_storage.40b0c8e1-e646-4e56-8420-827252743f93' is free. Now locking as 'shared' (1 active user) (resourceManager:531) 2021-02-11 08:59:10,081-0500 DEBUG (jsonrpc/0) [storage.ResourceManager.Request] (ResName='00_storage.40b0c8e1-e646-4e56-8420-827252743f93', ReqID='2f08c659-e79a-418a-b843-9118b8f127ec') Granted request (resourceManager:221) 2021-02-11 08:59:10,081-0500 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='9433aa55-a4b4-4597-a7c1-642d874b9191') _resourcesAcquired: 00_storage.40b0c8e1-e646-4e56-8420-827252743f93 (shared) (task:856) 2021-02-11 08:59:10,081-0500 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='9433aa55-a4b4-4597-a7c1-642d874b9191') ref 1 aborting False (task:1008) 2021-02-11 08:59:10,081-0500 DEBUG (jsonrpc/0) [storage.oop] Creating ioprocess Global (outOfProcess:89) 2021-02-11 08:59:10,082-0500 INFO (jsonrpc/0) [IOProcessClient] (Global) Starting client (__init__:340) 2021-02-11 08:59:10,109-0500 INFO (ioprocess/12899) [IOProcess] (Global) Starting ioprocess (__init__:465) 2021-02-11 08:59:10,118-0500 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='9433aa55-a4b4-4597-a7c1-642d874b9191') _save: orig /rhev/data-center/4fc1c8aa-6245-11eb-83ae-525400ea2c38/mastersd/master/tasks/9433aa55-a4b4-4597-a7c1-642d874b9191 temp /rhev/data-center/4fc1c8aa-6245-11eb-83ae-525400ea2c38/mastersd/master/tasks/9433aa55-a4b4-4597-a7c1-642d874b9191.temp (task:781) 2021-02-11 08:59:10,208-0500 DEBUG (jsonrpc/0) [storage.TaskManager] scheduled job createVolume for task 9433aa55-a4b4-4597-a7c1-642d874b9191 (taskManager:79) 2021-02-11 08:59:10,208-0500 INFO (jsonrpc/0) [vdsm.api] FINISH createVolume return=None from=::ffff:192.168.122.156,49800, flow_id=55bae408-29b7-4ec5-b80d-257f2d377e3e, task_id=9433aa55-a4b4-4597-a7c1-642d874b9191 (api:54) EXTEND: #vdsm-client Volume extendSize storagepoolID="4fc1c8aa-6245-11eb-83ae-525400ea2c38" \ storagedomainID="40b0c8e1-e646-4e56-8420-827252743f93" \ imageID="127d4fd0-1597-4f28-b6d3-d5cf491ab924" \ volumeID="127d4fd0-1597-4f28-b6d3-d5cf491ab924" \ newSize="11811160064" 2021-02-10 09:20:19,074-0500 INFO (tasks/6) [storage.Volume] executing a raw capacity extension for volume 127d4fd0-1597-4f28-b6d3-d5cf491ab924 from capacity 10737418240 to capacity 11811160064 (volume:1389) 2021-02-10 09:20:19,075-0500 DEBUG (tasks/6) [storage.TaskManager.Task] (Task='b6b5310c-bea8-4ab6-b70c-4d10b044a5f2') _save: orig /rhev/data-center/4fc1c8aa-6245-11eb-83ae-525400ea2c38/mastersd/master/tasks/b6b5310c-bea8-4ab6-b70c-4d10b044a5f2 temp /rhev/data-center/4fc1c8aa-6245-11eb-83ae-525400ea2c38/mastersd/master/tasks/b6b5310c-bea8-4ab6-b70c-4d10b044a5f2.temp (task:781) 2021-02-10 09:20:19,263-0500 INFO (tasks/6) [storage.LVM] Extending LV 40b0c8e1-e646-4e56-8420-827252743f93/127d4fd0-1597-4f28-b6d3-d5cf491ab924 to 11264 megabytes (lvm:1651) 2021-02-10 09:20:19,427-0500 DEBUG (tasks/6) [storage.LVM] lvs reloaded (lvm:759) 2021-02-10 09:20:19,427-0500 DEBUG (tasks/6) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/dd iflag=direct skip=2096 bs=512 if=/dev/40b0c8e1-e646-4e56-8420-827252743f93/metadata count=1 (cwd None) (commands:211) 2021-02-10 09:20:19,445-0500 DEBUG (mailbox-spm) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 dd if=/rhev/data-center/4fc1c8aa-6245-11eb-83ae-525400ea2c38/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:211) 2021-02-10 09:20:19,457-0500 DEBUG (periodic/1) [storage.TaskManager.Task] (Task='abdd4368-37c5-4b50-9ea5-5183e0bd1889') moving from state finished -> state preparing (task:624)