Bug 1811682 - lvcreate succeeds with warning: "WARNING: Logical volume not zeroed"
Summary: lvcreate succeeds with warning: "WARNING: Logical volume not zeroed"
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: vdsm
Classification: oVirt
Component: General
Version: 4.40.0
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ovirt-4.4.5-1
: ---
Assignee: Roman Bednář
QA Contact: meital avital
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-03-09 14:34 UTC by David Vaanunu
Modified: 2021-03-23 11:54 UTC (History)
5 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2021-02-11 14:48:39 UTC
oVirt Team: Storage
Embargoed:


Attachments (Terms of Use)
manager log file (1.68 MB, text/plain)
2020-03-09 14:34 UTC, David Vaanunu
no flags Details

Description David Vaanunu 2020-03-09 14:34:01 UTC
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:

Comment 1 Tal Nisan 2020-03-16 15:17:22 UTC
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?

Comment 2 Nir Soffer 2020-03-16 16:42:47 UTC
(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.

Comment 3 Tal Nisan 2020-03-23 15:45:48 UTC
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

Comment 5 David Vaanunu 2020-04-07 18:09:00 UTC
Have no RHV4.4 now
I'm going to install 4.4 latest. 
It will take time until we can start the testing

Comment 6 Roman Bednář 2021-02-11 14:15:37 UTC
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)


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