Created attachment 1520672 [details] engine and vdsm logs Description of problem: Adding 2 of the 4 created disks(RAW/QCOW/virtio/virtioscsi matrix) which are RAW/PREALLOCATED disks failed with VolumeCreationError: Error creating a new volume: (u'Volume creation cbcf3c7d-e004-4602-acda-715990775f1b failed: Failed reload Weird that the 4 disks that was created in about the same time only the 2 disks which happen to be RAW/PREALLOCATED failed . Disk1: 2019-01-11 11:50:57,270+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-55) [disks_create_2f19dd79-5447-4d92] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='7dfc9f14-1522-11e9-9c2d-001a4a168bfc', ignoreFailoverLimit='false', storageDomainId='37a4fb44-f0e4-4446-ac8a-cf14d10e74bb', imageGroupId='8ae5eaac-e16b-4d88-9050-0517ae8a5e53', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='e9f4e06f-36fb-4fb5-a5ed-5cc830436933', imageType='Preallocated', newImageDescription='{"DiskAlias":"disk_virtioraw_1111505693","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 5af0a223 Disk2: 2019-01-11 11:50:57,825+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-55) [disks_create_1d29351e-4131-437a] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='7dfc9f14-1522-11e9-9c2d-001a4a168bfc', ignoreFailoverLimit='false', storageDomainId='37a4fb44-f0e4-4446-ac8a-cf14d10e74bb', imageGroupId='0d5755d4-9f34-4b3e-ba8a-71bace0417b5', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='cbcf3c7d-e004-4602-acda-715990775f1b', imageType='Preallocated', newImageDescription='{"DiskAlias":"disk_virtio_scsiraw_1111505693","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 52b23d8e 2019-01-11 11:51:11,512+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [disks_create_2f19dd79-5447-4d92] Command 'AddDisk' id: '6e235cfd-9600-4f61-b27c-99d1c519e275' child commands '[995aedf1-4aae-4873-bc16-f130b23e7d61]' executions were completed, status 'FAILED' 2019-01-11 11:51:12,518+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [disks_create_1d29351e-4131-437a] Command 'AddDisk' id: '76de3635-55fc-44c7-b1c7-4027dbe7c3e3' child commands '[f5dc3352-d570-4a12-b9ce-005fb1e077e5]' executions were completed, status 'FAILED' 2019-01-11 11:51:12,524+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [disks_create_e14f9d29-da97-4cfa] Command 'AddDisk' id: '0ab9b740-783f-4f3a-b88a-43293ab3cf54' child commands '[01a49e89-0c41-4db1-be23-fbee67457b3a]' executions were completed, status 'SUCCEEDED' 2019-01-11 11:51:12,528+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [disks_create_01838690-5cbb-476d] Command 'AddDisk' id: '8d6163cc-f11e-411c-a758-9766951f0434' child commands '[7e655bb1-5b71-4f61-80fc-cd9dbcf0febd]' executions were completed, status 'SUCCEEDED' VDSM: 2019-01-11 11:50:59,124+0200 ERROR (tasks/7) [storage.Volume] Unexpected error (volume:1249) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1218, in create apparentSize = int(dom.getVSize(imgUUID, volUUID) / File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 717, in getVSize return self._manifest.getVSize(imgUUID, volUUID) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 453, in getVSize size = lvm.getLV(self.sdUUID, volUUID).size File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 82, in __getattr__ raise AttributeError("Failed reload: %s" % self.name) AttributeError: Failed reload: e9f4e06f-36fb-4fb5-a5ed-5cc830436933 2019-01-11 11:50:59,125+0200 DEBUG (tasks/7) [storage.ResourceManager] Trying to release resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.8ae5eaac-e16b-4d88-9050-0517ae8a5e53' (resourceManager:567) 2019-01-11 11:50:59,125+0200 DEBUG (tasks/7) [storage.ResourceManager] Released resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.8ae5eaac-e16b-4d88-9050-0517ae8a5e53' (0 active users) (resourceManager:585) 2019-01-11 11:50:59,125+0200 DEBUG (tasks/7) [storage.ResourceManager] Resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.8ae5eaac-e16b-4d88-9050-0517ae8a5e53' is free, finding out if anyone is waiting for it . (resourceManager:591) 2019-01-11 11:50:59,125+0200 DEBUG (tasks/7) [storage.ResourceManager] No one is waiting for resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.8ae5eaac-e16b-4d88-9050-0517ae8a5e53', Clearing records. (resour ceManager:599) 2019-01-11 11:50:59,127+0200 ERROR (tasks/7) [storage.TaskManager.Task] (Task='e9eb6318-ea75-41a4-a1b5-ababdf3f3453') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 336, in run return self.cmd(*self.argslist, **self.argsdict) File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper return method(self, *args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1943, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 820, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1251, in create (volUUID, e)) VolumeCreationError: Error creating a new volume: (u'Volume creation e9f4e06f-36fb-4fb5-a5ed-5cc830436933 failed: Failed reload: e9f4e06f-36fb-4fb5-a5ed-5cc830436933',) 2019-01-11 11:50:59,528+0200 ERROR (tasks/7) [storage.StorageDomain] create image rollback: Cannot remove dirty image (image_dir=/rhev/data-center/mnt/blockSD/37a4fb44-f0e4-4446-ac8a-cf14d10e74bb/images/8ae5eaac-e16b-4d88-9050-0517ae8a5e53) (sd:1296) 2019-01-11 11:51:00,267+0200 ERROR (tasks/1) [storage.Volume] Unexpected error (volume:1249) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1218, in create apparentSize = int(dom.getVSize(imgUUID, volUUID) / File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 717, in getVSize return self._manifest.getVSize(imgUUID, volUUID) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 453, in getVSize size = lvm.getLV(self.sdUUID, volUUID).size File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 82, in __getattr__ raise AttributeError("Failed reload: %s" % self.name) AttributeError: Failed reload: cbcf3c7d-e004-4602-acda-715990775f1b 2019-01-11 11:51:00,267+0200 DEBUG (tasks/1) [storage.ResourceManager] Trying to release resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.0d5755d4-9f34-4b3e-ba8a-71bace0417b5' (resourceManager:567) 2019-01-11 11:51:00,267+0200 DEBUG (tasks/1) [storage.ResourceManager] Released resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.0d5755d4-9f34-4b3e-ba8a-71bace0417b5' (0 active users) (resourceManager:585) 2019-01-11 11:51:00,267+0200 DEBUG (tasks/1) [storage.ResourceManager] Resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.0d5755d4-9f34-4b3e-ba8a-71bace0417b5' is free, finding out if anyone is waiting for it. (resourceManager:591) 2019-01-11 11:51:00,267+0200 DEBUG (tasks/1) [storage.ResourceManager] No one is waiting for resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.0d5755d4-9f34-4b3e-ba8a-71bace0417b5', Clearing records. (resourceManager:599) 2019-01-11 11:51:00,268+0200 ERROR (tasks/1) [storage.TaskManager.Task] (Task='13860a70-e672-4204-a146-7bfc4fa92fde') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 336, in run return self.cmd(*self.argslist, **self.argsdict) File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper return method(self, *args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1943, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 820, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1251, in create (volUUID, e)) VolumeCreationError: Error creating a new volume: (u'Volume creation cbcf3c7d-e004-4602-acda-715990775f1b failed: Failed reload: cbcf3c7d-e004-4602-acda-715990775f1b',) Engine log: 2019-01-11 11:50:57,561+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-44) [disks_create_01838690-5cbb-476d] START, CreateImageVDSCommand( CreateImageVDSCommandParameter s:{storagePoolId='7dfc9f14-1522-11e9-9c2d-001a4a168bfc', ignoreFailoverLimit='false', storageDomainId='37a4fb44-f0e4-4446-ac8a-cf14d10e74bb', imageGroupId='2cf7886b-eaa9-40c0-9295-1e46dfe4276d', imageSizeInBytes ='1073741824', volumeFormat='COW', newImageId='95ec2fb1-df47-4479-8b47-8fa7f6dce578', imageType='Sparse', newImageDescription='{"DiskAlias":"disk_virtio_scsicow_1111505693","DiskDescription":""}', imageInitialSi zeInBytes='0'}), log id: b06e9d7 2019-01-11 11:50:57,682+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-44) [disks_create_01838690-5cbb-476d] EVENT_ID: USER_ADD_DISK(2,020), Add-Disk operation of ' disk_virtio_scsicow_1111505693' was initiated by admin@internal-authz. 2019-01-11 11:51:04,508+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [disks_create_01838690-5cbb-476d] Command 'AddDisk' (id: '8d6163cc-f11e-411c-a758-9766951f0434') waiting on child command id: '7e655bb1-5b71-4f61-80fc-cd9dbcf0febd' type:'AddImageFromScratch' to complete 2019-01-11 11:51:07,157+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2019-01-11 11:51:07,162+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command HSMGetAllTasksStatusesVDS failed: Error creating a new volume: (u'Volume creation cbcf3c7d-e004-4602-acda-715990775f1b failed: Failed reload: cbcf3c7d-e004-4602-acda-715990775f1b',) 2019-01-11 11:51:07,162+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2019-01-11 11:51:07,162+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] SPMAsyncTask::PollTask: Polling task 'e9eb6318-ea75-41a4-a1b5-ababdf3f3453' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2019-01-11 11:51:07,166+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] BaseAsyncTask::logEndTaskFailure: Task 'e9eb6318-ea75-41a4-a1b5-ababdf3f3453' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Error creating a new volume: (u'Volume creation e9f4e06f-36fb-4fb5-a5ed-5cc830436933 failed: Failed reload: e9f4e06f-36fb-4fb5-a5ed-5cc830436933',), code = 205', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Error creating a new volume: (u'Volume creation e9f4e06f-36fb-4fb5-a5ed-5cc830436933 failed: Failed reload: e9f4e06f-36fb-4fb5-a5ed-5cc830436933',), code = 205' Version-Release number of selected component (if applicable): Engine host: Host Name hosted-engine-06.lab.eng.tlv2.redhat.com ovirt-engine ovirt-engine-4.2.8.2-0.1.el7ev.noarch ovirt-imageio-proxy ovirt-imageio-proxy-1.4.5-0.el7ev.noarch redhat_release Red Hat Enterprise Linux Server 7.6 (Maipo) build_info_product rhv build_info_version 4.2 build_info_name rhv-4.2.8-3 uptime 4031 kernel_release 3.10.0-957.5.1.el7.x86_64 nics_number 2 VDSM host: vdsm vdsm-4.20.46-1.el7ev.x86_64 vdsm-cli null libvirt libvirt-4.5.0-10.el7_6.3.x86_64 qemu-img-rhev qemu-img-rhev-2.12.0-18.el7_6.1.x86_64 glusterfs glusterfs-3.12.2-32.el7.x86_64 vdsm-python vdsm-python-4.20.46-1.el7ev.noarch sanlock sanlock-3.6.0-1.el7.x86_64 ovirt-imageio-daemon ovirt-imageio-daemon-1.4.5-0.el7ev.noarch redhat_release Red Hat Enterprise Linux Server 7.6 (Maipo) uuid 4c4c4544-0047-3210-804c-c4c04f533632 build_info_product rhv build_info_version 4.2 build_info_name rhv-4.2.8-3 uptime 2829 kernel_release 3.10.0-957.5.1.el7.x86_64 nics_number 10 How reproducible: Happened once so far. Steps to Reproduce: 09:48:01 art/tests/rhevmtests/storage/storage_remove_snapshots/test_live_merge.py 2019-01-11 11:48:01,757 INFO ================================================================================ 09:48:01 2019-01-11 11:48:01,757 INFO Test Setup 1: Creating VM vm_TestCase6038_1111480175 09:48:02 2019-01-11 11:48:01,981 INFO Test Setup 2: [class] Description: clone vm from a pre-defined template golden_mixed_virtio_template with {'vol_sparse': True, 'name': 'vm_TestCase6038_1111480175', 'clone': False, 'cluster': 'golden_env_mixed_1', 'storagedomain': 'fcp_0', 'display_type': 'spice', 'timeout': 900, 'virtio_scsi': True, 'vol_format': 'cow', 'os_type': 'RHEL6x64', 'type': 'desktop', 'wait': True} 09:48:14 2019-01-11 11:48:14,225 INFO Test Setup 3: Starting VM vm_TestCase6038_1111480175 09:48:14 2019-01-11 11:48:14,227 INFO Test Setup 4: [class] Start VM vm_TestCase6038_1111480175 with {'wait_for_ip': True, 'pause': False, 'use_cloud_init': False, 'timeout': 600, 'wait_for_status': 'up'} 09:50:56 2019-01-11 11:50:56,773 INFO Test Setup 5: Creating disks with filesystem and attach to VM vm_TestCase6038_1111480175 09:51:29 2019-01-11 11:51:29,242 INFO 293: storage/rhevmtests.storage.storage_remove_snapshots.test_live_merge.TestCase6038.test_basic_snapshot_deletion[fcp] 09:51:29 2019-01-11 11:51:29,242 INFO STORAGE: FCP 09:51:29 2019-01-11 11:51:29,242 ERROR NOTE: Test failed on setup phase! 09:51:29 2019-01-11 11:51:29,243 ERROR Result: FAILED Actual results: 2/4 disks which are RAW/Preallocated failed. Expected results: All disks creation should succeed. Additional info:
2nd reproduction on a different test TestCase6052 with a similar scenario, again on FCP . logs added . Here 1 out of 4 disks failed, again a RAW/PREALLOCATED DISK, detais :2019-01-11 12:36:41,669+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-62) [disks_create_3058c927-83b4-47db] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='7dfc9f14-1522-11e9-9c2d-001a4a168bfc', ignoreFailoverLimit='false', storageDomainId='37a4fb44-f0e4-4446-ac8a-cf14d10e74bb', imageGroupId='6f9e5226-8bef-4c82-948a-a2b21ed7e692', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='c73324a8-6e9d-4d90-a417-877166afb809', imageType='Preallocated', newImageDescription='{"DiskAlias":"disk_virtioraw_1112364136","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 72b1c0c5 VDSM: 2019-01-11 12:36:43,335+0200 ERROR (tasks/6) [storage.Volume] Unexpected error (volume:1249) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1218, in create apparentSize = int(dom.getVSize(imgUUID, volUUID) / File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 717, in getVSize return self._manifest.getVSize(imgUUID, volUUID) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 453, in getVSize size = lvm.getLV(self.sdUUID, volUUID).size File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 82, in __getattr__ raise AttributeError("Failed reload: %s" % self.name) AttributeError: Failed reload: c73324a8-6e9d-4d90-a417-877166afb809 2019-01-11 12:36:43,336+0200 DEBUG (tasks/6) [storage.ResourceManager] Trying to release resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.6f9e5226-8bef-4c82-948a-a2b21ed7e692' (resourceManager:567) 2019-01-11 12:36:43,336+0200 DEBUG (tasks/6) [storage.ResourceManager] Released resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.6f9e5226-8bef-4c82-948a-a2b21ed7e692' (0 active users) (resourceManager:585) 2019-01-11 12:36:43,336+0200 DEBUG (tasks/6) [storage.ResourceManager] Resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.6f9e5226-8bef-4c82-948a-a2b21ed7e692' is free, finding out if anyone is waiting for it. (resourceManager:591) 2019-01-11 12:36:43,336+0200 DEBUG (tasks/6) [storage.ResourceManager] No one is waiting for resource '01_img_37a4fb44-f0e4-4446-ac8a-cf14d10e74bb.6f9e5226-8bef-4c82-948a-a2b21ed7e692', Clearing records. (resourceManager:599) 2019-01-11 12:36:43,336+0200 ERROR (tasks/6) [storage.TaskManager.Task] (Task='66bc5775-40a6-463c-bdb9-e16c35c446b8') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 336, in run return self.cmd(*self.argslist, **self.argsdict) File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper return method(self, *args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1943, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 820, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1251, in create (volUUID, e)) VolumeCreationError: Error creating a new volume: (u'Volume creation c73324a8-6e9d-4d90-a417-877166afb809 failed: Failed reload: c73324a8-6e9d-4d90-a417-877166afb809',) 2019-01-11 12:36:43,649+0200 ERROR (tasks/6) [storage.StorageDomain] create image rollback: Cannot remove dirty image (image_dir=/rhev/data-center/mnt/blockSD/37a4fb44-f0e4-4446-ac8a-cf14d10e74bb/images/6f9e5226-8bef-4c82-948a-a2b21ed7e692) (sd:1296) Engine: 2019-01-11 12:36:41,669+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-62) [disks_create_3058c927-83b4-47db] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='7dfc9f14-1522-11e9-9c2d-001a4a168bfc', ignoreFailoverLimit='false', storageDomainId='37a4fb44-f0e4-4446-ac8a-cf14d10e74bb', imageGroupId='6f9e5226-8bef-4c82-948a-a2b21ed7e692', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='c73324a8-6e9d-4d90-a417-877166afb809', imageType='Preallocated', newImageDescription='{"DiskAlias":"disk_virtioraw_1112364136","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 72b1c0c5 2019-01-11 12:36:48,858+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [disks_create_15fa0cf5-79fb-45b3] Command 'AddDisk' id: '3a5e9759-fae6-4158-aa52-185cf738faae' child commands '[1640d3d2-b97d-47a4-ab38-78ef3597763e]' executions were completed, status '' 2019-01-11 12:36:48,863+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [disks_create_85bdbf0b-1bd0-4245] Command 'AddDisk' id: 'e9a75810-1c72-492a-9864-7b847377cf57' child commands '[dcc2096b-bfcc-47f4-be43-e8036112bf6d]' executions were completed, status 'SUCCEEDED' 2019-01-11 12:36:48,867+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [disks_create_7c4051cc-75d3-433a] Command 'AddDisk' id: '6a9f2baf-93e0-4f53-a873-bdb66d4205dd' child commands '[ec2d0f36-4115-43f9-9464-c789471c55df]' executions were completed, status 'SUCCEEDED' 2019-01-11 12:36:58,537+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-62) [disks_create_3058c927-83b4-47db] Command 'AddDisk' id: 'da86efd8-13f5-4cd4-9f1a-33a0291913aa' child commands '[ec40f50e-ad2e-4e85-9977-5ba165150a6b]' executions were completed, status 'FAILED' 2019-01-11 12:36:48,027+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2019-01-11 12:36:48,031+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command HSMGetAllTasksStatusesVDS failed: Error creating a new volume: (u'Volume creation c73324a8-6e9d-4d90-a417-877166afb809 failed: Failed reload: c73324a8-6e9d-4d90-a417-877166afb809',) 2019-01-11 12:36:48,038+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [] BaseAsyncTask::logEndTaskFailure: Task '66bc5775-40a6-463c-bdb9-e16c35c446b8' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Error creating a new volume: (u'Volume creation c73324a8-6e9d-4d90-a417-877166afb809 failed: Failed reload: c73324a8-6e9d-4d90-a417-877166afb809',), code = 205', 2019-01-11 12:36:58,537+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-62) [disks_create_3058c927-83b4-47db] Command 'AddDisk' id: 'da86efd8-13f5-4cd4-9f1a-33a0291913aa' child commands '[ec40f50e-ad2e-4e85-9977-5ba165150a6b]' executions were completed, status 'FAILED' 2019-01-11 12:36:59,549+02 ERROR [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-24) [disks_create_3058c927-83b4-47db] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' with failure. 2019-01-11 12:36:59,554+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-24) [disks_create_3058c927-83b4-47db] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' with failure. 2019-01-11 12:36:59,632+02 WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-24) [] VM is null - no unlocking 2019-01-11 12:36:59,642+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-24) [] EVENT_ID: USER_ADD_DISK_FINISHED_FAILURE(2,022), Add-Disk operation failed to complete. Scenario: 10:35:33 2019-01-11 12:35:33,251 INFO Test Setup 1: Creating VM vm_TestCase6052_1112353325 10:35:33 2019-01-11 12:35:33,454 INFO Test Setup 2: [class] Description: clone vm from a pre-defined template golden_mixed_virtio_template with {'vol_sparse': True, 'name': 'vm_TestCase6052_1112353325', 'clone': False, 'cluster': 'golden_env_mixed_1', 'storagedomain': 'fcp_0', 'display_type': 'spice', 'timeout': 900, 'virtio_scsi': True, 'vol_format': 'cow', 'os_type': 'RHEL6x64', 'type': 'desktop', 'wait': True} 10:35:45 2019-01-11 12:35:45,502 INFO Test Setup 3: Starting VM vm_TestCase6052_1112353325 10:35:45 2019-01-11 12:35:45,505 INFO Test Setup 4: [class] Start VM vm_TestCase6052_1112353325 with {'wait_for_ip': True, 'pause': False, 'use_cloud_init': False, 'timeout': 600, 'wait_for_status': 'up'} 10:36:41 2019-01-11 12:36:41,212 INFO Test Setup 5: Creating disks with filesystem and attach to VM vm_TestCase6052_1112353325 10:37:14 2019-01-11 12:37:14,756 ERROR NOTE: Test failed on setup phase!
Saw the same issue on Tier3 TestCase14955(change_disk_suspended_vm[iscsi]) when VM fails to be suspended as it fails to create 2 RAW/PREALLOCATED volumes. Adding also logs for this case. VDSM log: 2019-01-10 20:16:02,387+0200 ERROR (tasks/1) [storage.Volume] Unexpected error (volume:1249) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1218, in create apparentSize = int(dom.getVSize(imgUUID, volUUID) / File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 717, in getVSize return self._manifest.getVSize(imgUUID, volUUID) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 453, in getVSize size = lvm.getLV(self.sdUUID, volUUID).size File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 82, in __getattr__ raise AttributeError("Failed reload: %s" % self.name) AttributeError: Failed reload: d14372d1-7d62-406c-92df-d42f1c7aade5 2019-01-10 20:16:02,388+0200 DEBUG (tasks/1) [storage.ResourceManager] Trying to release resource '01_img_17a5db4e-3682-4d93-b0da-aba0bc9ee65e.d6606cc5-f2d2-4483-8a87-094625ffc144' (resourceManager:567) 2019-01-10 20:16:02,388+0200 DEBUG (tasks/1) [storage.ResourceManager] Released resource '01_img_17a5db4e-3682-4d93-b0da-aba0bc9ee65e.d6606cc5-f2d2-4483-8a87-094625ffc144' (0 active users) (resourceManager:585) 2019-01-10 20:16:02,388+0200 DEBUG (tasks/1) [storage.ResourceManager] Resource '01_img_17a5db4e-3682-4d93-b0da-aba0bc9ee65e.d6606cc5-f2d2-4483-8a87-094625ffc144' is free, finding out if anyone is waiting for it. (resourceManager:591) 2019-01-10 20:16:02,388+0200 DEBUG (tasks/1) [storage.ResourceManager] No one is waiting for resource '01_img_17a5db4e-3682-4d93-b0da-aba0bc9ee65e.d6606cc5-f2d2-4483-8a87-094625ffc144', Clearing records. (resourceManager:599) 2019-01-10 20:16:02,389+0200 ERROR (tasks/1) [storage.TaskManager.Task] (Task='38bf48e2-dd06-474e-baa1-857349818717') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 336, in run return self.cmd(*self.argslist, **self.argsdict) File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper return method(self, *args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1943, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 820, in createVolume initialSize=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1251, in create (volUUID, e)) VolumeCreationError: Error creating a new volume: (u'Volume creation d14372d1-7d62-406c-92df-d42f1c7aade5 failed: Failed reload: d14372d1-7d62-406c-92df-d42f1c7aade5',) 2019-01-10 20:16:02,708+0200 ERROR (tasks/1) [storage.StorageDomain] create image rollback: Cannot remove dirty image (image_dir=/rhev/data-center/mnt/blockSD/17a5db4e-3682-4d93-b0da-aba0bc9ee65e/images/d6606cc5-f2d2-4483-8a87-094625ffc144) (sd:1296) Engine log: 2019-01-10 20:16:00,975+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] EVENT_ID: USER_SUSPEND_VM(501), Suspending VM vm_TestCase14955_1020145601 was initiated by User admin@internal-authz (Host: host_mixed_2). 2019-01-10 20:16:00,976+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] BaseAsyncTask::startPollingTask: Starting to poll task '38bf48e2-dd06-474e-baa1-857349818717'. 2019-01-10 20:16:00,976+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] BaseAsyncTask::startPollingTask: Starting to poll task 'a8d4d73e-7951-42a3-943f-7e8349fd3357'. 2019-01-10 20:16:02,604+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] Polling and updating Async Tasks: 4 tasks, 2 tasks to poll now 2019-01-10 20:16:02,615+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] SPMAsyncTask::PollTask: Polling task '38bf48e2-dd06-474e-baa1-857349818717' (Parent Command 'HibernateVm', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'cleaning'. 2019-01-10 20:16:06,742+02 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-11) [] Operation Failed: [Cannot remove VM. VM is hibernating.] 2019-01-10 20:16:07,727+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmsStatisticsFetcher] (EE-ManagedThreadFactory-engineScheduled-Thread-20) [] Fetched 0 VMs from VDS '358ea39b-15e5-4937-b865-f088de536549' 2019-01-10 20:16:12,633+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-52) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_3 command HSMGetAllTasksStatusesVDS failed: Error creating a new volume: (u'Volume creation d14372d1-7d62-406c-92df-d42f1c7aade5 failed: Failed reload: d14372d1-7d62-406c-92df-d42f1c7aade5',) 2019-01-10 20:16:12,633+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-52) [] SPMAsyncTask::PollTask: Polling task '38bf48e2-dd06-474e-baa1-857349818717' (Parent Command 'HibernateVm', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2019-01-10 20:16:12,636+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-52) [] BaseAsyncTask::logEndTaskFailure: Task '38bf48e2-dd06-474e-baa1-857349818717' (Parent Command 'HibernateVm', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Error creating a new volume: (u'Volume creation d14372d1-7d62-406c-92df-d42f1c7aade5 failed: Failed reload: d14372d1-7d62-406c-92df-d42f1c7aade5',), code = 205', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Error creating a new volume: (u'Volume creation d14372d1-7d62-406c-92df-d42f1c7aade5 failed: Failed reload: d14372d1-7d62-406c-92df-d42f1c7aade5',), code = 205' Creation of volumes, both 'RAW' and 'Preallocated' : 2019-01-10 20:16:00,632+02 INFO [org.ovirt.engine.core.bll.HibernateVmCommand] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] Running command: HibernateVmCommand internal: false. Entities affected : ID: 3572b5f6-5cbe-401e-b3a5-b5d51cfd00ca Type: VMAction group HIBERNATE_VM with role type USER 2019-01-10 20:16:00,668+02 INFO [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] Running command: AddDiskCommand internal: true. Entities affected : ID: 17a5db4e-3682-4d93-b0da-aba0bc9ee65e Type: StorageAction group CREATE_DISK with role type USER 2019-01-10 20:16:00,678+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] Running command: AddImageFromScratchCommand intern al: true. Entities affected : ID: 17a5db4e-3682-4d93-b0da-aba0bc9ee65e Type: Storage 1st volume: 2019-01-10 20:16:00,715+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] START, CreateImageVDSCommand( CreateImageVDSCommandParamet ers:{storagePoolId='e01d687c-14dc-11e9-8283-001a4a168bf8', ignoreFailoverLimit='false', storageDomainId='17a5db4e-3682-4d93-b0da-aba0bc9ee65e', imageGroupId='d6606cc5-f2d2-4483-8a87-094625ffc144', imageSizeInByt es='1384120320', volumeFormat='RAW', newImageId='d14372d1-7d62-406c-92df-d42f1c7aade5', imageType='Preallocated', newImageDescription='{"DiskAlias":"vm_TestCase14955_1020145601_hibernation_memory","DiskDescripti on":"memory dump for VM hibernation"}', imageInitialSizeInBytes='0'}), log id: 59201d4f 2nd volume: 2019-01-10 20:16:00,873+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-11) [vms_syncAction_97fdfd95-0872-4c16] START, CreateImageVDSCommand( CreateImageVDSCommandParamet ers:{storagePoolId='e01d687c-14dc-11e9-8283-001a4a168bf8', ignoreFailoverLimit='false', storageDomainId='17a5db4e-3682-4d93-b0da-aba0bc9ee65e', imageGroupId='615142bb-f3b3-460a-b6ce-1ecf5db68fa1', imageSizeInByt es='10240', volumeFormat='RAW', newImageId='39a8fcec-9031-409a-83f9-bbf23b220415', imageType='Preallocated', newImageDescription='{"DiskAlias":"vm_TestCase14955_1020145601_hibernation_metadata","DiskDescription" :"metadata for VM hibernation"}', imageInitialSizeInBytes='0'}), log id: 7c45a4f3
Created attachment 1520993 [details] Tier3_TestCase14955_VM_suspend_scenario
Avihai, According to comment #2, does it means the header should change as it doesn't occur on [FCP] only?
(In reply to Raz Tamir from comment #4) > Avihai, > > According to comment #2, does it means the header should change as it > doesn't occur on [FCP] only? Indeed, in the 2nd time issue occur storage type was ISCSI, bug header changed.
*** This bug has been marked as a duplicate of bug 1637405 ***