Description of problem: Sanlock lockspace write times out while curl downloadImage jobs are writing on same NFS storage. 1. Starting task da6ef21e-ef66-4923-8260-99f37df8ef6b for downloadImage job on SD bdb91cce-a018-4661-915b-3214940524f5 2020-04-26 16:14:36,076+0200 INFO (jsonrpc/7) [vdsm.api] START downloadImage(methodArgs={'headers': {}, 'method': 'http', 'url': 'http://glance.ovirt.org:9292//v1/images/fe03ebf0-2cc9-4e20-bb2f-9d30e7abc0fd'}, spUUID='191a467c-ecf9-4010-a4ac-bd3ef862e893', sdUUID='bdb91cce-a018-4661-915b-3214940524f5', imgUUID='27389daf-258e-406e-86a9-a824faf637dd', volUUID='2974175c-8174-4e9c-b31e-b4f75e42b829') from=::ffff:192.168.205.2,54456, flow_id=e42a259c-9b1b-4cea-b381-a82fc28d57f7, task_id=da6ef21e-ef66-4923-8260-99f37df8ef6b (api:48) 2020-04-26 16:14:36,556+0200 INFO (jsonrpc/7) [vdsm.api] FINISH downloadImage return=None from=::ffff:192.168.205.2,54456, flow_id=e42a259c-9b1b-4cea-b381-a82fc28d57f7, task_id=da6ef21e-ef66-4923-8260-99f37df8ef6b (api:54) 2020-04-26 16:14:37,840+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Image.download succeeded in 1.77 seconds (__init__:312) 2020-04-26 16:14:37,840+0200 INFO (tasks/3) [storage.ThreadPool.WorkerThread] START task da6ef21e-ef66-4923-8260-99f37df8ef6b (cmd=<bound method Task.commit of <vdsm.storage.task.Task object at 0x7f9bf005f550>>, args=None) (threadPool:149) ... 2. Starting another task e757f316-e20f-4ab0-aa19-fa52a09f857a for donloadImage job on SD bdb91cce-a018-4661-915b-3214940524f5: 2020-04-26 16:14:41,686+0200 INFO (jsonrpc/6) [vdsm.api] START downloadImage(methodArgs={'headers': {}, 'method': 'http', 'url': 'http://glance.ovirt.org:9292//v1/images/fe03ebf0-2cc9-4e20-bb2f-9d30e7abc0fd'}, spUUID='191a467c-ecf9-4010-a4ac-bd3ef862e893', sdUUID='bdb91cce-a018-4661-915b-3214940524f5', imgUUID='5cb1beca-63a5-4864-9a2d-41bc9c9c68e8', volUUID='b180b9a2-e1fa-4fd1-ad82-e606ee34a154') from=::ffff:192.168.205.2,54456, flow_id=ce97b813-bb4d-404f-be58-2922c60037f0, task_id=e757f316-e20f-4ab0-aa19-fa52a09f857a (api:48) 2020-04-26 16:14:42,716+0200 INFO (jsonrpc/6) [vdsm.api] FINISH downloadImage return=None from=::ffff:192.168.205.2,54456, flow_id=ce97b813-bb4d-404f-be58-2922c60037f0, task_id=e757f316-e20f-4ab0-aa19-fa52a09f857a (api:54) 2020-04-26 16:14:43,834+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Image.download succeeded in 2.15 seconds (__init__:312) 2020-04-26 16:14:43,835+0200 INFO (tasks/6) [storage.ThreadPool.WorkerThread] START task e757f316-e20f-4ab0-aa19-fa52a09f857a (cmd=<bound method Task.commit of <vdsm.storage.task.Task object at 0x7f9bf0146b70>>, args=None) (threadPool:149) .... 3. Attempting to create another SD a3a050d6-cd2b-4cb8-a2d4-ca57525cedd0 on NFS share2 and writing lockspace fails due to sanlock io timeout: 2020-04-26 16:16:22,215+0200 INFO (jsonrpc/1) [vdsm.api] START createStorageDomain(storageType=1, sdUUID='a3a050d6-cd2b-4cb8-a2d4-ca57525cedd0', domainName='second-nfs', typeSpecificArg='192.168.207.2:/exports/nfs/share2', domClass=1, domVersion='5', block_size=512, max_hosts=250, options=None) from=::ffff:192.168.205.2,54384, flow_id=24f4c415, task_id=760cf549-8781-4447-8f28-fe4c77cddacc (api:48) ... 2020-04-26 16:16:54,195+0200 ERROR (jsonrpc/1) [storage.initSANLock] Cannot initialize SANLock for domain a3a050d6-cd2b-4cb8-a2d4-ca57525cedd0 (clusterlock:259) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/storage/clusterlock.py", line 250, in initSANLock lockspace_name, idsPath, align=alignment, sector=block_size) sanlock.SanlockException: (-202, 'Sanlock lockspace write failure', 'IO timeout') 2020-04-26 16:16:54,196+0200 INFO (jsonrpc/1) [vdsm.api] FINISH createStorageDomain error=Could not initialize cluster lock: () from=::ffff:192.168.205.2,54384, flow_id=24f4c415, task_id=760cf549-8781-4447-8f28-fe4c77cddacc (api:52) 2020-04-26 16:16:54,196+0200 ERROR (jsonrpc/1) [storage.TaskManager.Task] (Task='760cf549-8781-4447-8f28-fe4c77cddacc') Unexpected error (task:880) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/storage/clusterlock.py", line 250, in initSANLock lockspace_name, idsPath, align=alignment, sector=block_size) sanlock.SanlockException: (-202, 'Sanlock lockspace write failure', 'IO timeout') ... 4. 938 MB Write to NFS share1 for download image task da6ef21e-ef66-4923-8260-99f37df8ef6b has finished: 2020-04-26 16:17:48,825+0200 DEBUG (tasks/3) [root] SUCCESS: <err> = b"223+22550 records in\n223+22550 records out\n938409984 bytes (938 MB, 895 MiB) copied, 189.594 s, 4.9 MB/s\nfork_exec('/usr/bin/curl', 'curl', '-q', '--silent', '--fail', '--show-error', 'http://glance.ovirt.org:9292//v1/images/fe03ebf0-2cc9-4e20-bb2f-9d30e7abc0fd')\nfork_exec('/bin/dd', 'dd', 'bs=2M', 'of=/rhev/data-center/mnt/192.168.207.2:_exports_nfs_share1/bdb91cce-a018-4661-915b-3214940524f5/images/27389daf-258e-406e-86a9-a824faf637dd/2974175c-8174-4e9c-b31e-b4f75e42b829')\n"; <rc> = 0 (commands:224) ... 2020-04-26 16:17:51,077+0200 INFO (tasks/3) [storage.ThreadPool.WorkerThread] FINISH task da6ef21e-ef66-4923-8260-99f37df8ef6b (threadPool:151) 5. 938 MB Write to NFS share1 for download image task e757f316-e20f-4ab0-aa19-fa52a09f857a has finished: 2020-04-26 16:17:56,556+0200 DEBUG (tasks/6) [root] SUCCESS: <err> = b"220+18621 records in\n220+18621 records out\n938409984 bytes (938 MB, 895 MiB) copied, 191.032 s, 4.9 MB/s\nfork_exec('/usr/bin/curl', 'curl', '-q', '--silent', '--fail', '--show-error', 'http://glance.ovirt.org:9292//v1/images/fe03ebf0-2cc9-4e20-bb2f-9d30e7abc0fd')\nfork_exec('/bin/dd', 'dd', 'bs=2M', 'of=/rhev/data-center/mnt/192.168.207.2:_exports_nfs_share1/bdb91cce-a018-4661-915b-3214940524f5/images/5cb1beca-63a5-4864-9a2d-41bc9c9c68e8/b180b9a2-e1fa-4fd1-ad82-e606ee34a154')\n"; <rc> = 0 (commands:224) ... 2020-04-26 16:17:58,231+0200 INFO (tasks/6) [storage.ThreadPool.WorkerThread] FINISH task e757f316-e20f-4ab0-aa19-fa52a09f857a (threadPool:151) Version-Release number of selected component (if applicable): 4.40.13.1 How reproducible: Reoccurring on OST runs. Additional info: Discussed on https://bugzilla.redhat.com/1247135#c27 and onwards.
Setting severity and priority to high since this may break basic flows like creating storage domain, or fail lease renewal which may cause a lease to expire, killing vdsm or running VMs. We don't know how common is this issue, it probably affects only setups with very slow storage (like OST).
according the info, i think issue is with download image writes and not the upload image reads, so the title might be inaccurate.
The title say: "Uploading images from glance" which is correct. In the code we call this "download image". Feel free to make the title more clear.
(In reply to Nir Soffer from comment #3) > The title say: "Uploading images from glance" which is correct. In the code > we call > this "download image". Feel free to make the title more clear. Okay, as long it is clear that the "download" part is code-wise.
Amit can you please provide a clear verification scenario?
(In reply to Avihai from comment #5) > Amit can you please provide a clear verification scenario? Original issue seen on master 4.4 OST tests where NFS domain was in creation while glance image uploads were in progress to another NFS domain on the same NFS server. For testing independently I'll suggest the following first with an unfixed vdsm build: 1) Create NFS SD: nfs1 2) Run Import for glance images from ovirt-image-repository domain to nfs1 (in OST 2 ongoing uploads of 1GB each were enough to cause latency, but this may vary depending on QE env). 3) While image uploads are in progress, attempt it create another NFS SD: nfs2 on another export path of same storage, if there is sufficient latency it will cause it to fail with sanlock IO timeout error (-202) in vdsm.log - An alternative to step (3) is to run over host while the uploads are in progress: # touch /mnt1/ids # for x in `seq 1000`; do sanlock direct init -s LS:1/mnt1/ids:0 ; done where /mnt1 is mounted to another export path of the same NFS server used for domain nfs1, and see if calls return with "init done -202", on healthy condition all calls will print "init done 0" Repeating the process with a fixed vdsm build should not fail for nfs2 SD creation or alternatively return "init done 0" if tried manually with sanlock direct while uploads are in progress.
(In reply to Amit Bawer from comment #6) > (In reply to Avihai from comment #5) > > Amit can you please provide a clear verification scenario? > > Original issue seen on master 4.4 OST tests where NFS domain was in creation > while glance image uploads were in progress to another NFS domain on the > same NFS server. > > For testing independently I'll suggest the following first with an unfixed > vdsm build: > > 1) Create NFS SD: nfs1 > 2) Run Import for glance images from ovirt-image-repository domain to nfs1 > (in OST 2 ongoing uploads of 1GB each were enough to cause latency, but this > may vary depending on QE env). > 3) While image uploads are in progress, attempt it create another NFS SD: > nfs2 on another export path of same storage, if there is sufficient latency > it will cause it to fail with sanlock IO timeout error (-202) in vdsm.log > > - An alternative to step (3) is to run over host while the uploads are in > progress: > > # touch /mnt1/ids > # for x in `seq 1000`; do sanlock direct init -s LS:1/mnt1/ids:0 ; done > > where /mnt1 is mounted to another export path of the same NFS server used > for domain nfs1, > and see if calls return with "init done -202", on healthy condition all > calls will print "init done 0" > > Repeating the process with a fixed vdsm build should not fail for nfs2 SD > creation or alternatively return "init done 0" if tried manually with > sanlock direct while uploads are in progress. I tried several times in both ways with different image sizes (2G/10G). - Create new SD while image uploads are in progress - Operation succeed without errors. - Run over host while the uploads are in progress - Not sure what if operation succeeded or failed: "init done -19" - need your input.
(In reply to Evelina Shames from comment #7) > > I tried several times in both ways with different image sizes (2G/10G). > - Create new SD while image uploads are in progress - Operation succeed > without errors. > - Run over host while the uploads are in progress - Not sure what if > operation succeeded or failed: "init done -19" - need your input. Sounds like permission issue for sanlock to access the ids file you are trying to write into, also mentioned at bz1778485. Please check that file exists first and permissions allowing write for your user (preferably root) # id uid=0(root) gid=0(root) groups=0(root) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 # touch ids # ls -l ids -rw-r--r--. 1 root root 1048576 Jun 2 03:21 ids # sanlock direct init -s LS:1:ids:0 init done 0 For bad user "a", this will fail with -19 error code $ id uid=1000(a) gid=1000(a) groups=1000(a) context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 $ sanlock direct init -s LS:1:ids:0 init done -19
Verified with both ways: - Create new SD while image uploads are in progress - Operation succeed without errors. - Run over host while the uploads are in progress - Operation succeed: 'init done 0'. Version: rhv-4.4.1-2 Moving to 'Verified'.
This bugzilla is included in oVirt 4.4.1 release, published on July 8th 2020. Since the problem described in this bug report should be resolved in oVirt 4.4.1 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report.