+++ This bug is a downstream clone. The original bug is: +++ +++ bug 1758048 +++ ====================================================================== Created attachment 1622191 [details] engine and vdsm logs Description of problem: Automation TestCase11141. clone VM from template(created from VM) as thin failed. the cloned VM is locked and all of it's disks remain lock forever. disk id = '09d2cca3-662a-47f9-a1dd-6f6ebca12418' VDSM log: 2019-09-30 20:09:30,710+0300 ERROR (tasks/6) [storage.Volume] Requested capacity 1073741824 < parent capacity 3221225472 (volume:1211) 2019-09-30 20:09:30,710+0300 DEBUG (tasks/6) [storage.ResourceManager] Trying to release resource '01_img_90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1.09d2cca3-662a-47f9-a1dd-6f6ebca12418' (resourceManager:568) 2019-09-30 20:09:30,820+0300 DEBUG (tasks/8) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:219) 2019-09-30 20:09:30,823+0300 DEBUG (tasks/8) [storage.LVM] lvs reloaded (lvm:567) 2019-09-30 20:09:30,823+0300 DEBUG (tasks/8) [storage.ResourcesFactories] Image ca08a22a-6e0a-45b9-8db4-9323245bdfbd does not exist in domain 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1 (resourceFactories:125) 2019-09-30 20:09:30,823+0300 DEBUG (tasks/8) [storage.ResourceManager] Resource '01_img_90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1.ca08a22a-6e0a-45b9-8db4-9323245bdfbd' is free. Now locking as 'exclusive' (1 active user) (resourceManager:553) 2019-09-30 20:09:30,823+0300 DEBUG (tasks/8) [storage.ResourceManager.Request] (ResName='01_img_90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1.ca08a22a-6e0a-45b9-8db4-9323245bdfbd', ReqID='e9127f6b-b2b7-4b2c-8ed7-4c01e13def73') Granted request (resourceManager:223) 2019-09-30 20:09:30,826+0300 INFO (tasks/8) [storage.StorageDomain] Create placeholder /rhev/data-center/mnt/blockSD/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/images/ca08a22a-6e0a-45b9-8db4-9323245bdfbd for image's volumes (sd:1392) 2019-09-30 20:09:30,826+0300 DEBUG (tasks/6) [storage.ResourceManager] Released resource '01_img_90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1.09d2cca3-662a-47f9-a1dd-6f6ebca12418' (0 active users) (resourceManager:586) 2019-09-30 20:09:30,831+0300 DEBUG (tasks/6) [storage.ResourceManager] Resource '01_img_90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1.09d2cca3-662a-47f9-a1dd-6f6ebca12418' is free, finding out if anyone is waiting for it. (resourceManager:592) 2019-09-30 20:09:30,831+0300 DEBUG (tasks/6) [storage.ResourceManager] No one is waiting for resource '01_img_90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1.09d2cca3-662a-47f9-a1dd-6f6ebca12418', Clearing records. (resourceManager:600) 2019-09-30 20:09:30,831+0300 ERROR (tasks/6) [storage.TaskManager.Task] (Task='852412ff-dfe8-4d01-8752-2ad2572c839e') 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 1940, in createVolume initial_size=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 930, in createVolume initial_size=initial_size) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1212, in create raise se.InvalidParameterException("capacity", capacity) InvalidParameterException: Invalid parameter: 'q??=1073741824' Engine log: 2019-09-30 20:09:35,598+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-38) [vms_create_5865f184-2b60-4d68] Command 'AddVm' (id: '578a21ee-3f5a-47ba-90b4-e9cd1623bb54') waiting on child command id: '0c86b4ca-454b-4db8-871d-f69b56df40db' type:'CreateSnapshotFromTemplate' to complete 2019-09-30 20:09:35,659+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] Polling and updating Async Tasks: 10 tasks, 5 tasks to poll now 2019-09-30 20:09:35,679+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2019-09-30 20:09:35,685+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command HSMGetAllTasksStatusesVDS failed: Invalid parameter: 'capacity=1073741824' 2019-09-30 20:09:35,685+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] SPMAsyncTask::PollTask: Polling task '852412ff-dfe8-4d01-8752-2ad2572c839e' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2019-09-30 20:09:35,688+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] BaseAsyncTask::logEndTaskFailure: Task '852412ff-dfe8-4d01-8752-2ad2572c839e' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', code = 100', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', code = 100' 2019-09-30 20:09:35,688+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '25ae0108-f4ea-4785-9a91-12dacd69bf3b' has ended -> executing 'endAction' 2019-09-30 20:09:35,689+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '25ae0108-f4ea-4785-9a91-12dacd69bf3b'): calling endAction '. 2019-09-30 20:09:55,194+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM cloned_vm_copy_disk_11141 creation. 2019-09-30 20:09:55,195+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] Failed invoking callback end method 'onFailed' for command '578a21ee-3f5a-47ba-90b4-e9cd1623bb54' with exception 'null', the callback is marked for end method retries 2019-09-30 20:09:57,251+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-16) [6c0ab9c3] START, DeleteImageGroupVDSCommand( DeleteIm ageGroupVDSCommandParameters:{storagePoolId='3d5b32f3-3a06-4263-9b32-a4fa20853922', ignoreFailoverLimit='false', storageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', imageGroupId='8e522c86-e64a-4479-8bff-005 a1a55ae69', postZeros='false', discard='false', forceDelete='false'}), log id: 2eb6201e 2019-09-30 20:09:58,722+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-16) [6c0ab9c3] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803 ), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=8e522c86-e64a-4479-8bff-005a1a55ae69, domain=90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1' 2019-09-30 20:09:58,722+03 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-16) [6c0ab9c3] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='3d5b32f3-3a06-4263-9b32-a4fa20853922', ignoreFailoverLimit='false', storageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', imageGroupId='8e522c86-e64a-4479-8bff-005a1a55ae69', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=8e522c86-e64a-4479-8bff-005a1a55ae69, domain=90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1' After many ERROR's comes this NPE exception: 2019-09-30 20:10:32,514+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM cloned_vm_copy_disk_11141 creation. 2019-09-30 20:10:32,545+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [vms_create_5865f184-2b60-4d68] Failed invoking callback end method 'onFailed' for command '578a21ee-3f5a-47ba-90b4-e9cd1623bb54' with exception 'null', the callback is marked for end method retries but max number of retries have been attempted. The command will be marked as Fa iled. 2019-09-30 20:10:32,546+03 INFO [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [vms_create_5865f184-2b60-4d68] Exception in invoking callback of command AddVm (578a21ee-3f5a-47ba-90b4-e9cd1623bb54): NullPointerException: 2019-09-30 20:10:32,546+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [vms_create_5865f184-2b60-4d68] Error invoking callback method 'onFailed' for 'FAILED' command '578a21ee-3f5a-47ba-90b4-e9cd1623bb54' 2019-09-30 20:10:32,546+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-50) [vms_create_5865f184-2b60-4d68] Exception: javax.ejb.EJBTransactionRolledbackException at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:203) [wildfly-ejb3-7.2.4.GA-redhat-00002.jar:7.2.4.GA-redhat-00002] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:420) [wildfly-ejb3-7.2.4.GA-redhat-00002.jar:7.2.4.GA-redhat-00002] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:148) [wildfly-ejb3-7.2.4.GA-redhat-00002.jar:7.2.4.GA-redhat-00002] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) ....................................................................................................................................................................................................................................................... at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [wildfly-ejb3-7.2.4.GA-redhat-00002.jar:7.2.4.GA-redhat-00002] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185) [wildfly-ejb3-7.2.4.GA-redhat-00002.jar:7.2.4.GA-redhat-00002] ... 63 more Version-Release number of selected component (if applicable): How reproducible: Very hard, occured only once. Retried the same automation TC run for 12 times and the issue did not reproduce. Steps to Reproduce: From automation log + timestamps: 20:06:18 2019-09-30 20:06:18,426 INFO Test Setup 1: Creating new VM vm_test_copy_disk_iscsi_3020061842 from template(capacity 10G) 20:06:18 2019-09-30 20:06:18,429 INFO Test Setup 2: [function] Create new vm with nic nic1, disk and OS with {'diskActive': True, 'wipe_after_delete': 'false', 'slim': False, 'cluster': 'golden_env_mixed_1', 'linked': 'true', 'network': 'ovirtmgmt', 'plugged': 'true', 'start': 'false', 'vmDescription': 'vm_test_copy_disk_iscsi_3020061842', 'type': 'desktop', 'template': 'Blank', 'volume?Format': 'cow', 'display_type': 'spice', 'attempt': 60, 'password': 'qum5net', 'installation': False, 'diskInterface': 'virtio', 'bootable': 'true', 'vmName': 'vm_test_copy_disk_iscsi_3020061842', 'copy_permissions': False, 'interval': 60, 'volumeType': 'true', 'diskType': 'data', 'useAgent': True, 'async': False, 'user': 'root'} 20:06:18 2019-09-30 20:06:18,433 INFO Test Setup 3: [function] Description vm_test_copy_disk_iscsi_3020061842: add new vm (without starting it) with {'name': 'vm_test_copy_disk_iscsi_3020061842', 'copy_permissions': False, 'cluster': 'golden_env_mixed_1', 'display_type': 'spice', 'template': 'Blank', 'async': False, 'type': 'desktop', 'wait': True} 20:06:19 2019-09-30 20:06:19,180 INFO Test Setup 4: [function] Add vNIC name nic1 to VM vm_test_copy_disk_iscsi_3020061842 with {'linked': 'true', 'vnic_profile': 'ovirtmgmt', 'network': 'ovirtmgmt', 'plugged': 'true'} 20:06:19 2019-09-30 20:06:19,901 INFO 024: storage/rhevmtests.storage.storage_copy_disk.test_copy_disk.TestCase11141.test_copy_vm_disks_after_cloned_as_thin[iscsi] 20:06:19 2019-09-30 20:06:19,901 INFO Copy existing disk when vm cloned from snapshot as thin 20:06:19 2019-09-30 20:06:19,902 INFO STORAGE: ISCSI 20:06:20 2019-09-30 20:06:20,078 INFO Test Step 5: Start VM copy_disk_vm_iscsi with {'wait_for_ip': False, 'pause': False, 'use_cloud_init': False, 'timeout': 600, 'wait_for_status': 'powering_up'} 20:07:15 2019-09-30 20:07:15,360 INFO Test Step 6: Stop vm copy_disk_vm_iscsi with {'async': 'false'} 20:07:30 2019-09-30 20:07:30,013 INFO Test Step 7: Creating template from VM copy_disk_vm_iscsi (capacity 10G) 20:07:30 2019-09-30 20:07:30,015 INFO Test Step 8: create new template with {'name': 'template_copy_disk_11141', 'vm': 'copy_disk_vm_iscsi', 'cluster': 'golden_env_mixed_1', 'storagedomain': 'iscsi_2', 'timeout': 1800, 'wait': True} 20:09:27 2019-09-30 20:09:27,410 INFO Test Step 9: Cloning VM from template template_copy_disk_11141 20:09:27 2019-09-30 20:09:27,414 INFO Test Step 10: Description: clone vm from a pre-defined template template_copy_disk_11141 with {'vol_sparse': True, 'name': 'cloned_vm_copy_disk_11141', 'clone': False, 'cluster': 'golden_env_mixed_1', 'storagedomain': 'iscsi_2', 'timeout': 1200, 'virtio_scsi': True, 'vol_format': 'cow', 'wait': True} 20:29:49 2019-09-30 20:29:49,041 ERROR Result: FAILED Actual results: Cloning VM from template fails but also rollback fails so the cloned VM 'cloned_vm_copy_disk_11141' is created but it's locked and all it's disks are in locked state. The VM can not be removed as it's locked. Expected results: Cloning VM from template works. or If Cloning VM from template fails rollback should work and the VM should be removed. Additional info: 1) DB record of the image: engine=# select * from images where image_group_id='09d2cca3-662a-47f9-a1dd-6f6ebca12418'; -[ RECORD 1 ]---------+------------------------------------- image_guid | 76c2db22-d0eb-44cd-891f-2ce18828ef79 creation_date | 2019-09-30 20:09:29.496+03 size | 1073741824 it_guid | cc709bc2-402e-4022-b174-7935ddc30dfb parentid | cc709bc2-402e-4022-b174-7935ddc30dfb imagestatus | 2 lastmodified | 2019-09-30 20:09:29.496+03 vm_snapshot_id | aecaa0e1-3ef5-44c4-98ac-21d32abf8c96 volume_type | 2 volume_format | 4 image_group_id | 09d2cca3-662a-47f9-a1dd-6f6ebca12418 _create_date | 2019-09-30 20:09:29.643271+03 _update_date | active | t volume_classification | 0 qcow_compat | 0 2) Get request on this disk image shows capacity is 3G: https://hosted-engine-04.lab.eng.tlv2.redhat.com/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418 <disk href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418" id="09d2cca3-662a-47f9-a1dd-6f6ebca12418"> <actions> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/reduce" rel="reduce"/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/refreshlun" rel="refreshlun"/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/copy" rel="copy"/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/export" rel="export"/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/move" rel="move"/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/sparsify" rel="sparsify"/> </actions> <name>disk_virtio_scsiraw_3019262787_copy_disk</name> <description/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/permissions" rel="permissions"/> <link href="/ovirt-engine/api/disks/09d2cca3-662a-47f9-a1dd-6f6ebca12418/statistics" rel="statistics"/> <actual_size>3221225472</actual_size> <alias>disk_virtio_scsiraw_3019262787_copy_disk</alias> <backup>none</backup> <content_type>data</content_type> <format>cow</format> <image_id>76c2db22-d0eb-44cd-891f-2ce18828ef79</image_id> <propagate_errors>false</propagate_errors> <provisioned_size>1073741824</provisioned_size> <shareable>false</shareable> <sparse>true</sparse> <status>locked</status> <storage_type>image</storage_type> <total_size>3221225472</total_size> <wipe_after_delete>true</wipe_after_delete> <disk_profile href="/ovirt-engine/api/diskprofiles/5fbe33cb-5815-47fe-bf87-ee0e9f654cbd" id="5fbe33cb-5815-47fe-bf87-ee0e9f654cbd"/> <storage_domains> <storage_domain href="/ovirt-engine/api/storagedomains/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1" id="90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1"/> </storage_domains> </disk> (Originally by Avihai Efrat)
Version-Release number of selected component (if applicable): ovirt-engine-4.3.6.6-0.1.el7.noarch vdsm-4.30.33-1.el7ev.x86_64 libvirt-4.5.0-23.el7_7.1.x86_64 qemu-img-rhev-2.12.0-33.el7.x86_64 (Originally by Avihai Efrat)
Another 2nd hit for this issue in TestCase11339(Copy existing disk when vm is with snapshot) this time CREATE SNAPSHOT FAILED. Raising severity and marking as automation blocker. Adding logs in new attachment. Engine: 2019-09-30 19:51:19,775+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-13) [] BaseAsyncTask::logEndTaskFailure: Task '11ef4b1c-34a4-42cd-bae2-b47a421e1015' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', code = 100', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', code = 100' VDSM: 2019-09-30 19:51:09,111+0300 DEBUG (tasks/4) [storage.TaskManager.Task] (Task='11ef4b1c-34a4-42cd-bae2-b47a421e1015') Job.run: running createVolume: <bound method StoragePool.createVolume of <vdsm.storage.sp.St oragePool object at 0x7fbc080c7290>> (args: (u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', u'4a6f681b-7d99-4d70-8842-62d6cbabcf1d', 1073741824, 4, 2, 'DATA', u'114e525e-3951-472f-9f41-072bd784684d', u'', u'4a6f681b- 7d99-4d70-8842-62d6cbabcf1d', u'a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', None) kwargs: {}) callback None (task:333) 2019-09-30 19:51:10,241+0300 ERROR (tasks/4) [storage.TaskManager.Task] (Task='11ef4b1c-34a4-42cd-bae2-b47a421e1015') 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 1940, in createVolume initial_size=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 930, in createVolume initial_size=initial_size) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1212, in create raise se.InvalidParameterException("capacity", capacity) InvalidParameterException: Invalid parameter: 'capacity=1073741824' Scenario + timestamps: 19:51:07 2019-09-30 19:51:07,022 INFO Test Setup 1: Creating new VM vm_test_copy_disk_iscsi_3019510702 19:51:07 2019-09-30 19:51:07,025 INFO Test Setup 2: [function] Create new vm with nic nic1, disk and OS with {'diskActive': True, 'wipe_after_delete': 'false', 'slim': False, 'cluster': 'golden_env_mixed_1', 'linked': 'true', 'network': 'ovirtmgmt', 'plugged': 'true', 'start': 'false', 'vmDescription': 'vm_test_copy_disk_iscsi_3019510702', 'type': 'desktop', 'template': 'Blank', 'volumeFormat': 'cow', 'display_type': 'spice', 'attempt': 60, 'password': 'qum5net', 'installation': False, 'diskInterface': 'virtio', 'bootable': 'true', 'vmName': 'vm_test_copy_disk_iscsi_3019510702', 'copy_permissions': False, 'interval': 60, 'volumeType': 'true', 'diskType': 'data', 'useAgent': True, 'async': False, 'user': 'root'} 19:51:07 2019-09-30 19:51:07,028 INFO Test Setup 3: [function] Description vm_test_copy_disk_iscsi_3019510702: add new vm (without starting it) with {'name': 'vm_test_copy_disk_iscsi_3019510702', 'copy_permissions': False, 'cluster': 'golden_env_mixed_1', 'display_type': 'spice', 'template': 'Blank', 'async': False, 'type': 'desktop', 'wait': True} 19:51:07 2019-09-30 19:51:07,848 INFO Test Setup 4: [function] Add vNIC name nic1 to VM vm_test_copy_disk_iscsi_3019510702 with {'linked': 'true', 'vnic_profile': 'ovirtmgmt', 'network': 'ovirtmgmt', 'plugged': 'true'} 19:51:08 2019-09-30 19:51:08,504 INFO 022: storage/rhevmtests.storage.storage_copy_disk.test_copy_disk.TestCase11339.test_copy_vm_disks_with_snapshot[iscsi] 19:51:08 2019-09-30 19:51:08,504 INFO Copy existing disk when vm is with snapshot 19:51:08 2019-09-30 19:51:08,505 INFO STORAGE: ISCSI 19:51:08 2019-09-30 19:51:08,505 INFO Test Step 5: Taking snapshot of VM copy_disk_vm_iscsi 19:51:08 2019-09-30 19:51:08,507 INFO Test Step 6: Add snapshot to VM copy_disk_vm_iscsi with {'description': 'snapshot_11339', 'wait': True} 19:51:47 2019-09-30 19:51:47,211 ERROR Result: FAILED? 2019-09-30 19:51:09,651+0300 ERROR (tasks/4) [storage.Volume] Requested capacity 1073741824 < parent capacity 3221225472 (volume:1211) (Originally by Avihai Efrat)
Created attachment 1622222 [details] TC11339_snapshot_failed_logs (Originally by Avihai Efrat)
Avihai, Can you please add clear steps to reproduce without all the automation log noise? (Originally by Eyal Shenitzky)
Created attachment 1622297 [details] suspicious_disk_actual_size_print_screen (Originally by Avihai Efrat)
2 suspicious disks found related to first TestCase which is still on the ENV. Both can not be accessed via host but only appear at engine DB as seen below. 1) This was the first disk(templateB created from VM virtio_scsiraw disk) that was created with the wrong actual_size(3G) and triggered this issue. creation_date correlates to this engine log entire: 2019-09-30 20:07:35,142+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-11) [templates_create_3141cdb7-af66-42fe] START, CopyImageVDSCommand( CopyImageVDSCommandParameters :{storagePoolId='3d5b32f3-3a06-4263-9b32-a4fa20853922', ignoreFailoverLimit='false', storageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', imageGroupId='4a6f681b-7d99-4d70-8842-62d6cbabcf1d', imageId='a288569 7-aaaa-4e0f-8f0d-0370cdd3c4f7', dstImageGroupId='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', vmId='7d3e4f40-cd2e-476c-8ae3-2ab5f86e32e9', dstImageId='cc709bc2-402e-4022-b174-7935ddc30dfb', imageDescription='{"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""}', dstStorageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', copyVolumeType='SharedVol', volumeFormat='RAW', preallocate='Preallocated', postZero='true', discard='false', force='false'}), log id: 7b82c104 VDSM: 2019-09-30 20:07:35,150+0300 INFO (jsonrpc/7) [vdsm.api] START copyImage(sdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID=u'3d5b32f3-3a06-4263-9b32-a4fa20853922', vmUUID='', srcImgUUID=u'4a6f681b-7d99-4d70-8842-62d6cbabcf1d', srcVolUUID=u'a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', dstImgUUID=u'be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', dstVolUUID=u'cc709bc2-402e-4022-b174-7935ddc30dfb', description=u'{"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""}', dstSdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', volType=6, volFormat=5, preallocate=1, postZero=u'true', force=u'false', discard=False) from=::ffff:10.46.16.250,56230, flow_id=templates_create_3141cdb7-af66-42fe, task_id=0fa29924-566d-42fe-bd08-f716528e0c6a (api:48) *** AND here you see the request to create this volume with faulty size: 2019-09-30 20:07:44,380+0300 INFO (tasks/0) [storage.Volume] Request to create RAW volume /rhev/data-center/mnt/blockSD/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/images/be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed/cc709bc2-402e-4022-b174-7935ddc30dfb with capacity = 3221225472 (blockVolume:508) *** DB INFO on disk1: actual_size = 3221225472 size = 1073741824 alias = disk_virtio_scsiraw_3019262787_copy_disk disk_id='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed' Creation date = '2019-09-30 20:07:46+03' engine=# select * from all_disks where disk_id='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed'; -[ RECORD 1 ]--------------+----------------------------------------- storage_id | 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1 storage_name | iscsi_2 storage_type | 3 storage_pool_id | 3d5b32f3-3a06-4263-9b32-a4fa20853922 image_guid | cc709bc2-402e-4022-b174-7935ddc30dfb creation_date | 2019-09-30 20:07:46+03 actual_size | 3221225472 read_rate | write_rate | read_latency_seconds | write_latency_seconds | flush_latency_seconds | size | 1073741824 it_guid | 00000000-0000-0000-0000-000000000000 imagestatus | 1 lastmodified | 1970-01-01 02:00:00+02 volume_type | 1 volume_format | 5 qcow_compat | 0 image_group_id | be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed description | parentid | 00000000-0000-0000-0000-000000000000 app_list | vm_snapshot_id | 14d91e27-b389-4cb0-9da3-70f6e6347f30 active | t volume_classification | 0 entity_type | TEMPLATE number_of_vms | 1 vm_names | template_copy_disk_11141 template_version_names | base version quota_id | quota_name | quota_enforcement_type | 0 image_transfer_phase | image_transfer_type | image_transfer_bytes_sent | image_transfer_bytes_total | progress | disk_profile_id | 5fbe33cb-5815-47fe-bf87-ee0e9f654cbd disk_profile_name | iscsi_2 lun_id | physical_volume_id | volume_group_id | serial | lun_mapping | vendor_id | product_id | device_size | discard_max_size | disk_id | be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed wipe_after_delete | t propagate_errors | Off disk_alias | disk_virtio_scsiraw_3019262787_copy_disk disk_description | shareable | f sgio | disk_storage_type | 0 cinder_volume_type | disk_content_type | 0 backup | None 2) This is the 2nd disk that was created from template B ( from the faulty template disk1) VDSM log: 2019-09-30 20:09:29,517+0300 INFO (jsonrpc/2) [vdsm.api] START createVolume(sdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID=u'3d5b32f3-3a06-4263-9b32-a4fa20853922', imgUUID=u'09d2cca3-662a-47f9-a1dd-6f6ebca12418', size=u'1073741824', volFormat=4, preallocate=2, diskType=u'DATA', volUUID=u'76c2db22-d0eb-44cd-891f-2ce18828ef79', desc=u'', srcImgUUID=u'be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', srcVolUUID=u'cc709bc2-402e-4022-b174-7935ddc30dfb', initialSize=None) from=::ffff:10.46.16.250,56230, flow_id=vms_create_5865f184-2b60-4d68, task_id=852412ff-dfe8-4d01-8752-2ad2572c839e (api:48) *** DB INFO on disk2: actual_size = 3221225472 size = 1073741824 alias = disk_virtio_scsiraw_3019262787_copy_disk disk_id='09d2cca3-662a-47f9-a1dd-6f6ebca12418' creation_date= '2019-09-30 20:09:29.496+03' engine=# select * from all_disks where disk_id='09d2cca3-662a-47f9-a1dd-6f6ebca12418'; -[ RECORD 1 ]--------------+----------------------------------------- storage_id | 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1 storage_name | iscsi_2 storage_type | 3 storage_pool_id | 3d5b32f3-3a06-4263-9b32-a4fa20853922 image_guid | 76c2db22-d0eb-44cd-891f-2ce18828ef79 creation_date | 2019-09-30 20:09:29.496+03 actual_size | 3221225472 read_rate | write_rate | read_latency_seconds | write_latency_seconds | flush_latency_seconds | size | 1073741824 it_guid | cc709bc2-402e-4022-b174-7935ddc30dfb imagestatus | 2 lastmodified | 2019-09-30 20:09:29.496+03 volume_type | 2 volume_format | 4 qcow_compat | 0 image_group_id | 09d2cca3-662a-47f9-a1dd-6f6ebca12418 description | Active VM parentid | cc709bc2-402e-4022-b174-7935ddc30dfb app_list | vm_snapshot_id | aecaa0e1-3ef5-44c4-98ac-21d32abf8c96 active | t volume_classification | 0 entity_type | VM number_of_vms | 1 vm_names | cloned_vm_copy_disk_11141 template_version_names | quota_id | quota_name | quota_enforcement_type | 0 image_transfer_phase | image_transfer_type | image_transfer_bytes_sent | image_transfer_bytes_total | progress | disk_profile_id | 5fbe33cb-5815-47fe-bf87-ee0e9f654cbd disk_profile_name | iscsi_2 lun_id | physical_volume_id | volume_group_id | serial | lun_mapping | vendor_id | product_id | device_size | discard_max_size | disk_id | 09d2cca3-662a-47f9-a1dd-6f6ebca12418 wipe_after_delete | t propagate_errors | Off disk_alias | disk_virtio_scsiraw_3019262787_copy_disk disk_description | shareable | f sgio | disk_storage_type | 0 cinder_volume_type | disk_content_type | 0 backup | None (Originally by Avihai Efrat)
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. (Originally by pm-rhel)
In both TestCases the VM is added with additional(other than OS disk) +4 disks to it each with 1G size(RAW_VIRTIO, RAW_SCSI_VIRTIO, QCOW_VIRTIO, QCOW_SCSI_VIRTIO ) and then some operation was done to it like creating a template from VM(TestCase11141) or creating snapshot(TestCase11339). Somehow after that operation the new volumes created from the 'virtio_scsiraw' disk ONLY get created with actual_size=3G and virtual_size=1G. This occurs only on 'virtio_scsiraw' disk in both TC's, why is that seen only on a disk that its origin was with: interface=virtio_scsi and Allocation policy= Preallocated(RAW) (Originally by Avihai Efrat)
Image be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed was created as a copy of an image 4a6f681b-7d99-4d70-8842-62d6cbabcf1d: engine.log:2019-09-30 20:07:35,142+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-11) [templates_create_3141cdb7-af66-42fe] START, CopyImageVDSCommand( CopyImageVDSCommandParameters:{storagePoolId='3d5b32f3-3a06-4263-9b32-a4fa20853922', ignoreFailoverLimit='false', storageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', imageGroupId='4a6f681b-7d99-4d70-8842-62d6cbabcf1d', imageId='a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', dstImageGroupId='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', vmId='7d3e4f40-cd2e-476c-8ae3-2ab5f86e32e9', dstImageId='cc709bc2-402e-4022-b174-7935ddc30dfb', imageDescription='{"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""}', dstStorageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', copyVolumeType='SharedVol', volumeFormat='RAW', preallocate='Preallocated', postZero='true', discard='false', force='false'}), log id: 7b82c104 vdsm.log:2019-09-30 20:07:35,150+0300 INFO (jsonrpc/7) [vdsm.api] START copyImage(sdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID=u'3d5b32f3-3a06-4263-9b32-a4fa20853922', vmUUID='', srcImgUUID=u'4a6f681b-7d99-4d70-8842-62d6cbabcf1d', srcVolUUID=u'a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', dstImgUUID=u'be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', dstVolUUID=u'cc709bc2-402e-4022-b174-7935ddc30dfb', description=u'{"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""}', dstSdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', volType=6, volFormat=5, preallocate=1, postZero=u'true', force=u'false', discard=False) from=::ffff:10.46.16.250,56230, flow_id=templates_create_3141cdb7-af66-42fe, task_id=0fa29924-566d-42fe-bd08-f716528e0c6a (api:48) Image 4a6f681b-7d99-4d70-8842-62d6cbabcf1d doesn't exits any more in the environment, but its size was 3GB: vdsm.log:2019-09-30 20:07:38,069+0300 INFO (tasks/0) [storage.Image] Copy source 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1:4a6f681b-7d99-4d70-8842-62d6cbabcf1d:a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 to destination 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1:be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed:cc709bc2-402e-4022-b174-7935ddc30dfb size=3221225472, initial size=None (image:771) Before creating another image from it (snapshot from template), engine asked for info about be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed (resp. about its volume be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed) engine.log:2019-09-30 20:09:09,908+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engine-Thread-4611) [templates_create_3141cdb7-af66-42fe] START, GetVolumeInfoVDSCommand(HostName = host_mixed_1, GetVolumeInfoVDSCommandParameters:{hostId='076fcaa1-7c22-49ad-b515-f0381f9b46ea', storagePoolId='3d5b32f3-3a06-4263-9b32-a4fa20853922', storageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', imageGroupId='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', imageId='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed'}), log id: 3d817a33 and got correct answer from vdsm, that its size is 3GB: vdsm.log:2019-09-30 20:09:09,966+0300 INFO (jsonrpc/2) [vdsm.api] FINISH getVolumeInfo return={'info': {'status': 'OK', 'domain': '90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', 'voltype': 'SHARED', 'description': '{"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'generation': 0, 'image': 'be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', 'disktype': 'DATA', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '3221225472', 'children': [], 'pool': '', 'ctime': '1569863266', 'capacity': '3221225472', 'uuid': u'cc709bc2-402e-4022-b174-7935ddc30dfb', 'truesize': '3221225472', 'type': 'PREALLOCATED', 'lease': {'path': '/dev/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/leases', 'owners': [], 'version': None, 'offset': 123731968}}} from=::ffff:10.46.16.250,56222, flow_id=templates_create_3141cdb7-af66-42fe, task_id=9e1b7503-4ef0-4eb2-8f62-57b419295568 (api:54) Engine went ahead and asked vdsm to create new volume from be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed, but now only with size 1GB: engine.log:2019-09-30 20:09:29,512+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-11) [vms_create_5865f184-2b60-4d68] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='3d5b32f3-3a06-4263-9b32-a4fa20853922', ignoreFailoverLimit='false', storageDomainId='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', imageGroupId='09d2cca3-662a-47f9-a1dd-6f6ebca12418', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='76c2db22-d0eb-44cd-891f-2ce18828ef79', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='cc709bc2-402e-4022-b174-7935ddc30dfb', sourceImageGroupId='be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed'}), log id: 475f3780 which vdsm did: vdsm.log:2019-09-30 20:09:29,517+0300 INFO (jsonrpc/2) [vdsm.api] START createVolume(sdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID=u'3d5b32f3-3a06-4263-9b32-a4fa20853922', imgUUID=u'09d2cca3-662a-47f9-a1dd-6f6ebca12418', size=u'10737418 24', volFormat=4, preallocate=2, diskType=u'DATA', volUUID=u'76c2db22-d0eb-44cd-891f-2ce18828ef79', desc=u'', srcImgUUID=u'be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', srcVolUUID=u'cc709bc2-402e-4022-b174-7935ddc30dfb', initialSize=None) from= ::ffff:10.46.16.250,56230, flow_id=vms_create_5865f184-2b60-4d68, task_id=852412ff-dfe8-4d01-8752-2ad2572c839e (api:48) and failed as requested size was lower than parent size: vdsm.log:2019-09-30 20:09:30,710+0300 ERROR (tasks/6) [storage.Volume] Requested capacity 1073741824 < parent capacity 3221225472 (volume:1211) If you run volume info on be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed, you still get correct information from vdsm, that it's volume is 3GB: 2019-10-07 14:55:32,238+0300 INFO (jsonrpc/4) [vdsm.api] FINISH getVolumeInfo return={'info': {'status': 'OK', 'domain': '90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', 'voltype': 'SHARED', 'description': '{"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'generation': 0, 'image': 'be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed', 'disktype': 'DATA', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '3221225472', 'children': [], 'pool': '', 'ctime': '1569863266', 'capacity': '3221225472', 'uuid': u'cc709bc2-402e-4022-b174-7935ddc30dfb', 'truesize': '3221225472', 'type': 'PREALLOCATED', 'lease': {'path': '/dev/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/leases', 'owners': [], 'version': None, 'offset': 123731968}}} from=::1,40128, task_id=4a77c351-38c1-46e1-8f71-9387c90e03b8 (api:54) You can also check it directly on the host by running vdsm-client (for be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed as well as for it's snapshot 09d2cca3-662a-47f9-a1dd-6f6ebca12418): vdsm-client Volume getInfo storagepoolID=3d5b32f3-3a06-4263-9b32-a4fa20853922 storagedomainID=90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1 imageID=be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed volumeID=cc709bc2-402e-4022-b174-7935ddc30dfb { "status": "OK", "lease": { "path": "/dev/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/leases", "owners": [], "version": null, "offset": 123731968 }, "domain": "90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1", "capacity": "3221225472", "voltype": "SHARED", "description": "{\"DiskAlias\":\"disk_virtio_scsiraw_3019262787_copy_disk\",\"DiskDescription\":\"\"}", "parent": "00000000-0000-0000-0000-000000000000", "format": "RAW", "generation": 0, "image": "be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed", "uuid": "cc709bc2-402e-4022-b174-7935ddc30dfb", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "3221225472", "truesize": "3221225472", "type": "PREALLOCATED", "children": [], "pool": "", "ctime": "1569863266" } [root@lynx09 images]# vdsm-client Volume getInfo storagepoolID=3d5b32f3-3a06-4263-9b32-a4fa20853922 storagedomainID=90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1 imageID=09d2cca3-662a-47f9-a1dd-6f6ebca12418 volumeID=cc709bc2-402e-4022-b174-7935ddc30dfb { "status": "OK", "lease": { "path": "/dev/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/leases", "owners": [], "version": null, "offset": 123731968 }, "domain": "90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1", "capacity": "3221225472", "voltype": "SHARED", "description": "{\"DiskAlias\":\"disk_virtio_scsiraw_3019262787_copy_disk\",\"DiskDescription\":\"\"}", "parent": "00000000-0000-0000-0000-000000000000", "format": "RAW", "generation": 0, "image": "be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed", "uuid": "cc709bc2-402e-4022-b174-7935ddc30dfb", "disktype": "DATA", "legality": "LEGAL", "mtime": "0", "apparentsize": "3221225472", "truesize": "3221225472", "type": "PREALLOCATED", "children": [], "pool": "", "ctime": "1569863266" } Also the metadata of the volume cc709bc2-402e-4022-b174-7935ddc30dfb is correct: #lvs -o tags 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/cc709bc2-402e-4022-b174-7935ddc30dfb LV Tags IU_be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed,MD_18,PU_00000000-0000-0000-0000-000000000000 #dd if=/dev/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/metadata bs=512 count=1 skip=$OFFSET iflag=direct,skip_bytes CAP=3221225472 CTIME=1569863266 DESCRIPTION={"DiskAlias":"disk_virtio_scsiraw_3019262787_copy_disk","DiskDescription":""} DISKTYPE=DATA DOMAIN=90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1 FORMAT=RAW GEN=0 IMAGE=be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed LEGALITY=LEGAL PUUID=00000000-0000-0000-0000-000000000000 TYPE=PREALLOCATED VOLTYPE=SHARED EOF So, I'd conclude that vdsm provided correct information, and it went wrong somewhere in the engine at the very beginning, during creation of the image be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed (maybe in CopyImageVDSCommand?). (Originally by Vojtech Juranek)
Vojech , Thanks for the in depth details! Do you still need the stand? Also to provide more info on my side: "Image 4a6f681b-7d99-4d70-8842-62d6cbabcf1d doesn't exits any more in the environment, but its size was 3GB" Well on this stage (2019-09-30 20:07:38) the test was at step 6: 1) Create VM from templateA 2) Add 4 disks: RAW_VIRTIO, RAW_SCSI_VIRTIO, QCOW_VIRTIO, QCOW_SCSI_VIRTIO 3) Start VM 4) Creating FS on VM's disks 5) Stop VM 6) Create templateB from VM as thin(not clone) Meaning that either the RAW_SCSI_VIRTIO disk size alone changed to 3G before/after creating templateB from VM. In any case a RAW/Preallocated disk SHOULD NOT change size unless it has been extended and as it was created as 1G and was not extended. 1)How can this occur without extending the disk? 2) about: "Engine went ahead and asked vdsm to create new volume from be01fb5c-0aa2-413f-9f36-d4d41b4cd3ed, but now only with size 1GB:" If the engine already knew that capacity if the father volume is 3G why did it create a new child volume with 1GB size ? (Originally by Avihai Efrat)
The root cause seem that the image (4a6f681b-7d99-4d70-8842-62d6cbabcf1d) somehow changed its size from 1GB to 3GB. It was really created as 1GB image: 2019-09-30 19:26:28,731+0300 INFO (jsonrpc/6) [vdsm.api] START createVolume(sdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID=u'3d5b32f3-3a06-4263-9b32-a4fa20853922', imgUUID=u'4a6f681b-7d99-4d70-8842-62d6cbabcf1d', size=u'1073741824', volFormat=5, preallocate=1, diskType=u'DATA', volUUID=u'a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', desc=u'{"DiskAlias":"disk_virtio_scsiraw_3019262787","DiskDescription":""}', srcImgUUID=u'00000000-0000-0000-0000-000000000000', srcVolUUID=u'00000000-0000-0000-0000-000000000000', initialSize=None) from=::ffff:10.46.16.250,56230, flow_id=disks_create_a5ae27cd-d9bd-47f6, task_id=a190a48b-d7b9-4480-9720-4f69e9c712e0 (api:48) vdsm saw it as 1GB image: 2019-09-30 19:26:46,019+0300 INFO (jsonrpc/4) [vdsm.api] FINISH getVolumeInfo return={'info': {'status': 'OK', 'domain': '90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', 'voltype': 'LEAF', 'description': '{"DiskAlias":"disk_virtio_scsiraw_3019262787","DiskDescription":""}', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'generation': 0, 'image': '4a6f681b-7d99-4d70-8842-62d6cbabcf1d', 'disktype': 'DATA', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '1073741824', 'children': [], 'pool': '', 'ctime': '1569860791', 'capacity': '1073741824', 'uuid': u'a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', 'truesize': '1073741824', 'type': 'PREALLOCATED', 'lease': {'path': '/dev/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/leases', 'owners': [], 'version': None, 'offset': 113246208}}} from=::ffff:10.46.16.250,56222, flow_id=disks_create_a5ae27cd-d9bd-47f6, task_id=7a3d114d-3b4b-4ad8-8484-445f72c6876f (api:54) then the image was attached to to VMs, the last one still saw it as 1GB image: 2019-09-30 19:34:34,699+0300 INFO (jsonrpc/4) [api.virt] FINISH getStats return={ ... 'disks': {... 'sdb': {'readLatency': '0', 'flushLatency': '0', 'readRate': '0.0', 'writeRate': '0.0', 'writtenBytes': '32768', 'truesize': '1073741824', 'apparentsize': '1073741824', 'readOps': '345', 'writeLatency': '0', 'imageID': '4a6f681b-7d99-4d70-8842-62d6cbabcf1d', 'readBytes': '9538048', 'writeOps': '7'} ... } VM was tuned off and only few seconds later on different host (assuming time was synced on all hosts), vdsm copied the image as 3GB: 2019-09-30 19:34:56,503+0300 INFO (tasks/9) [storage.Image] Copy source 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1:4a6f681b-7d99-4d70-8842-62d6cbabcf1d:a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 to destination 7253012f-5881-44a4-bbf6-d37cf0e1f06e:e9b4b15f-71d7-4fb0-bf7e-dd0bd22ec3e5:ffda270b-2889-4290-a01b-e06938527443 size=3221225472, initial size=None (image:771) Unfortunately, I have no idea how this could happened:-( (Originally by Vojtech Juranek)
According to the logs the steps to reproduce are missing a step, in that step the error occurs: 1) Create VM from templateA 2) Add 4 disks: RAW_VIRTIO, RAW_SCSI_VIRTIO, QCOW_VIRTIO, QCOW_SCSI_VIRTIO 3) Start VM 4) Creating FS on VM's disks 5) Stop VM 6) Create templateB from VM 7) Create a VM from templateB as thin(not clone) -> here the operation failed. I'm still not sure why is this occurs, I try to track back the whole image chain to see if there is some conflicts during all those steps but the log doesn't contain all the image history. (Originally by Eyal Shenitzky)
> I try to track back the whole image > chain to see if there is some > conflicts during all those steps but the log doesn't contain all the image > history. which log do you mean? vdsm logs IMHO contains all history for this image chain. It starts with creating image 4a6f681b-7d99-4d70-8842-62d6cbabcf1d (step 2) - adding a disk to new VM), see comment #14 (Originally by Vojtech Juranek)
as for conflicts, volume a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 had metadata slot number 8 and there was a disk with size 3GB in the same SD: vdsm.log.91:2019-09-30 19:21:50,520+0300 INFO (tasks/0) [storage.Volume] Request to create COW volume /rhev/data-center/mnt/blockSD/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/images/5ea2c926-4b37-46f5-8e04-de0a916098c2/fd451551-a9e5-4cc6-8f4d-2afec4371fe6 with capacity = 3221225472 (blockVolume:508) and had also MD slot 8: vdsm.log.91:2019-09-30 19:21:50,879+0300 DEBUG (tasks/0) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/sudo -n /sbin/lvm lvchange --config 'devices { preferred_names=["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter=["a|^/dev/mapper/3600a09803830447a4f244c4657595049$|^/dev/mapper/3600a09803830447a4f244c465759504a$|^/dev/mapper/3600a09803830447a4f244c465759504b$|^/dev/mapper/3600a09803830447a4f244c465759504c$|^/dev/mapper/3600a09803830447a4f244c465759504d$|^/dev/mapper/3600a09803830447a4f244c465759504e$|^/dev/mapper/3600a09803830447a4f244c4657595072$|", "r|.*|"] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 use_lvmetad=0 } backup { retain_min=50 retain_days=0 }' --autobackup n --deltag OVIRT_VOL_INITIALIZING --addtag PU_00000000-0000-0000-0000-000000000000 --addtag MD_8 --addtag IU_5ea2c926-4b37-46f5-8e04-de0a916098c2 90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/fd451551-a9e5-4cc6-8f4d-2afec4371fe6 (cwd None) (commands:198) but this volume was removed about one minute before a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 was created: vdsm.log.91:2019-09-30 19:25:00,240+0300 INFO (tasks/7) [storage.StorageDomainManifest] removed: [u'/rhev/data-center/mnt/blockSD/90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1/images/5ea2c926-4b37-46f5-8e04-de0a916098c2/fd451551-a9e5-4cc6-8f4d-2afec4371fe6'] (blockSD:729) I don't see a way how we can write new metadata (for a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7), but old size, therefore I didn't mentioned it in previous comments. Maybe there's something I missed... (Originally by Vojtech Juranek)
The same issue has seen again on 4.3 tier1 execution (TestCase6004) Live disk migration from iscsi_1 to iscsi_2 failed. The reason is the failure of snapshot creation as part of the live disk migration. I tried to execute it again but all went fine. Environment: ovirt-engine-4.3.6.7-0.1.el7.noarch vdsm-4.30.33-1.el7ev.x86_64 The test steps are: 1. Create VM from template 2. Create 4 disks in addition to the disk from the template 3. Attach the disks to the VM 4. Move the disks from iscsi_1 to iscsi_2 In this case (attached logs): 1. Create VM (vm_TestCase6004_1621365240) from template (rhel8): id=3de71a63-fe80-4284-a4bb-bacf6b0660ce disk = vm_TestCase6004_1621365240_Disk_0 (d16a2369-358d-43bd-94ce-5655e9de2f7b) 2. Create 4 disks: disk_virtioraw_1621371521 (2df1761e-44c1-47f2-83ef-37ccb8c08dd5) disk_virtiocow_1621371521 (10e3137e-ba61-4a41-8466-1abb8fcf8fef) disk_virtio_scsicow_1621371521 (4a278ae2-861b-45ca-ac3e-3e5bed31655a) disk_virtio_scsiraw_1621371521 (e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb) 3. Attach the disks 4. Move the disks from iscsi_1 to iscsi_2 The disk e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb (disk_virtio_scsiraw_1621371521) failed to move due to snapshot creation failure Engine log: 2019-10-16 21:38:40,607+03 INFO [org.ovirt.engine.core.bll.storage.disk.MoveDiskCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] Running command: MoveDiskCommand internal: false. Entities affected : ID: e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb Type: DiskAction group CONFIGURE_DISK_STORAGE with role type USER, ID: 9cba961d-7943-4c23-89c4-bd6c4b024500 Type: StorageAction group CREATE_DISK with role type USER 2019-10-16 21:38:41,071+03 INFO [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] Running command: LiveMigrateDiskCommand internal: true. Entities affected : ID: e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb Type: DiskAction group DISK_LIVE_STORAGE_MIGRATION with role type USER 2019-10-16 21:38:41,223+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] Running command: CreateSnapshotForVmCommand internal: true. Entities affected : ID: 3de71a63-fe80-4284-a4bb-bacf6b0660ce Type: VMAction group MANIPULATE_VM_SNAPSHOTS with role type USER 2019-10-16 21:38:41,256+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] Running command: CreateSnapshotDiskCommand internal: true. Entities affected : ID: 3de71a63-fe80-4284-a4bb-bacf6b0660ce Type: VMAction group MANIPULATE_VM_SNAPSHOTS with role type USER 2019-10-16 21:38:41,349+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='ab862b38-1bd5-40fb-bcc5-649b6693aa03', ignoreFailoverLimit='false', storageDomainId='343db66b-129a-4b55-9dbf-5395a32b6d25', imageGroupId='e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='67fe6587-4191-44c0-8d8c-fbeb315e6b03', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='f675aa67-6a38-441b-9b31-cb404742635d', sourceImageGroupId='e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb'}), log id: 2a63b3ec 2019-10-16 21:38:41,403+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [41186452] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 62f3a77b 2019-10-16 21:38:41,408+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [41186452] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='ab862b38-1bd5-40fb-bcc5-649b6693aa03', ignoreFailoverLimit='false', storageDomainId='7973aadb-0edc-498a-b929-74867f077b53', imageGroupId='a9d05840-24af-4083-9fc0-9e6faa5122d0', imageId='c359a2f7-0272-4f31-a04d-89068d077b71'}), log id: 6a87cf 2019-10-16 21:38:41,462+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] FINISH, CreateVolumeVDSCommand, return: 67fe6587-4191-44c0-8d8c-fbeb315e6b03, log id: 2a63b3ec 2019-10-16 21:38:41,469+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-7) [disks_syncAction_744a180c-eddd-4512] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'ab4f1edd-9f52-4480-af97-97f82a9586c6' 2019-10-16 21:38:41,469+03 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-7) [disks_syncAction_744a180c-eddd-4512] CommandMultiAsyncTasks::attachTask: Attaching task 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' to command 'ab4f1edd-9f52-4480-af97-97f82a9586c6'. 2019-10-16 21:38:41,488+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-7) [disks_syncAction_744a180c-eddd-4512] Adding task 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2019-10-16 21:38:41,602+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-7) [disks_syncAction_744a180c-eddd-4512] EVENT_ID: USER_CREATE_SNAPSHOT(45), Snapshot 'disk_virtio_scsiraw_1621371521 Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase6004_1621365240' was initiated by admin@internal-authz. 2019-10-16 21:38:41,629+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-7) [disks_syncAction_744a180c-eddd-4512] EVENT_ID: USER_MOVED_DISK(2,008), User admin@internal-authz moving disk disk_virtio_scsiraw_1621371521 to domain iscsi_2. 2019-10-16 21:38:41,637+03 INFO [org.ovirt.engine.core.bll.storage.disk.MoveDiskCommand] (default task-7) [disks_syncAction_744a180c-eddd-4512] Lock freed to object 'EngineLock:{exclusiveLocks='[e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb=DISK]', sharedLocks=''}' 2019-10-16 21:38:42,164+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-89) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotForVm' (id: '054f142a-5100-4b68-9575-17a970cef1f4') waiting on child command id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' type:'CreateSnapshotDisk' to complete 2019-10-16 21:38:42,165+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-89) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' (id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7') waiting on child command id: 'ab4f1edd-9f52-4480-af97-97f82a9586c6' type:'CreateSnapshot' to complete 2019-10-16 21:38:43,293+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-48) [disks_syncAction_744a180c-eddd-4512] Command 'LiveMigrateDisk' (id: 'dc63c772-0b1e-4752-9116-14f935c80214') waiting on child command id: '054f142a-5100-4b68-9575-17a970cef1f4' type:'CreateSnapshotForVm' to complete 2019-10-16 21:38:44,337+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-6) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotForVm' (id: '054f142a-5100-4b68-9575-17a970cef1f4') waiting on child command id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' type:'CreateSnapshotDisk' to complete 2019-10-16 21:38:44,338+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-6) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' (id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7') waiting on child command id: 'ab4f1edd-9f52-4480-af97-97f82a9586c6' type:'CreateSnapshot' to complete 2019-10-16 21:38:45,333+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] BaseAsyncTask::logEndTaskFailure: Task 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', code = 100', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', code = 100' 2019-10-16 21:38:45,339+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (EE-ManagedThreadFactory-engine-Thread-1552) [disks_syncAction_744a180c-eddd-4512] Command [id=ab4f1edd-9f52-4480-af97-97f82a9586c6]: Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands. 2019-10-16 21:38:45,340+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-1552) [disks_syncAction_744a180c-eddd-4512] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshot' completed, handling the result. 2019-10-16 21:38:45,340+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-1552) [disks_syncAction_744a180c-eddd-4512] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshot' succeeded, clearing tasks. 2019-10-16 21:38:45,340+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-1552) [disks_syncAction_744a180c-eddd-4512] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' 2019-10-16 21:38:48,516+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-29) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotForVm' (id: '054f142a-5100-4b68-9575-17a970cef1f4') waiting on child command id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' type:'CreateSnapshotDisk' to complete 2019-10-16 21:38:48,517+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-29) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' child commands '[ab4f1edd-9f52-4480-af97-97f82a9586c6]' executions were completed, status 'FAILED' 2019-10-16 21:38:48,517+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-29) [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' id: '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands. VDSM log: 2019-10-16 21:38:41,832+0300 ERROR (tasks/5) [storage.Volume] Requested capacity 1073741824 < parent capacity 10737418240 (volume:1211) 2019-10-16 21:38:41,833+0300 ERROR (tasks/5) [storage.TaskManager.Task] (Task='e5a566e9-51c0-4df7-bf3f-982f1322ac34') 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 1940, in createVolume initial_size=initialSize) File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 930, in createVolume initial_size=initial_size) File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1212, in create raise se.InvalidParameterException("capacity", capacity) InvalidParameterException: Invalid parameter: 'capacity=1073741824' (Originally by Yosef Ben Shimon)
Created attachment 1628461 [details] TestCase6004 logs (Originally by Yosef Ben Shimon)
(In reply to Yosi Ben Shimon from comment #18) > The same issue has seen again on 4.3 tier1 execution (TestCase6004) > Live disk migration from iscsi_1 to iscsi_2 failed. > The reason is the failure of snapshot creation as part of the live disk > migration. > I tried to execute it again but all went fine. > > Environment: > ovirt-engine-4.3.6.7-0.1.el7.noarch > vdsm-4.30.33-1.el7ev.x86_64 > > > The test steps are: > 1. Create VM from template > 2. Create 4 disks in addition to the disk from the template > 3. Attach the disks to the VM > 4. Move the disks from iscsi_1 to iscsi_2 > > > In this case (attached logs): > 1. Create VM (vm_TestCase6004_1621365240) from template (rhel8): > id=3de71a63-fe80-4284-a4bb-bacf6b0660ce > disk = vm_TestCase6004_1621365240_Disk_0 > (d16a2369-358d-43bd-94ce-5655e9de2f7b) > > 2. Create 4 disks: > disk_virtioraw_1621371521 (2df1761e-44c1-47f2-83ef-37ccb8c08dd5) > disk_virtiocow_1621371521 (10e3137e-ba61-4a41-8466-1abb8fcf8fef) > disk_virtio_scsicow_1621371521 (4a278ae2-861b-45ca-ac3e-3e5bed31655a) > disk_virtio_scsiraw_1621371521 (e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb) > 3. Attach the disks > 4. Move the disks from iscsi_1 to iscsi_2 > > The disk e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb > (disk_virtio_scsiraw_1621371521) failed to move due to snapshot creation > failure > > > Engine log: > > 2019-10-16 21:38:40,607+03 INFO > [org.ovirt.engine.core.bll.storage.disk.MoveDiskCommand] (default task-7) > [disks_syncAction_744a180c-eddd-4512] Running command: MoveDiskCommand > internal: false. Entities affected : ID: > e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb Type: DiskAction group > CONFIGURE_DISK_STORAGE with role type USER, ID: > 9cba961d-7943-4c23-89c4-bd6c4b024500 Type: StorageAction group CREATE_DISK > with role type USER > > 2019-10-16 21:38:41,071+03 INFO > [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand] (default > task-7) [disks_syncAction_744a180c-eddd-4512] Running command: > LiveMigrateDiskCommand internal: true. Entities affected : ID: > e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb Type: DiskAction group > DISK_LIVE_STORAGE_MIGRATION with role type USER > > > 2019-10-16 21:38:41,223+03 INFO > [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default > task-7) [disks_syncAction_744a180c-eddd-4512] Running command: > CreateSnapshotForVmCommand internal: true. Entities affected : ID: > 3de71a63-fe80-4284-a4bb-bacf6b0660ce Type: VMAction group > MANIPULATE_VM_SNAPSHOTS with role type USER > 2019-10-16 21:38:41,256+03 INFO > [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (default > task-7) [disks_syncAction_744a180c-eddd-4512] Running command: > CreateSnapshotDiskCommand internal: true. Entities affected : ID: > 3de71a63-fe80-4284-a4bb-bacf6b0660ce Type: VMAction group > MANIPULATE_VM_SNAPSHOTS with role type USER > > 2019-10-16 21:38:41,349+03 INFO > [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default > task-7) [disks_syncAction_744a180c-eddd-4512] START, CreateVolumeVDSCommand( > CreateVolumeVDSCommandParameters:{storagePoolId='ab862b38-1bd5-40fb-bcc5- > 649b6693aa03', ignoreFailoverLimit='false', > storageDomainId='343db66b-129a-4b55-9dbf-5395a32b6d25', > imageGroupId='e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb', > imageSizeInBytes='1073741824', volumeFormat='COW', > newImageId='67fe6587-4191-44c0-8d8c-fbeb315e6b03', imageType='Sparse', > newImageDescription='', imageInitialSizeInBytes='0', > imageId='f675aa67-6a38-441b-9b31-cb404742635d', > sourceImageGroupId='e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb'}), log id: 2a63b3ec > 2019-10-16 21:38:41,403+03 INFO > [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] > (EE-ManagedThreadFactory-engineScheduled-Thread-91) [41186452] FINISH, > SetVolumeDescriptionVDSCommand, return: , log id: 62f3a77b > 2019-10-16 21:38:41,408+03 INFO > [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] > (EE-ManagedThreadFactory-engineScheduled-Thread-91) [41186452] START, > SetVolumeDescriptionVDSCommand( > SetVolumeDescriptionVDSCommandParameters:{storagePoolId='ab862b38-1bd5-40fb- > bcc5-649b6693aa03', ignoreFailoverLimit='false', > storageDomainId='7973aadb-0edc-498a-b929-74867f077b53', > imageGroupId='a9d05840-24af-4083-9fc0-9e6faa5122d0', > imageId='c359a2f7-0272-4f31-a04d-89068d077b71'}), log id: 6a87cf > 2019-10-16 21:38:41,462+03 INFO > [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default > task-7) [disks_syncAction_744a180c-eddd-4512] FINISH, > CreateVolumeVDSCommand, return: 67fe6587-4191-44c0-8d8c-fbeb315e6b03, log > id: 2a63b3ec > > 2019-10-16 21:38:41,469+03 INFO > [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-7) > [disks_syncAction_744a180c-eddd-4512] CommandAsyncTask::Adding > CommandMultiAsyncTasks object for command > 'ab4f1edd-9f52-4480-af97-97f82a9586c6' > 2019-10-16 21:38:41,469+03 INFO > [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-7) > [disks_syncAction_744a180c-eddd-4512] CommandMultiAsyncTasks::attachTask: > Attaching task 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' to command > 'ab4f1edd-9f52-4480-af97-97f82a9586c6'. > 2019-10-16 21:38:41,488+03 INFO > [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-7) > [disks_syncAction_744a180c-eddd-4512] Adding task > 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' (Parent Command 'CreateSnapshot', > Parameters Type > 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling > hasn't started yet.. > > 2019-10-16 21:38:41,602+03 INFO > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] > (default task-7) [disks_syncAction_744a180c-eddd-4512] EVENT_ID: > USER_CREATE_SNAPSHOT(45), Snapshot 'disk_virtio_scsiraw_1621371521 > Auto-generated for Live Storage Migration' creation for VM > 'vm_TestCase6004_1621365240' was initiated by admin@internal-authz. > 2019-10-16 21:38:41,629+03 INFO > [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] > (default task-7) [disks_syncAction_744a180c-eddd-4512] EVENT_ID: > USER_MOVED_DISK(2,008), User admin@internal-authz moving disk > disk_virtio_scsiraw_1621371521 to domain iscsi_2. > 2019-10-16 21:38:41,637+03 INFO > [org.ovirt.engine.core.bll.storage.disk.MoveDiskCommand] (default task-7) > [disks_syncAction_744a180c-eddd-4512] Lock freed to object > 'EngineLock:{exclusiveLocks='[e0f8d2a3-4f58-4f9f-8b8b-26fff70d5dfb=DISK]', > sharedLocks=''}' > > 2019-10-16 21:38:42,164+03 INFO > [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-89) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotForVm' (id: > '054f142a-5100-4b68-9575-17a970cef1f4') waiting on child command id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' type:'CreateSnapshotDisk' to complete > 2019-10-16 21:38:42,165+03 INFO > [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-89) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' (id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7') waiting on child command id: > 'ab4f1edd-9f52-4480-af97-97f82a9586c6' type:'CreateSnapshot' to complete > > 2019-10-16 21:38:43,293+03 INFO > [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-48) > [disks_syncAction_744a180c-eddd-4512] Command 'LiveMigrateDisk' (id: > 'dc63c772-0b1e-4752-9116-14f935c80214') waiting on child command id: > '054f142a-5100-4b68-9575-17a970cef1f4' type:'CreateSnapshotForVm' to complete > > 2019-10-16 21:38:44,337+03 INFO > [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-6) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotForVm' (id: > '054f142a-5100-4b68-9575-17a970cef1f4') waiting on child command id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' type:'CreateSnapshotDisk' to complete > 2019-10-16 21:38:44,338+03 INFO > [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-6) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' (id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7') waiting on child command id: > 'ab4f1edd-9f52-4480-af97-97f82a9586c6' type:'CreateSnapshot' to complete > > 2019-10-16 21:38:45,333+03 ERROR > [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] > (EE-ManagedThreadFactory-engineScheduled-Thread-34) [] > BaseAsyncTask::logEndTaskFailure: Task > 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' (Parent Command 'CreateSnapshot', > Parameters Type > 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with > failure: > -- Result: 'cleanSuccess' > -- Message: 'VDSGenericException: VDSErrorException: Failed to > HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', > code = 100', > -- Exception: 'VDSGenericException: VDSErrorException: Failed to > HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'capacity=1073741824', > code = 100' > > 2019-10-16 21:38:45,339+03 INFO > [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] > (EE-ManagedThreadFactory-engine-Thread-1552) > [disks_syncAction_744a180c-eddd-4512] Command > [id=ab4f1edd-9f52-4480-af97-97f82a9586c6]: Updating status to 'FAILED', The > command end method logic will be executed by one of its parent commands. > 2019-10-16 21:38:45,340+03 INFO > [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] > (EE-ManagedThreadFactory-engine-Thread-1552) > [disks_syncAction_744a180c-eddd-4512] > CommandAsyncTask::HandleEndActionResult [within thread]: endAction for > action type 'CreateSnapshot' completed, handling the result. > 2019-10-16 21:38:45,340+03 INFO > [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] > (EE-ManagedThreadFactory-engine-Thread-1552) > [disks_syncAction_744a180c-eddd-4512] > CommandAsyncTask::HandleEndActionResult [within thread]: endAction for > action type 'CreateSnapshot' succeeded, clearing tasks. > 2019-10-16 21:38:45,340+03 INFO > [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] > (EE-ManagedThreadFactory-engine-Thread-1552) > [disks_syncAction_744a180c-eddd-4512] SPMAsyncTask::ClearAsyncTask: > Attempting to clear task 'e5a566e9-51c0-4df7-bf3f-982f1322ac34' > > 2019-10-16 21:38:48,516+03 INFO > [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-29) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotForVm' (id: > '054f142a-5100-4b68-9575-17a970cef1f4') waiting on child command id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' type:'CreateSnapshotDisk' to complete > 2019-10-16 21:38:48,517+03 INFO > [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-29) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' child commands > '[ab4f1edd-9f52-4480-af97-97f82a9586c6]' executions were completed, status > 'FAILED' > 2019-10-16 21:38:48,517+03 INFO > [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] > (EE-ManagedThreadFactory-engineScheduled-Thread-29) > [disks_syncAction_744a180c-eddd-4512] Command 'CreateSnapshotDisk' id: > '6097fcbd-008a-47cc-82ef-3918a1d1c7d7' Updating status to 'FAILED', The > command end method logic will be executed by one of its parent commands. > > > VDSM log: > > 2019-10-16 21:38:41,832+0300 ERROR (tasks/5) [storage.Volume] Requested > capacity 1073741824 < parent capacity 10737418240 (volume:1211) > > > 2019-10-16 21:38:41,833+0300 ERROR (tasks/5) [storage.TaskManager.Task] > (Task='e5a566e9-51c0-4df7-bf3f-982f1322ac34') 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 1940, in > createVolume > initial_size=initialSize) > File "/usr/lib/python2.7/site-packages/vdsm/storage/sd.py", line 930, in > createVolume > initial_size=initial_size) > File "/usr/lib/python2.7/site-packages/vdsm/storage/volume.py", line 1212, > in create > raise se.InvalidParameterException("capacity", capacity) > InvalidParameterException: Invalid parameter: 'capacity=1073741824' Same test failed again with these errors. Environment: ovirt-engine-4.3.7.1-0.1.el7.noarch vdsm-4.30.37-1.el7ev.x86_64 Vojtech, we see this issue multiple times ,do you have enough information to fix it? (Originally by Evelina Shames)
Created attachment 1639147 [details] TC6004 logs (Originally by Evelina Shames)
> Vojtech, we see this issue multiple times ,do you have enough information to > fix it? I haven't gone through logs you've attached yet, but as I explained in comment #14, the size in metadata has changed from 1GB to 3GB and logs don't give any hints why (unless I missed something there). To be able to fix it, I'd need a reproducer. I'll look more into it again and if don't find anything, I'll add more debug info into the code which writes metadata. (Originally by Vojtech Juranek)
*** Bug 1772853 has been marked as a duplicate of this bug. *** (Originally by Tal Nisan)
*** Bug 1788647 has been marked as a duplicate of this bug. *** (Originally by Marina Kalinin)
I went in detail through the logs from the first case and found something I missed before - metadata are not corrupted, but was changed by vdsm. vdsm's VolumeManifest.updateInvalidatedSize() checks and repairs metadata capacity when it's invalid. If there as some metadata can has wrong capacity due to previous bags (see e.g. BZ #1700623). This is how the metadata of the disk a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 was changed from 1GB to 3GB. What has happens is as follows: The disk was created on host09: vdsm.log.91:2019-09-30 19:26:28,731+0300 INFO (jsonrpc/6) [vdsm.api] START createVolume(sdUUID=u'90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID=u'3d5b32f3-3a06-4263-9b32-a4fa20853922', imgUUID=u'4a6f681b-7d99-4d70-8842-62d6cbabcf1d', size=u'1073741824', volFormat=5, preallocate=1, diskType=u'DATA', volUUID=u'a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', desc=u'{"DiskAlias":"disk_virtio_scsiraw_3019262787","DiskDescription":""}', srcImgUUID=u'00000000-0000-0000-0000-000000000000', srcVolUUID=u'00000000-0000-0000-0000-000000000000', initialSize=None) from=::ffff:10.46.16.250,56230, flow_id=disks_create_a5ae27cd-d9bd-47f6, task_id=a190a48b-d7b9-4480-9720-4f69e9c712e0 (api:48) LVM was created with size 1GB: vdsm.log.91:2019-09-30 19:26:29,433+0300 INFO (tasks/3) [storage.LVM] Creating LV (vg=90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1, lv=a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7, size=1024m, activate=True, contiguous=False, initialTags=('OVIRT_VOL_INITIALIZING',), device=None) (lvm:1285) and there isn't any log record that this LV or volume extended or reduced (using grep a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 *|grep "Extending LV", resp. grep a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 *|grep "Reducing LV"). Then VM with this disk was started on host10: Image was prepared there: 2019-09-30 19:26:53,680+0300 INFO (vm/7d3e4f40) [vdsm.api] START prepareImage(sdUUID='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID='3d5b32f3-3a06-4263-9b32-a4fa20853922', imgUUID='4a6f681b-7d99-4d70-8842-62d6cbabcf1d', leafUUID='a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', allowIllegal=False) from=internal, task_id=80dbe6f6-5d43-456f-931e-9f8ec9d4b330 (api:48) and during this process image metadata was changed to 3GB: 2019-09-30 19:26:54,456+0300 WARN (vm/7d3e4f40) [storage.VolumeManifest] Repairing wrong CAP for volume a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7 stored=1073741824 actual=3221225472 (volume:520) However, 3 GB was seem only by qemu, even after this change, OS still saw it as 1 GB (even on host10): 2019-09-30 19:39:46,557+0300 INFO (vm/7d3e4f40) [vdsm.api] START getVolumeSize(sdUUID='90cf7c8c-74b3-4fda-b780-5c4ad73e7ff1', spUUID='3d5b32f3-3a06-4263-9b32-a4fa20853922', imgUUID='4a6f681b-7d99-4d70-8842-62d6cbabcf1d', volUUID='a2885697-aaaa-4e0f-8f0d-0370cdd3c4f7', options=None) from=internal, task_id=07a555e4-6814-43a4-b35c-e3c89946bd8a (api:48) 2019-09-30 19:39:46,557+0300 INFO (vm/7d3e4f40) [vdsm.api] FINISH getVolumeSize return={'truesize': '1073741824', 'apparentsize': '1073741824'} from=internal, task_id=07a555e4-6814-43a4-b35c-e3c89946bd8a (api:54) Given that it was a RAW image, true size and apparent size should be same as capacity. Unless I missed again something important, from above info I'd conclude the this seems to be some issue in qemu-img info which returned wrong value, but further investigation is needed to confirm it. Avihai, could you please let me check on your environment this hypothesis once it happens again or at least try to run manually qemu-img info for affected image and check how big it's seen by LVM? I'll continue with checking other logs attached here, it any of them provide more info. (Originally by Vojtech Juranek)
might be solved by bug 1811391, we'll see, for now let's target 4.3.10 (Originally by michal.skrivanek)
Can we check this on latest 4.3.9, RHEL 7.8? (Originally by Lukas Svaty)
(In reply to Lukas Svaty from comment #45) > Can we check this on latest 4.3.9, RHEL 7.8? We are testing it currnetly, will post results once done. (Originally by Evelina Shames)
(In reply to Evelina Shames from comment #46) > (In reply to Lukas Svaty from comment #45) > > Can we check this on latest 4.3.9, RHEL 7.8? > > We are testing it currently, will post results once done. Couldn't reproduce the issue. (Originally by Evelina Shames)
(In reply to Roman Hodain from comment #50) > So yes it could. The VG extend size is 128MB so it was just rounded and the > engine did not expect that. yes, it's easy to reproduce by creating a raw disk on iscsi with <1G size and then trying to create a snapshot, but I'm not sure it's the same issue as in the original report (Originally by Benny Zlotnik)
Hi Roman, Can you please share the lvm version in the customer environment? The fix for bz 1811391 that was dependent on lvm fix bz 1809660 - should be included in lvm version - lvm2-2.02.186-7.el7_8.1. The issue might be related to it, can we please make sure that this version is found on the customer side? (Originally by Eyal Shenitzky)
(In reply to Eyal Shenitzky from comment #52) > Hi Roman, > > Can you please share the lvm version in the customer environment? > The fix for bz 1811391 that was dependent on lvm fix bz 1809660 - should be > included in lvm version - lvm2-2.02.186-7.el7_8.1. > > The issue might be related to it, can we please make sure that this version > is found on the customer side? No, they do not have this version. They run lvm2-2.02.185-2.el7_7.2.x86_64 The reason is that they tried to upgrade to 4.3.9 and the hypervisor started to fail on the storage subsystem. The tasks get stuck. Sanlock gets stuck and so on. It is currently under investigation. (Originally by Roman Hodain)
(In reply to RHV bug bot from comment #51) > (In reply to Roman Hodain from comment #50) > > So yes it could. The VG extend size is 128MB so it was just rounded and the > > engine did not expect that. > > yes, it's easy to reproduce by creating a raw disk on iscsi with <1G size > and then trying to create a snapshot, but I'm not sure it's the same issue > as in the original report > > (Originally by Benny Zlotnik) I need some clarifications on this bug to know how to proceed with this bug: 1) Do this simple reproduction and posted fixes actually fix all customer issues posted under links section? 2) Is the original issue reported by QE different than customer's issues? Can you elaborate on why this is the case? If indeed these are 2 different issues and we might consider verifying this bug with customers issues fix and open a new bug on QE seen the issue for further DEV investigation. But again we must be sure all customer issues are indeed fixed.
Hi all, Thank you for the work so far on the reported issue. In the meantime, I found the way to solve it, by implementing oVirt Ansible creates template steps. It could well be that I initially did not resize qcow image in a proper way, which ultimately led to this problem. What did I do to get to this problem: - download cloud build CentOS qcow image - using qcow-resize set the wanted image/disk size - upload the image to oVirt and create a VM which will ultimately serve as a template, with predefined disk size - Up to this point, the template can be used and I see no errors in the logs - export the template once created and import it to another cluster or another oVirt deployment - I think when export or import is done, all unused space of the image disk is cleared (sparsified) and once an imported template is used to create new VM, the mismatch in actual vs expected image/disk size is reported it was a while ago since I had this error so my apologies if it's not totally clear. Marko
(In reply to RHV bug bot from comment #51) > (In reply to Roman Hodain from comment #50) > > So yes it could. The VG extend size is 128MB so it was just rounded and the > > engine did not expect that. > > yes, it's easy to reproduce by creating a raw disk on iscsi with <1G size > and then trying to create a snapshot, but I'm not sure it's the same issue > as in the original report > > (Originally by Benny Zlotnik) Verified customer's issue with the above flow. As in our automation the issue doesn't reproduce - Moving to 'Verified'. Versions: rhv-4.3.10-5 ovirt-engine-4.3.10.3
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2020:2396