Created attachment 1238875 [details] engine.log Description of problem: Clone VM from template failed. Version-Release number of selected component (if applicable): Engine: ovirt-engine-4.1.0-0.4.master.20170104181027.gitab0e3f4.el7.centos.noarch Host: OS Version:RHEL - 7.3 - 7.el7 Kernel Version:3.10.0 - 514.2.2.el7.x86_64 KVM Version:2.6.0 - 28.el7_3.2 LIBVIRT Version:libvirt-2.0.0-10.el7_3.2 VDSM Version: vdsm-4.19.1-18.git79e5ea5.el7.centos.x86_64 qemu-img-rhev: qemu-img-rhev-2.6.0-28.el7_3.2.x86_64 sanlock: sanlock-3.4.0-1.el7.x86_64 glusterfs: glusterfs-3.8.5-1.el7.x86_64 vdsm-cli: vdsm-cli-4.19.1-18.git79e5ea5.el7.centos.noarch Additional info: art log: 2017-01-05 23:27:32,604 - MainThread - art.logging - INFO - SETUP <TestCaseFunction 'test_clone_vm_template_case'> REST request: 2017-01-05 23:28:33,334 - MainThread - vms - DEBUG - CREATE request content is -- url:https://jenkins-vm-13.qa.lab.tlv.redhat.com/ovirt-engine/api/vms;clone=true body:<vm> <name>tested_vm_clone_vm</name> <cluster href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a" id="bd5c13da-0d4c-49d7-9a11-ca82e0456f6a"> <actions> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/resetemulatedmachine" rel="resetemulatedmachine"/> </actions> <name>golden_env_mixed_1</name> <description></description> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/affinitygroups" rel="affinitygroups"/> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/cpuprofiles" rel="cpuprofiles"/> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/permissions" rel="permissions"/> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/networkfilters" rel="networkfilters"/> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/networks" rel="networks"/> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/glustervolumes" rel="glustervolumes"/> <link href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a/glusterhooks" rel="glusterhooks"/> <ballooning_enabled>false</ballooning_enabled> <cpu> <architecture>x86_64</architecture> <type>Intel Conroe Family</type> </cpu> <custom_scheduling_policy_properties> <property> <name>HighUtilization</name> <value>80</value> </property> <property> <name>CpuOverCommitDurationMinutes</name> <value>2</value> </property> </custom_scheduling_policy_properties> <error_handling> <on_error>migrate</on_error> </error_handling> <fencing_policy> <enabled>true</enabled> <skip_if_connectivity_broken> <enabled>false</enabled> <threshold>50</threshold> </skip_if_connectivity_broken> <skip_if_gluster_bricks_up>false</skip_if_gluster_bricks_up> <skip_if_gluster_quorum_not_met>false</skip_if_gluster_quorum_not_met> <skip_if_sd_active> <enabled>false</enabled> </skip_if_sd_active> </fencing_policy> <gluster_service>false</gluster_service> <ha_reservation>false</ha_reservation> <ksm> <enabled>false</enabled> <merge_across_nodes>true</merge_across_nodes> </ksm> <maintenance_reason_required>false</maintenance_reason_required> <memory_policy> <over_commit> <percent>200</percent> </over_commit> <transparent_hugepages> <enabled>true</enabled> </transparent_hugepages> </memory_policy> <migration> <auto_converge>inherit</auto_converge> <bandwidth> <assignment_method>auto</assignment_method> </bandwidth> <compressed>inherit</compressed> </migration> <optional_reason>false</optional_reason> <required_rng_sources> <required_rng_source>urandom</required_rng_source> </required_rng_sources> <switch_type>legacy</switch_type> <threads_as_cores>false</threads_as_cores> <trusted_service>false</trusted_service> <tunnel_migration>false</tunnel_migration> <version> <major>4</major> <minor>1</minor> </version> <virt_service>true</virt_service> <data_center href="/ovirt-engine/api/datacenters/ce35d08f-9ca7-4bfb-8788-a5db39bfb041" id="ce35d08f-9ca7-4bfb-8788-a5db39bfb041"/> <mac_pool href="/ovirt-engine/api/macpools/586e003a-03e9-00b8-0339-000000000244" id="586e003a-03e9-00b8-0339-000000000244"/> <scheduling_policy href="/ovirt-engine/api/schedulingpolicies/b4ed2332-a7ac-4d5f-9596-99a439cb2812" id="b4ed2332-a7ac-4d5f-9596-99a439cb2812"/> </cluster> <disk_attachments> <disk_attachment> <bootable>true</bootable> <interface>virtio</interface> <disk id="c57181d6-b3e2-4053-9de1-5d3be9ce8869"> <storage_domains> <storage_domain href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec" id="094a33f4-a9ff-46b9-a247-75cfae9b91ec"> <actions> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/isattached" rel="isattached"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/updateovfstore" rel="updateovfstore"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/reduceluns" rel="reduceluns"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/refreshluns" rel="refreshluns"/> </actions> <name>fcp_0</name> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/diskprofiles" rel="diskprofiles"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/disks" rel="disks"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/storageconnections" rel="storageconnections"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/permissions" rel="permissions"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/templates" rel="templates"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/vms" rel="vms"/> <link href="/ovirt-engine/api/storagedomains/094a33f4-a9ff-46b9-a247-75cfae9b91ec/disksnapshots" rel="disksnapshots"/> <available>90194313216</available> <committed>30064771072</committed> <critical_space_action_blocker>5</critical_space_action_blocker> <discard_after_delete>false</discard_after_delete> <external_status>ok</external_status> <master>true</master> <storage> <type>fcp</type> <volume_group id="2QfhAs-Ay1D-io5a-moeT-u9cm-nko5-NAaflP"> <logical_units> <logical_unit id="3600a09803830347a625d467a79745665"> <discard_max_size>0</discard_max_size> <discard_zeroes_data>false</discard_zeroes_data> <lun_mapping>4</lun_mapping> <paths>0</paths> <product_id>LUN C-Mode</product_id> <serial>SNETAPP_LUN_C-Mode_804zb_FzytVe</serial> <size>107374182400</size> <storage_domain_id>094a33f4-a9ff-46b9-a247-75cfae9b91ec</storage_domain_id> <vendor_id>NETAPP</vendor_id> <volume_group_id>2QfhAs-Ay1D-io5a-moeT-u9cm-nko5-NAaflP</volume_group_id> </logical_unit> </logical_units> </volume_group> </storage> <storage_format>v4</storage_format> <supports_discard>false</supports_discard> <supports_discard_zeroes_data>false</supports_discard_zeroes_data> <type>data</type> <used>16106127360</used> <warning_low_space_indicator>10</warning_low_space_indicator> <wipe_after_delete>false</wipe_after_delete> <data_centers> <data_center id="ce35d08f-9ca7-4bfb-8788-a5db39bfb041"/> </data_centers> </storage_domain> </storage_domains> </disk> </disk_attachment> </disk_attachments> <template href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451" id="8fd71887-c1bf-4358-9372-00c1b6a80451"> <actions> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/seal" rel="seal"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/export" rel="export"/> </actions> <name>virt_base_template</name> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/permissions" rel="permissions"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/tags" rel="tags"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/diskattachments" rel="diskattachments"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/graphicsconsoles" rel="graphicsconsoles"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/cdroms" rel="cdroms"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/nics" rel="nics"/> <link href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451/watchdogs" rel="watchdogs"/> <bios> <boot_menu> <enabled>false</enabled> </boot_menu> </bios> <cpu> <architecture>x86_64</architecture> <topology> <cores>1</cores> <sockets>1</sockets> <threads>1</threads> </topology> </cpu> <cpu_shares>0</cpu_shares> <creation_time>2017-01-05T23:27:45.791000+02:00</creation_time> <delete_protected>false</delete_protected> <display> <allow_override>false</allow_override> <copy_paste_enabled>true</copy_paste_enabled> <disconnect_action>LOCK_SCREEN</disconnect_action> <file_transfer_enabled>true</file_transfer_enabled> <monitors>1</monitors> <single_qxl_pci>false</single_qxl_pci> <smartcard_enabled>false</smartcard_enabled> <type>spice</type> </display> <high_availability> <enabled>false</enabled> <priority>0</priority> </high_availability> <io> <threads>0</threads> </io> <large_icon href="/ovirt-engine/api/icons/ac3c2f0e-c463-46b1-bd98-3446d2b692f1" id="ac3c2f0e-c463-46b1-bd98-3446d2b692f1"/> <memory>1073741824</memory> <memory_policy> <guaranteed>1073741824</guaranteed> <max>4294967296</max> </memory_policy> <migration> <auto_converge>inherit</auto_converge> <compressed>inherit</compressed> </migration> <migration_downtime>-1</migration_downtime> <origin>ovirt</origin> <os> <boot> <devices> <device>hd</device> </devices> </boot> <type>rhel_6x64</type> </os> <small_icon href="/ovirt-engine/api/icons/2f57c59c-b823-4d84-96b4-b0fbb2679fa0" id="2f57c59c-b823-4d84-96b4-b0fbb2679fa0"/> <sso> <methods> <method id="guest_agent"/> </methods> </sso> <start_paused>false</start_paused> <stateless>false</stateless> <time_zone> <name>Etc/GMT</name> </time_zone> <type>desktop</type> <usb> <enabled>false</enabled> </usb> <cluster href="/ovirt-engine/api/clusters/bd5c13da-0d4c-49d7-9a11-ca82e0456f6a" id="bd5c13da-0d4c-49d7-9a11-ca82e0456f6a"/> <cpu_profile href="/ovirt-engine/api/cpuprofiles/9e124b0c-7fbf-4aa7-9fb0-76af15cb6ed6" id="9e124b0c-7fbf-4aa7-9fb0-76af15cb6ed6"/> <quota id="28860500-0a3a-4326-be19-ca6441e28425"/> <status>ok</status> <version> <version_name>base version</version_name> <version_number>1</version_number> <base_template href="/ovirt-engine/api/templates/8fd71887-c1bf-4358-9372-00c1b6a80451" id="8fd71887-c1bf-4358-9372-00c1b6a80451"/> </version> </template> </vm> engine log: 2017-01-05 23:28:32,473+02 INFO [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (default task-16) [vms_create_24192412-ac61-4804] Lock Acquired to object 'EngineLock:{exclusiveLocks='[tested_vm_clone_vm=<VM_NAME, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='[8fd71887-c1bf-4358-9372-00c1b6a80451=<TEMPLATE, ACTION_TYPE_FAILED_TEMPLATE_IS_USED_FOR_CREATE_VM$VmName tested_vm_clone_vm>, c57181d6-b3e2-4053-9de1-5d3be9ce8869=<DISK, ACTION_TYPE_FAILED_DISK_IS_USED_FOR_CREATE_VM$VmName tested_vm_clone_vm>]'}' 2017-01-05 23:28:32,563+02 INFO [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (default task-16) [vms_create_24192412-ac61-4804] Running command: AddVmFromTemplateCommand internal: false. Entities affected : ID: bd5c13da-0d4c-49d7-9a11-ca82e0456f6a Type: ClusterAction group CREATE_VM with role type USER, ID: 8fd71887-c1bf-4358-9372-00c1b6a80451 Type: VmTemplateAction group CREATE_VM with role type USER, ID: 094a33f4-a9ff-46b9-a247-75cfae9b91ec Type: StorageAction group CREATE_DISK with role type USER 2017-01-05 23:28:32,622+02 INFO [org.ovirt.engine.core.bll.AddRngDeviceCommand] (default task-16) [65223419] Running command: AddRngDeviceCommand internal: true. Entities affected : ID: c18bc863-2d00-4ac3-889a-fce19f4c6e79 Type: VMAction group EDIT_VM_PROPERTIES with role type USER 2017-01-05 23:28:32,628+02 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-16) [65223419] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{runAsync='true', vmId='c18bc863-2d00-4ac3-889a-fce19f4c6e79', status='ImageLocked', exitStatus='Normal'}), log id: 63150c4d 2017-01-05 23:28:32,632+02 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-16) [65223419] FINISH, SetVmStatusVDSCommand, log id: 63150c4d 2017-01-05 23:28:32,664+02 INFO [org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand] (default task-16) [1dafb449] Running command: CreateCloneOfTemplateCommand internal: true. Entities affected : ID: 094a33f4-a9ff-46b9-a247-75cfae9b91ec Type: Storage 2017-01-05 23:28:32,704+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (default task-16) [70dd286] Running command: CopyImageGroupWithDataCommand internal: true. 2017-01-05 23:28:32,738+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (default task-16) [70dd286] START, GetVolumeInfoVDSCommand(HostName = host_mixed_2, GetVolumeInfoVDSCommandParameters:{runAsync='true', hostId='cce51c7e-9ca5-404a-bcc9-aa1a28efc423', storagePoolId='ce35d08f-9ca7-4bfb-8788-a5db39bfb041', storageDomainId='094a33f4-a9ff-46b9-a247-75cfae9b91ec', imageGroupId='c57181d6-b3e2-4053-9de1-5d3be9ce8869', imageId='92886377-d3e3-42bc-819b-86c76db3b1d4'}), log id: e09c556 2017-01-05 23:28:33,416+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (default task-16) [70dd286] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@40072cb3, log id: e09c556 2017-01-05 23:28:33,460+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (default task-16) [2f7bba02] Running command: CreateVolumeContainerCommand internal: true. 2017-01-05 23:28:33,482+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (default task-16) [2f7bba02] START, CreateSnapshotVDSCommand( CreateSnapshotVDSCommandParameters:{runAsync='true', storagePoolId='ce35d08f-9ca7-4bfb-8788-a5db39bfb041', ignoreFailoverLimit='false', storageDomainId='094a33f4-a9ff-46b9-a247-75cfae9b91ec', imageGroupId='d78ef841-e189-4f6b-b73d-46467c0cdaf6', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='a980aa98-b19c-41b6-9a59-1cdb6eb9a01a', newImageDescription='null', imageInitialSizeInBytes='1073741825', imageId='00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000'}), log id: 5c6e7d87 2017-01-05 23:28:33,483+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (default task-16) [2f7bba02] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID 2017-01-05 23:28:34,351+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (default task-16) [2f7bba02] FINISH, CreateSnapshotVDSCommand, return: a980aa98-b19c-41b6-9a59-1cdb6eb9a01a, log id: 5c6e7d87 2017-01-05 23:28:34,357+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-16) [2f7bba02] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'ba1addb1-c760-43e4-8737-4847aad6e3a9' 2017-01-05 23:28:34,357+02 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-16) [2f7bba02] CommandMultiAsyncTasks::attachTask: Attaching task '4428b760-3a18-4757-8d30-3279437d4d9a' to command 'ba1addb1-c760-43e4-8737-4847aad6e3a9'. 2017-01-05 23:28:34,376+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-16) [2f7bba02] Adding task '4428b760-3a18-4757-8d30-3279437d4d9a' (Parent Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2017-01-05 23:28:34,386+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-16) [2f7bba02] BaseAsyncTask::startPollingTask: Starting to poll task '4428b760-3a18-4757-8d30-3279437d4d9a'. 2017-01-05 23:28:34,536+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-16) [2f7bba02] Correlation ID: vms_create_24192412-ac61-4804, Job ID: 29d333b6-6945-4b71-a06d-0cf4d1e38e23, Call Stack: null, Custom Event ID: -1, Message: VM tested_vm_clone_vm creation was initiated by admin@internal-authz. 2017-01-05 23:28:35,359+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [70dd286] Command 'CreateCloneOfTemplate' (id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39') waiting on child command id: '1befb680-66f5-4fe3-99c3-1c288c22220b' type:'CopyImageGroupWithData' to complete 2017-01-05 23:28:35,378+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [1dafb449] Command 'AddVmFromTemplate' (id: '07efe6e1-1b3a-443b-8209-b13bfddc4826') waiting on child command id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39' type:'CreateCloneOfTemplate' to complete 2017-01-05 23:28:35,382+02 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [2f7bba02] Command 'CopyImageGroupWithData' (id: '1befb680-66f5-4fe3-99c3-1c288c22220b') waiting on child command id: 'ba1addb1-c760-43e4-8737-4847aad6e3a9' type:'CreateVolumeContainer' to complete 2017-01-05 23:28:39,389+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler9) [70dd286] Command 'CreateCloneOfTemplate' (id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39') waiting on child command id: '1befb680-66f5-4fe3-99c3-1c288c22220b' type:'CopyImageGroupWithData' to complete 2017-01-05 23:28:39,406+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler9) [1dafb449] Command 'AddVmFromTemplate' (id: '07efe6e1-1b3a-443b-8209-b13bfddc4826') waiting on child command id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39' type:'CreateCloneOfTemplate' to complete 2017-01-05 23:28:39,410+02 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler9) [2f7bba02] Command 'CopyImageGroupWithData' (id: '1befb680-66f5-4fe3-99c3-1c288c22220b') waiting on child command id: 'ba1addb1-c760-43e4-8737-4847aad6e3a9' type:'CreateVolumeContainer' to complete 2017-01-05 23:28:41,952+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler8) [] Setting new tasks map. The map contains now 3 tasks 2017-01-05 23:28:42,250+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler2) [51f9fedc] Polling and updating Async Tasks: 3 tasks, 1 tasks to poll now 2017-01-05 23:28:43,258+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler2) [51f9fedc] Failed in 'HSMGetAllTasksStatusesVDS' method 2017-01-05 23:28:43,264+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler2) [51f9fedc] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VDSM host_mixed_3 command failed: Error creating a new volume 2017-01-05 23:28:43,264+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler2) [51f9fedc] SPMAsyncTask::PollTask: Polling task '4428b760-3a18-4757-8d30-3279437d4d9a' (Parent Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2017-01-05 23:28:43,279+02 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler2) [51f9fedc] BaseAsyncTask::logEndTaskFailure: Task '4428b760-3a18-4757-8d30-3279437d4d9a' (Parent Command 'CreateVolumeContainer', 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, code = 205', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Error creating a new volume, code = 205' 2017-01-05 23:28:43,280+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler2) [51f9fedc] CommandAsyncTask::endActionIfNecessary: All tasks of command 'ba1addb1-c760-43e4-8737-4847aad6e3a9' has ended -> executing 'endAction' 2017-01-05 23:28:43,280+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler2) [51f9fedc] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'ba1addb1-c760-43e4-8737-4847aad6e3a9'): calling endAction '. 2017-01-05 23:28:43,281+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-31) [51f9fedc] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'CreateVolumeContainer', 2017-01-05 23:28:43,286+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand' with failure. 2017-01-05 23:28:43,293+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateVolumeContainer' completed, handling the result. 2017-01-05 23:28:43,293+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateVolumeContainer' succeeded, clearing tasks. 2017-01-05 23:28:43,293+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '4428b760-3a18-4757-8d30-3279437d4d9a' 2017-01-05 23:28:43,294+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='ce35d08f-9ca7-4bfb-8788-a5db39bfb041', ignoreFailoverLimit='false', taskId='4428b760-3a18-4757-8d30-3279437d4d9a'}), log id: 206399ee 2017-01-05 23:28:45,524+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] START, HSMClearTaskVDSCommand(HostName = host_mixed_3, HSMTaskGuidBaseVDSCommandParameters:{runAsync='true', hostId='a1a6c3c4-3c42-41dd-95f7-81b3e45aa342', taskId='4428b760-3a18-4757-8d30-3279437d4d9a'}), log id: 19b1486 2017-01-05 23:28:46,534+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] FINISH, HSMClearTaskVDSCommand, log id: 19b1486 2017-01-05 23:28:46,534+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] FINISH, SPMClearTaskVDSCommand, log id: 206399ee 2017-01-05 23:28:46,538+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] BaseAsyncTask::removeTaskFromDB: Removed task '4428b760-3a18-4757-8d30-3279437d4d9a' from DataBase 2017-01-05 23:28:46,538+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-6-thread-31) [2f7bba02] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'ba1addb1-c760-43e4-8737-4847aad6e3a9' 2017-01-05 23:28:47,420+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [70dd286] Command 'CreateCloneOfTemplate' (id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39') waiting on child command id: '1befb680-66f5-4fe3-99c3-1c288c22220b' type:'CopyImageGroupWithData' to complete 2017-01-05 23:28:47,435+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [1dafb449] Command 'AddVmFromTemplate' (id: '07efe6e1-1b3a-443b-8209-b13bfddc4826') waiting on child command id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39' type:'CreateCloneOfTemplate' to complete 2017-01-05 23:28:47,439+02 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [2f7bba02] Command 'CopyImageGroupWithData' id: '1befb680-66f5-4fe3-99c3-1c288c22220b' child commands '[ba1addb1-c760-43e4-8737-4847aad6e3a9]' executions were completed, status 'FAILED' 2017-01-05 23:28:48,450+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (DefaultQuartzScheduler2) [2f7bba02] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand' with failure. 2017-01-05 23:28:49,487+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [70dd286] Command 'CreateCloneOfTemplate' id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39' child commands '[1befb680-66f5-4fe3-99c3-1c288c22220b]' executions were completed, status 'FAILED' 2017-01-05 23:28:49,487+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler1) [70dd286] Command 'CreateCloneOfTemplate' id: 'e0bf579b-fc12-4e0d-806e-e099ba260e39' Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands. 2017-01-05 23:28:50,518+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler4) [1dafb449] Command 'AddVmFromTemplate' id: '07efe6e1-1b3a-443b-8209-b13bfddc4826' child commands '[e0bf579b-fc12-4e0d-806e-e099ba260e39]' executions were completed, status 'FAILED' 2017-01-05 23:28:51,542+02 ERROR [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (DefaultQuartzScheduler1) [1dafb449] Ending command 'org.ovirt.engine.core.bll.AddVmFromTemplateCommand' with failure. 2017-01-05 23:28:51,549+02 ERROR [org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand] (DefaultQuartzScheduler1) [70dd286] Ending command 'org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand' with failure. 2017-01-05 23:28:51,628+02 INFO [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (DefaultQuartzScheduler1) [] Lock freed to object 'EngineLock:{exclusiveLocks='[tested_vm_clone_vm=<VM_NAME, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='[8fd71887-c1bf-4358-9372-00c1b6a80451=<TEMPLATE, ACTION_TYPE_FAILED_TEMPLATE_IS_USED_FOR_CREATE_VM$VmName tested_vm_clone_vm>, c57181d6-b3e2-4053-9de1-5d3be9ce8869=<DISK, ACTION_TYPE_FAILED_DISK_IS_USED_FOR_CREATE_VM$VmName tested_vm_clone_vm>]'}' 2017-01-05 23:28:51,637+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [] Correlation ID: vms_create_24192412-ac61-4804, Job ID: 29d333b6-6945-4b71-a06d-0cf4d1e38e23, Call Stack: null, Custom Event ID: -1, Message: Failed to complete VM tested_vm_clone_vm creation. 2017-01-05 23:28:56,147+02 INFO [org.ovirt.engine.core.bll.RemoveVmCommand] (default task-16) [vms_delete_59a9fcd7-b3fe-47b2] Lock Acquired to object 'EngineLock:{exclusiveLocks='[ae7533c8-cdb4-499a-8ba0-10bd314894fd=<VM, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}' 2017-01-05 23:28:56,190+02 INFO [org.ovirt.engine.core.bll.RemoveVmCommand] (default task-16) [vms_delete_59a9fcd7-b3fe-47b2] Running command: RemoveVmCommand internal: false. Entities affected : ID: ae7533c8-cdb4-499a-8ba0-10bd314894fd Type: VMAction group DELETE_VM with role type USER 2017-01-05 23:28:56,192+02 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-16) [vms_delete_59a9fcd7-b3fe-47b2] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{runAsync='true', vmId='ae7533c8-cdb4-499a-8ba0-10bd314894fd', status='ImageLocked', exitStatus='Normal'}), log id: 1b7ee8dd 2017-01-05 23:28:56,195+02 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-16) [vms_delete_59a9fcd7-b3fe-47b2] FINISH, SetVmStatusVDSCommand, log id: 1b7ee8dd 2017-01-05 23:28:56,196+02 INFO [org.ovirt.engine.core.bll.RemoveVmCommand] (default task-16) [vms_delete_59a9fcd7-b3fe-47b2] Lock freed to object 'EngineLock:{exclusiveLocks='[ae7533c8-cdb4-499a-8ba0-10bd314894fd=<VM, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}' 2017-01-05 23:28:56,217+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveAllVmImagesCommand] (default task-16) [65e6902] Running command: RemoveAllVmImagesCommand internal: true. Entities affected : ID: ae7533c8-cdb4-499a-8ba0-10bd314894fd Type: VM 2017-01-05 23:28:56,222+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (default task-16) [589fa86] Running command: RemoveImageCommand internal: true. Entities affected : ID: 00000000-0000-0000-0000-000000000000 Type: Storage 2017-01-05 23:28:56,271+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (default task-16) [589fa86] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{runAsync='true', storagePoolId='ce35d08f-9ca7-4bfb-8788-a5db39bfb041', ignoreFailoverLimit='false', storageDomainId='094a33f4-a9ff-46b9-a247-75cfae9b91ec', imageGroupId='4f4cd990-e792-4102-b9a9-2236ede15ee7', postZeros='false', discard='false', forceDelete='false'}), log id: 7e2a04d9 vdsm log: 2017-01-05 23:28:34,603 INFO (tasks/9) [storage.Volume] Creating volume a980aa98-b19c-41b6-9a59-1cdb6eb9a01a (volume:1023) 2017-01-05 23:28:34,628 ERROR (tasks/9) [storage.Volume] The volume size 2097152 is smaller than the requested initial size 2097153 (blockVolume:344) 2017-01-05 23:28:34,628 ERROR (tasks/9) [storage.Volume] Failed to create volume /rhev/data-center/ce35d08f-9ca7-4bfb-8788-a5db39bfb041/094a33f4-a9ff-46b9-a247-75cfae9b91ec/images/d78ef841-e189-4f6b-b73d-46467c0cdaf6/a980aa98-b19c-41b6-9a59-1cdb6eb9a01a: Invalid parameter: 'initial size=2097153' (volume:1047) 2017-01-05 23:28:34,629 ERROR (tasks/9) [storage.Volume] Unexpected error (volume:1087) Traceback (most recent call last): File "/usr/share/vdsm/storage/volume.py", line 1044, in create initialSize=initialSize) File "/usr/share/vdsm/storage/blockVolume.py", line 461, in _create size, initialSize) File "/usr/share/vdsm/storage/blockVolume.py", line 503, in calculate_volume_alloc_size preallocate, capacity, initial_size) File "/usr/share/vdsm/storage/blockVolume.py", line 346, in calculate_volume_alloc_size initial_size) InvalidParameterException: Invalid parameter: 'initial size=2097153' 2017-01-05 23:28:34,630 ERROR (tasks/9) [storage.TaskManager.Task] (Task='4428b760-3a18-4757-8d30-3279437d4d9a') Unexpected error (task:870) Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 877, in _run return fn(*args, **kargs) File "/usr/share/vdsm/storage/task.py", line 333, 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/share/vdsm/storage/sp.py", line 1921, in createVolume initialSize=initialSize) File "/usr/share/vdsm/storage/sd.py", line 762, in createVolume initialSize=initialSize) File "/usr/share/vdsm/storage/volume.py", line 1089, in create (volUUID, e)) VolumeCreationError: Error creating a new volume: ("Volume creation a980aa98-b19c-41b6-9a59-1cdb6eb9a01a failed: Invalid parameter: 'initial size=2097153'",) 2017-01-05 23:28:34,670 INFO (tasks/9) [storage.Volume] startCreateVolumeRollback: sdUUID=094a33f4-a9ff-46b9-a247-75cfae9b91ec imgUUID=d78ef841-e189-4f6b-b73d-46467c0cdaf6 volUUID=a980aa98-b19c-41b6-9a59-1cdb6eb9a01a (volume:933) 2017-01-05 23:28:34,670 INFO (tasks/9) [storage.Image] createImageRollback: imageDir=/rhev/data-center/ce35d08f-9ca7-4bfb-8788-a5db39bfb041/094a33f4-a9ff-46b9-a247-75cfae9b91ec/images/d78ef841-e189-4f6b-b73d-46467c0cdaf6 (image:119)
Created attachment 1238876 [details] vdsm.log
Created attachment 1238877 [details] art_test_log
Liron, What exactly the problem here? Cloning vm from template is working fine for me ovirt-engine-4.1.0-0.4.master.20170111000229.git9ce0636.el7.centos.noarch
Steps to reproduce: Have a 4.1 DC - 1. Create a new VM 2. Create a 1GB Sparse disk on a block domain 3. Attach the disk to the vm 4. Create template from the VM 5. Add a VM based on the template with the following chosen in the add dialog: *"Server" VM * Resource allocation - choose block domain as the target for the template disk, COW format.
(In reply to Raz Tamir from comment #3) > Liron, > What exactly the problem here? > Cloning vm from template is working fine for me > ovirt-engine-4.1.0-0.4.master.20170111000229.git9ce0636.el7.centos.noarch Raz, the failure is on a specific scenario - I've added steps to reproduce. Thanks, Liron
Thanks Liron
verified. Engine : ovirt-engine-4.1.0.1-0.4.master.20170118134729.gitf34da1f.el7.centos.noarch vdsm: 4.19.2-1