Bug 1544056
| Summary: | [PPC] Failed to start VM with snapshot with "MissingDevice()MissingDevice: Base class for vdsm errors" | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Raz Tamir <ratamir> | ||||||
| Component: | BLL.Virt | Assignee: | Arik <ahadas> | ||||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Israel Pinto <ipinto> | ||||||
| Severity: | urgent | Docs Contact: | |||||||
| Priority: | high | ||||||||
| Version: | 4.2.1 | CC: | ahadas, bugs, cshao, fromani, huzhao, jiaczhan, michal.skrivanek, qiyuan, ratamir, weiwang, yaniwang, ycui, yzhao | ||||||
| Target Milestone: | ovirt-4.2.2 | Keywords: | Automation, Regression | ||||||
| Target Release: | --- | Flags: | rule-engine:
ovirt-4.2+
ykaul: blocker+ |
||||||
| Hardware: | Unspecified | ||||||||
| OS: | Unspecified | ||||||||
| Whiteboard: | |||||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||||
| Doc Text: | Story Points: | --- | |||||||
| Clone Of: | Environment: | ||||||||
| Last Closed: | 2018-03-29 11:19:09 UTC | Type: | Bug | ||||||
| Regression: | --- | Mount Type: | --- | ||||||
| Documentation: | --- | CRM: | |||||||
| Verified Versions: | Category: | --- | |||||||
| oVirt Team: | Virt | RHEL 7.3 requirements from Atomic Host: | |||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||
| Embargoed: | |||||||||
| Attachments: |
|
||||||||
Created attachment 1394063 [details]
vm xml
Adding regression keyword as start VM with snapshot used to work in previous builds Vdsm raises this error if it can't match the metadata with the devices.
Vdsm can handle just fine if a device lack metadata, but it raises this error if it can distinguish clearly which metadata belongs to which device.
For disks, Vdsm matches the metadata using devtype='disk' name='$TARGET_DEVICE'
while $TARGET_DEVICE is the device which the guest OS will use to access the drive. This is the <target> subelement of the domain XML.
Looking at the provided XML, the devices section doesn't look right:
<disk snapshot="no" type="file">
<target/>
<source file="/rhev/data-center/336e1701-ad96-4ab8-9d62-ab725c8e2018/24408724-86a7-436d-9fbc-e27e16b56ce8/images/6dbd26d9-9346-4b0f-8e8d-3639f6262ab8/774f68d9-67e2-4814-b4df-23e666bed4f7"/>
<driver name="qemu" io="threads" type="qcow2" error_policy="stop" cache="none"/>
<address bus="0" controller="0" unit="3" type="drive" target="0"/>
<serial>6dbd26d9-9346-4b0f-8e8d-3639f6262ab8</serial>
</disk>
<disk snapshot="no" type="file">
<target/>
<source file="/rhev/data-center/336e1701-ad96-4ab8-9d62-ab725c8e2018/24408724-86a7-436d-9fbc-e27e16b56ce8/images/0170a332-485a-4291-9051-d7f3b65089d6/bb40f5e4-8cd2-4ee3-b801-1f21bc860e89"/>
<driver name="qemu" io="threads" type="qcow2" error_policy="stop" cache="none"/>
<address bus="0" controller="0" unit="4" type="drive" target="0"/>
<serial>0170a332-485a-4291-9051-d7f3b65089d6</serial>
</disk>
the <target> element is empty, this causes the ambiguity in the mapping between metadata and disks.
Looking at UUIDs, it seems that the missing drives are 'sda' and 'sdb'.
Arik, any idea why we lack the 'target' elements here?
(In reply to Francesco Romani from comment #3) > Arik, any idea why we lack the 'target' elements here? Yes, that's a gap in the generation of engine XML [1] [1] https://github.com/oVirt/ovirt-engine/blob/master/backend/manager/modules/vdsbroker/src/main/java/org/ovirt/engine/core/vdsbroker/builder/vminfo/LibvirtVmXmlBuilder.java#L1793 Thanks Arik. I don't think Vdsm should swallow this error ad let the VM run with less disk than allowed, so I suggest to move this bug to Engine. BTW, how could this have worked before with SCSI disks on PPC? (In reply to Francesco Romani from comment #5) > I don't think Vdsm should swallow this error ad let the VM run with less > disk than allowed, so I suggest to move this bug to Engine. Right, changed. > > BTW, how could this have worked before with SCSI disks on PPC? Before using engine XML? the engine used to send the disk device with iface=scsi also for SCSI disks on PPC and therefore VDSM generated <driver dev=".." bus="scsi"> (In reply to Arik from comment #6) > > BTW, how could this have worked before with SCSI disks on PPC? > > Before using engine XML? the engine used to send the disk device with > iface=scsi also for SCSI disks on PPC and therefore VDSM generated <driver > dev=".." bus="scsi"> OK, thanks for the explanation, makes sense. POST -> ASSIGNED, the attached Vdsm patch wants the improve the error message and will not fix this issue (In reply to Francesco Romani from comment #7) > POST -> ASSIGNED, the attached Vdsm patch wants the improve the error > message and will not fix this issue But mine is supposed to fix this (gerrit.ovirt.org/87457) :) Unfortunately, with no PPC host available, I have no way to properly verifying it. Raz, is it possible for you to run the failed automation you mentioned against the master branch once the fix is merged? needinfo is irrelevant anymore - merged to 4.2 branch (In reply to Arik from comment #9) > needinfo is irrelevant anymore - merged to 4.2 branch Sorry for late response Arik. Verify with: Engine: Software Version:4.2.2-0.1.el7 Host: OS Version:RHEL - 7.5 - 6.el7 Kernel Version:3.10.0 - 830.el7.ppc64le KVM Version:2.10.0 - 20.el7 LIBVIRT Version:libvirt-3.9.0-13.el7 VDSM Version:vdsm-4.20.18-1.el7ev Steps: 1. Create VM with disk 2. Create snapshot 3. Start the VM Results: VM is running with no errros This bugzilla is included in oVirt 4.2.2 release, published on March 28th 2018. Since the problem described in this bug report should be resolved in oVirt 4.2.2 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report. |
Created attachment 1394062 [details] engine and vdsm logs Description of problem: In our automation, when starting VM with snapshot will fail with: engine.log: 2018-02-06 23:47:32,663+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-8) [vms_syncAction_3640cf37-1324-4a7f] EVENT_ID: USER_STARTED_VM(153), VM vm_TestCase6052_0623415346 was started by admin@internal-authz (Host: host_mixed_2). 2018-02-06 23:47:32,825+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-13) [] VM '72703326-193b-4d6b-8e83-e2918c7af036' was reported as Down on VDS 'b09b6ef2-ec8b-42c7-a2df-f2580491024b'(host_mixed_2) 2018-02-06 23:47:32,827+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-13) [] START, DestroyVDSCommand(HostName = host_mixed_2, DestroyVmVDSCommandParameters:{hostId='b09b6ef2-ec8b-42c7-a2df-f2580491024b', vmId='72703326-193b-4d6b-8e83-e2918c7af036', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='true'}), log id: 409b4707 2018-02-06 23:47:34,114+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-13) [] FINISH, DestroyVDSCommand, log id: 409b4707 2018-02-06 23:47:34,114+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-13) [] VM '72703326-193b-4d6b-8e83-e2918c7af036'(vm_TestCase6052_0623415346) moved from 'WaitForLaunch' --> 'Down' 2018-02-06 23:47:34,124+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-13) [] EVENT_ID: VM_DOWN_ERROR(119), VM vm_TestCase6052_0623415346 is down with error. Exit message: Base class for vdsm errors. 2018-02-06 23:47:34,125+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-13) [] add VM '72703326-193b-4d6b-8e83-e2918c7af036'(vm_TestCase6052_0623415346) to rerun treatment 2018-02-06 23:47:34,129+02 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (ForkJoinPool-1-worker-13) [] Rerun VM '72703326-193b-4d6b-8e83-e2918c7af036'. Called from VDS 'host_mixed_2' 2018-02-06 23:47:34,143+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-3469) [] EVENT_ID: USER_INITIATED_RUN_VM_FAILED(151), Failed to run VM vm_TestCase6052_0623415346 on Host host_mixed_2. vdsm.log: 2018-02-06 23:47:32,577+0200 ERROR (vm/72703326) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') The vm start process failed (vm:927) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 856, in _startUnderlyingVm self._run() File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2661, in _run self._devices = self._make_devices() File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2598, in _make_devices self.id, self.domain, self._md_desc, self.log File "/usr/lib/python2.7/site-packages/vdsm/virt/vmdevices/common.py", line 224, in dev_map_from_domain_xml dev_class, dev_elem) File "/usr/lib/python2.7/site-packages/vdsm/virt/vmdevices/common.py", line 403, in _get_metadata_from_elem_xml with md_desc.device(**attrs) as dev_data: File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__ return self.gen.next() File "/usr/lib/python2.7/site-packages/vdsm/virt/metadata.py", line 533, in device dev_data = self._find_device(kwargs) File "/usr/lib/python2.7/site-packages/vdsm/virt/metadata.py", line 664, in _find_device raise MissingDevice()MissingDevice: Base class for vdsm errors 2018-02-06 23:47:32,577+0200 INFO (vm/72703326) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') Changed state to Down: Base class for vdsm errors (code=1) (vm:1646) 2018-02-06 23:47:32,583+0200 INFO (vm/72703326) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') Stopping connection (guestagent:438) 2018-02-06 23:47:32,912+0200 INFO (jsonrpc/2) [api.virt] START destroy(gracefulAttempts=1) from=::ffff:10.35.69.81,44164 (api:46) 2018-02-06 23:47:32,913+0200 INFO (jsonrpc/2) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') Release VM resources (vm:5035) 2018-02-06 23:47:32,913+0200 WARN (jsonrpc/2) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') trying to set state to Powering down when already Down (vm:589) 2018-02-06 23:47:32,913+0200 INFO (jsonrpc/2) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') Stopping connection (guestagent:438) 2018-02-06 23:47:32,913+0200 INFO (jsonrpc/2) [virt.vm] (vmId='72703326-193b-4d6b-8e83-e2918c7af036') Stopping connection (guestagent:438) 2018-02-06 23:47:32,913+0200 WARN (jsonrpc/2) [root] File: /var/lib/libvirt/qemu/channels/72703326-193b-4d6b-8e83-e2918c7af036.ovirt-guest-agent.0 already removed (fileutils:51) 2018-02-06 23:47:32,914+0200 WARN (jsonrpc/2) [root] File: /var/lib/libvirt/qemu/channels/72703326-193b-4d6b-8e83-e2918c7af036.org.qemu.guest_agent.0 already removed (fileutils:51) 2018-02-06 23:47:32,914+0200 DEBUG (jsonrpc/2) [storage.TaskManager.Task] (Task='5980b2b1-b1ed-4f54-b32c-c71c3f1e4216') moving from state init -> state preparing (task:602) Version-Release number of selected component (if applicable): vdsm-4.20.17-1.el7ev.ppc64le ovirt-engine-4.2.1.6-0.1.el7 How reproducible: 100% Steps to Reproduce: 1. Create VM with disk (checked on iscsi and nfs) 2. Create snapshot 3. Start the VM Actual results: The VM will fail to start Expected results: VM should start with no issues Additional info: