Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1811590

Summary:

Failed to copy template disk on NFS domain

Product:

[oVirt] ovirt-engine

Reporter:

Evelina Shames <eshames>

Component:

BLL.Storage

Assignee:

Benny Zlotnik <bzlotnik>

Status:

CLOSED WORKSFORME

QA Contact:

Avihai <aefrat>

Severity:

high

Docs Contact:

Priority:

unspecified

Version:

4.4.0

CC:

aefrat, bugs, lsvaty, nsoffer

Target Milestone:

ovirt-4.4.0

Keywords:

Automation, AutomationBlocker, Regression

Target Release:

---

Flags:

pm-rhel: ovirt-4.4+
pm-rhel: blocker?

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

Fixed In Version:

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2020-04-01 09:43:57 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

Storage

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
Logs	none
Logs	none
vdsm logs	none
logs-part1	none
logs-part2	none
older engine log and journalctl log with latest reproduction logs	none

Description Evelina Shames 2020-03-09 10:03:31 UTC

Created attachment 1668620 [details]
Logs

Description of problem:
Copying template disk to NFS fails with the following errors:
2020-03-09 11:07:33,780+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mi
xed_3 command HSMGetAllTasksStatusesVDS failed: value=Volume already exists: ('7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7',) abortedcode=212
2020-03-09 11:07:33,780+02 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [] SPMAsyncTask::PollTask: Polling task 'd22e3ae7-5ada-4fad-8770-2ef48aacac1d' (Paren
t Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2020-03-09 11:07:33,783+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [] BaseAsyncTask::logEndTaskFailure: Task 'd22e3ae7-5ada-4fad-8770-2ef48aacac1d' (Par
ent Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure:
-- Result: 'cleanSuccess'
-- Message: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = value=Volume already exists: ('7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7',) abortedcode=212',
-- Exception: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = value=Volume already exists: ('7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7',) abortedcode=212'
2020-03-09 11:07:33,783+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '5bf99358-2e97-45
c1-86ae-ec2140744612' has ended -> executing 'endAction'
2020-03-09 11:07:33,783+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '5bf9935
8-2e97-45c1-86ae-ec2140744612'): calling endAction '.
2020-03-09 11:07:33,784+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-106033) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'CreateVolumeContain
er',
2020-03-09 11:07:33,789+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (EE-ManagedThreadFactory-engine-Thread-106033) [69614422-fc30-44b6-b411-45cbb70eb740] Ending command 'org.ovirt.engine.core.bll.s
torage.disk.image.CreateVolumeContainerCommand' with failure.

020-03-09 11:07:42,128+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-41) [69614422-fc30-44b6-b411-45cbb70eb740] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand' with failure.
2020-03-09 11:07:43,135+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-99) [69614422-fc30-44b6-b411-45cbb70eb740] Command 'CopyImageGroupWithData' id: '7940aa15-f93e-4a99-ba5e-b3a7d4760cfb' child commands '[dd7a27ae-3163-4fee-9b03-d1d6ea778aaa]' executions were completed, status 'FAILED'
2020-03-09 11:07:44,138+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94) [69614422-fc30-44b6-b411-45cbb70eb740] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand' with failure.
2020-03-09 11:07:45,170+02 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-98) [69614422-fc30-44b6-b411-45cbb70eb740] Command 'CopyImageGroup' id: '4e50fb12-887f-497d-91ed-0fd1d37d37c4' child commands '[7940aa15-f93e-4a99-ba5e-b3a7d4760cfb]' executions were completed, status 'FAILED'
2020-03-09 11:07:45,170+02 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-98) [69614422-fc30-44b6-b411-45cbb70eb740] Command 'CopyImageGroup' id: '4e50fb12-887f-497d-91ed-0fd1d37d37c4' Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands.
2020-03-09 11:07:46,190+02 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-87) [69614422-fc30-44b6-b411-45cbb70eb740] Command 'MoveOrCopyDisk' id: '25623353-7877-4dfb-94ba-fce4ff4a80ef' child commands '[4e50fb12-887f-497d-91ed-0fd1d37d37c4]' executions were completed, status 'FAILED'
2020-03-09 11:07:47,205+02 ERROR [org.ovirt.engine.core.bll.storage.disk.MoveOrCopyDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [69614422-fc30-44b6-b411-45cbb70eb740] Ending command 'org.ovirt.engine.core.bll.storage.disk.MoveOrCopyDiskCommand' with failure.
2020-03-09 11:07:47,209+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [69614422-fc30-44b6-b411-45cbb70eb740] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupCommand' with failure.
2020-03-09 11:07:47,217+02 INFO  [org.ovirt.engine.core.bll.storage.disk.MoveOrCopyDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] Lock freed to object 'EngineLock:{exclusiveLocks='[e205b36c-bd18-45e1-bc6b-097db4be64bb=DISK]', sharedLocks='[fd5f518e-5eec-479e-8f3d-69f571efd71a=TEMPLATE]'}'
2020-03-09 11:07:47,230+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] EVENT_ID: USER_COPIED_DISK_FINISHED_FAILURE(2,007), User admin@internal-authz finished with error copying disk latest-rhel-guest-image-8.1-infra to domain nfs_1.


Version-Release number of selected component (if applicable):
Software Version:4.4.0-0.24.master.el8ev


How reproducible:
Reproduction is easy 100% on jenkins-vm-09.lab.eng.tlv2.redhat.com


Steps to Reproduce:
via webadmin -> template -> latest-rhel-guest-image-8.1-infra -> copy disk to 'nfs_1' SD

Actual results:
Failed to copy disk to nfs_1


Expected results:
Operation should succeed


Additional info:
Logs are attached

Comment 1 Evelina Shames 2020-03-09 12:25:12 UTC

Created attachment 1668655 [details]
Logs

Comment 2 Evelina Shames 2020-03-09 12:31:23 UTC

Created attachment 1668656 [details]
vdsm logs

Sorry, attached wrong logs, attaching the relevant:
2020-03-09 14:26:39,829+0200 ERROR (tasks/7) [storage.TaskManager.Task] (Task='045e6406-80c1-4d9c-b137-e4096a04d186') Unexpected error (task:874)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 542, in _truncate_volume
    creatExcl=True)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/outOfProcess.py", line 345, in truncateFile
    ioproc.truncate(path, size, mode if mode is not None else 0, creatExcl)
  File "/usr/lib/python3.6/site-packages/ioprocess/__init__.py", line 576, in truncate
    self.timeout)
  File "/usr/lib/python3.6/site-packages/ioprocess/__init__.py", line 448, in _sendCommand
    raise OSError(errcode, errstr)
FileExistsError: [Errno 17] File exists

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 881, in _run
    return fn(*args, **kargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 344, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/securable.py", line 79, in wrapper
    return method(self, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/sp.py", line 1874, in createVolume
    initial_size=initialSize)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/sd.py", line 968, in createVolume
    initial_size=initial_size)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/volume.py", line 1163, in create
    initial_size=initial_size)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 457, in _create
    imgUUID, srcImgUUID, srcVolUUID)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 513, in _create_cow_volume
    cls._truncate_volume(vol_path, 0, vol_id, dom)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 545, in _truncate_volume
    raise se.VolumeAlreadyExists(vol_id)
vdsm.storage.exception.VolumeAlreadyExists: Volume already exists: ('7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7',)

Comment 3 Evelina Shames 2020-03-09 12:38:15 UTC

This is blocking our automation, a lot of test cases fail because SD nfs_1 doesn't contain the template disk and copying template disk to nfs_1 fails

Comment 4 Avihai 2020-03-09 13:20:45 UTC

Manual Steps for bug currently does via jenkins/ansible scripts:

1) Create DC+ cluster + create 3xstorage domains per storage flavor(FCP,ISCSI,NFS,glusterFS)
2) import imageRHEL8 infra latest ) as a template from glance.
3) copy template disk to all existing SD's -> Here we see the issue when copying with the template disk to one of the NFS SD(nfs_1).

Comment 5 Benny Zlotnik 2020-03-09 17:12:37 UTC

it's clear the volume already exists on the SD, when was it created?

Comment 7 Evelina Shames 2020-03-15 10:10:09 UTC

Created attachment 1670223 [details]
logs-part1

Comment 8 Evelina Shames 2020-03-15 10:11:24 UTC

Created attachment 1670224 [details]
logs-part2

Comment 10 Avihai 2020-03-17 14:23:57 UTC

(In reply to Benny Zlotnik from comment #5)
> it's clear the volume already exists on the SD, when was it created?
This volume( '7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7' ) father image is template disk latest-rhel-guest-image-8.1-infra (id='e205b36c-bd18-45e1-bc6b-097db4be64bb') and looking from the timestamps the creation of the same volume is created on many storage domain (as we copy the template disk to all active storage domains).

Volume '7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7' existed on SD 'nfs_1' id='3e511cc8-b7a0-4927-a632-2e81b1440b09' and was created at Mar  5 15:54 (I see this volum: 

On nfs_1 storage domain:
[root@caracal05 ~]# ls -lr /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/*/*/*/* | grep 7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 1 vdsm kvm        257 Mar  5 15:54 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/3e511cc8-b7a0-4927-a632-2e81b1440b09/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 1 vdsm kvm    1048576 Mar  5 15:54 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/3e511cc8-b7a0-4927-a632-2e81b1440b09/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 1 vdsm kvm    2490368 Mar  5 15:54 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/3e511cc8-b7a0-4927-a632-2e81b1440b09/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7

Same volume created at around that time (Mar  5 15:54 , 15:57, 16:11)on other storage domains:
[root@caracal05 ~]# ls -lr /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/*/*/*/* | grep 7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 3 vdsm kvm        257 Mar  5 16:11 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/edc9fb91-079a-4102-a4b0-51deae7011ee/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 3 vdsm kvm    1048576 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/edc9fb91-079a-4102-a4b0-51deae7011ee/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 3 vdsm kvm 2656108544 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/edc9fb91-079a-4102-a4b0-51deae7011ee/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 3 vdsm kvm        257 Mar  5 16:11 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 3 vdsm kvm    1048576 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 3 vdsm kvm 2656108544 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 3 vdsm kvm        257 Mar  5 16:11 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/7092a967-2ec3-4b1e-8a12-a1816496701f/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 3 vdsm kvm    1048576 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/7092a967-2ec3-4b1e-8a12-a1816496701f/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 3 vdsm kvm 2656108544 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/mastersd/images/7092a967-2ec3-4b1e-8a12-a1816496701f/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 3 vdsm kvm        257 Mar  5 16:11 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/edc9fb91-079a-4102-a4b0-51deae7011ee/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 3 vdsm kvm    1048576 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/edc9fb91-079a-4102-a4b0-51deae7011ee/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 3 vdsm kvm 2656108544 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/edc9fb91-079a-4102-a4b0-51deae7011ee/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 3 vdsm kvm        257 Mar  5 16:11 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 3 vdsm kvm    1048576 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 3 vdsm kvm 2656108544 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 3 vdsm kvm        257 Mar  5 16:11 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/7092a967-2ec3-4b1e-8a12-a1816496701f/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 3 vdsm kvm    1048576 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/7092a967-2ec3-4b1e-8a12-a1816496701f/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 3 vdsm kvm 2656108544 Mar  5 15:57 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/d8d3a003-3b7b-453a-8e45-8b60d6b17338/images/7092a967-2ec3-4b1e-8a12-a1816496701f/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 1 vdsm kvm        257 Mar  5 21:09 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/cb6ee6a0-4c96-4f5e-b79a-7f35e80058aa/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 1 vdsm kvm    1048576 Mar  5 15:59 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/cb6ee6a0-4c96-4f5e-b79a-7f35e80058aa/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 1 vdsm kvm 2656108544 Mar  5 15:59 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/cb6ee6a0-4c96-4f5e-b79a-7f35e80058aa/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 1 vdsm kvm        255 Mar  5 16:01 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/c08f1eb5-75c2-4384-a957-07cc378077d0/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 1 vdsm kvm    1048576 Mar  5 16:01 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/c08f1eb5-75c2-4384-a957-07cc378077d0/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 1 vdsm kvm 2656108544 Mar  5 16:01 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/c08f1eb5-75c2-4384-a957-07cc378077d0/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 6 vdsm kvm        366 Mar  5 16:10 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 6 vdsm kvm    1048576 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 6 vdsm kvm 2656108544 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 6 vdsm kvm        366 Mar  5 16:10 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/e0a5b289-88bb-450f-b52b-e63799afa630/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 6 vdsm kvm    1048576 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/e0a5b289-88bb-450f-b52b-e63799afa630/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 6 vdsm kvm 2656108544 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/e0a5b289-88bb-450f-b52b-e63799afa630/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 6 vdsm kvm        366 Mar  5 16:10 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/8bf5b570-9e8f-458a-8903-baf81a199344/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 6 vdsm kvm    1048576 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/8bf5b570-9e8f-458a-8903-baf81a199344/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 6 vdsm kvm 2656108544 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/8bf5b570-9e8f-458a-8903-baf81a199344/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 6 vdsm kvm        366 Mar  5 16:10 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/895d67bf-5a32-4a3f-b162-e3d59f196ba4/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 6 vdsm kvm    1048576 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/895d67bf-5a32-4a3f-b162-e3d59f196ba4/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 6 vdsm kvm 2656108544 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/895d67bf-5a32-4a3f-b162-e3d59f196ba4/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 6 vdsm kvm        366 Mar  5 16:10 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/72309560-f047-4c96-b070-b41c8a0415d8/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 6 vdsm kvm    1048576 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/72309560-f047-4c96-b070-b41c8a0415d8/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 6 vdsm kvm 2656108544 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/72309560-f047-4c96-b070-b41c8a0415d8/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 6 vdsm kvm        366 Mar  5 16:10 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/456bcd7e-19d1-48cd-ba1a-97093ddf8063/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 6 vdsm kvm    1048576 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/456bcd7e-19d1-48cd-ba1a-97093ddf8063/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 6 vdsm kvm 2656108544 Mar  5 15:48 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/84fa6082-4fb5-45eb-afa7-6c114fe3fb81/images/456bcd7e-19d1-48cd-ba1a-97093ddf8063/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7
-rw-r--r--. 1 vdsm kvm        255 Mar  5 15:55 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/7571dd20-ecfd-48a7-a843-a730e1c8d015/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.meta
-rw-rw----. 1 vdsm kvm    1048576 Mar  5 15:55 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/7571dd20-ecfd-48a7-a843-a730e1c8d015/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7.lease
-rw-rw----. 1 vdsm kvm 2656108544 Mar  5 15:55 /rhev/data-center/51ca1c95-06e1-4d09-8cb0-6226a65f3a59/7571dd20-ecfd-48a7-a843-a730e1c8d015/images/e205b36c-bd18-45e1-bc6b-097db4be64bb/7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7

***From journalctl log I can see at the same time ansible job to copy this temlate disk to 'nfs_1' and 'nfs_2' ran :
Mar 05 15:51:14 jenkins-vm-09.lab.eng.tlv2.redhat.com python[77485]: ansible-ovirt_disk Invoked with storage_domains=['nfs_1'] auth={'ca_file': None, 'url': 'https://jenkins-vm-09.lab.eng.tlv2.redhat.com/ovirt-
engine/api', 'insecure': True, 'kerberos': False, 'compress': True, 'headers': None, 'token': 'vI57Se-BNP6Uu4N4PksS1VFROamlOjy1pBBU8G8bbHs5HZDtc0XpdsFjfrWCAlW1N6MsKfj2F5b3Eqy1C3RXSw', 'timeout': 0} fetch_nested
=True timeout=600 id=e205b36c-bd18-45e1-bc6b-097db4be64bb wait=True poll_interval=3 nested_attributes=[] state=present format=cow content_type=data force=False name=None description=None vm_name=None vm_id=None
 size=None interface=None storage_domain=None profile=None quota_id=None sparse=None bootable=None shareable=None logical_unit=None download_image_path=None upload_image_path=None sparsify=None openstack_volume
_type=None image_provider=None host=None wipe_after_delete=None activate=None

Mar 05 15:54:44 jenkins-vm-09.lab.eng.tlv2.redhat.com python[77763]: ansible-ovirt_disk Invoked with storage_domains=['nfs_2'] auth={'ca_file': None, 'url': 'https://jenkins-vm-09.lab.eng.tlv2.redhat.com/ovirt-
engine/api', 'insecure': True, 'kerberos': False, 'compress': True, 'headers': None, 'token': 'vI57Se-BNP6Uu4N4PksS1VFROamlOjy1pBBU8G8bbHs5HZDtc0XpdsFjfrWCAlW1N6MsKfj2F5b3Eqy1C3RXSw', 'timeout': 0} fetch_nested
=True timeout=600 id=e205b36c-bd18-45e1-bc6b-097db4be64bb wait=True poll_interval=3 nested_attributes=[] state=present format=cow content_type=data force=False name=None description=None vm_name=None vm_id=None
 size=None interface=None storage_domain=None profile=None quota_id=None sparse=None bootable=None shareable=None logical_unit=None download_image_path=None upload_image_path=None sparsify=None openstack_volume
_type=None image_provider=None host=None wipe_after_delete=None activate=None

*** Earlies time I see this volume is in engine.log-20200306 log while it's used to create a  new VM:
sourceImageGroupId='e205b36c-bd18-45e1-bc6b-097db4be64bb'
imageId='7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7'

2020-03-05 16:26:52,578+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-12) [vms_create_704e7151-485d-4adc] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='51ca1c95-06e1-4d09-8cb0-6226a65f3a59', ignoreFailoverLimit='false', storageDomainId='84fa6082-4fb5-45eb-afa7-6c114fe3fb81', imageGroupId='0d22a6f2-1819-4ef8-98b5-d869f87eddb7', imageSizeInBytes='10737418240', volumeFormat='COW', newImageId='39ea26b1-6b74-4b8f-b7cc-0e8e57e15dce', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='7d4dd2f1-3d19-4f8e-91a8-4747dbedb0a7', sourceImageGroupId='e205b36c-bd18-45e1-bc6b-097db4be64bb'}), log id: 5d07a5ca



Attaching oldest engine log and journalctl log of the engine

Comment 11 Avihai 2020-03-17 14:26:31 UTC

Created attachment 1670813 [details]
older engine log and journalctl log with latest reproduction logs

Comment 12 Nir Soffer 2020-03-17 15:14:34 UTC

Avihay, can you reproduce this with bare metal hosts?

I suspect the issues related to sanlock are caused by overloaded hosts
and using multiple level of nested virtualization.

Comment 14 Avihai 2020-03-23 08:22:45 UTC

Seen again with LVM filters configured on all hosts with same scenario.
Logs attached.

ovirt-engine-4.4.0-0.26.master.el8ev.noarch
vdsm-4.40.7-1.el8ev.x86_64

LVM filters are configured on all hosts:
[root@lynx24 vdsm]# vdsm-tool config-lvm-filter
Analyzing host...
LVM filter is already configured for Vdsm

Events:
Mar 21, 2020, 9:42:05 PM User admin@internal-authz is copying disk latest-rhel-guest-image-7.7-infra to domain nfs_2. 
Mar 21, 2020, 9:42:10 PM VDSM host_mixed_1 command HSMGetAllTasksStatusesVDS failed: value=Volume already exists: ('d1fee325-96ff-40fb-93ec-49245f3c1791',) abortedcode=212

Engine:
2020-03-21 21:42:10,319+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-53) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command HSMGetAllTasksStatusesVDS failed: value=Volume already exists: ('d1fee325-96ff-40fb-93ec-49245f3c1791',) abortedcode=212
2020-03-21 21:42:10,319+02 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-53) [] SPMAsyncTask::PollTask: Polling task '0840b2d9-9f0c-4e92-ab10-a89befbcc899' (Parent Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2020-03-21 21:42:10,322+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-53) [] BaseAsyncTask::logEndTaskFailure: Task '0840b2d9-9f0c-4e92-ab10-a89befbcc899' (Parent Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure:
-- Result: 'cleanSuccess'
-- Message: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = value=Volume already exists: ('d1fee325-96ff-40fb-93ec-49245f3c1791',) abortedcode=212',
-- Exception: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = value=Volume already exists: ('d1fee325-96ff-40fb-93ec-49245f3c1791',) abortedcode=212'
2020-03-21 21:42:10,322+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-53) [] CommandAsyncTask::endActionIfNecessary: All tasks of command 'da170221-1d73-418d-863b-f0b7a8db39c7' has ended -> executing 'endAction'
2020-03-21 21:42:10,322+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-53) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'da170221-1d73-418d-863b-f0b7a8db39c7'): calling endAction '.
2020-03-21 21:42:10,322+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-13205) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'CreateVolumeContainer',
2020-03-21 21:42:10,327+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (EE-ManagedThreadFactory-engine-Thread-13205) [13387b84-5e45-4c13-ba7f-6e9f231e4f7c] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand' with failure.


VDSM log:
2020-03-21 21:42:06,735+0200 ERROR (tasks/4) [storage.Volume] Failed to create volume /rhev/data-center/mnt/mantis-nfs-lif2.lab.eng.tlv2.redhat.com:_nas01_ge__6__nfs__3/16483589-b481-49ed-8f06-596df6330afb/imag
es/a5d54a36-40da-46c2-ac35-71c714e0a633/d1fee325-96ff-40fb-93ec-49245f3c1791: Volume already exists: ('d1fee325-96ff-40fb-93ec-49245f3c1791',) (volume:1166)
2020-03-21 21:42:06,735+0200 ERROR (tasks/4) [storage.Volume] Unexpected error (volume:1202)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 542, in _truncate_volume
    creatExcl=True)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/outOfProcess.py", line 347, in truncateFile
    ioproc.truncate(path, size, mode if mode is not None else 0, creatExcl)
  File "/usr/lib/python3.6/site-packages/ioprocess/__init__.py", line 576, in truncate
    self.timeout)
  File "/usr/lib/python3.6/site-packages/ioprocess/__init__.py", line 448, in _sendCommand
    raise OSError(errcode, errstr)
FileExistsError: [Errno 17] File exists

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/volume.py", line 1163, in create
    initial_size=initial_size)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 457, in _create
    imgUUID, srcImgUUID, srcVolUUID)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 513, in _create_cow_volume
    cls._truncate_volume(vol_path, 0, vol_id, dom)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/fileVolume.py", line 545, in _truncate_volume
    raise se.VolumeAlreadyExists(vol_id)
vdsm.storage.exception.VolumeAlreadyExists: Volume already exists: ('d1fee325-96ff-40fb-93ec-49245f3c1791',)

Comment 15 RHEL Program Management 2020-03-23 09:43:39 UTC

This bug report has Keywords: Regression or TestBlocker.
Since no regressions or test blockers are allowed between releases, it is also being identified as a blocker for this release. Please resolve ASAP.

Comment 16 Lukas Svaty 2020-03-24 13:03:34 UTC

Targeting to 4.4.0 due to regression and blocker? flags

Comment 17 Avihai 2020-04-01 09:43:57 UTC

The issue does not reoccur on many ENV's in rhv-4.4.0-27.
Closing this bug.