Bug 1507511
| Summary: | Start VM after commit snapshot with memory fails | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Raz Tamir <ratamir> | ||||
| Component: | BLL.Virt | Assignee: | Michal Skrivanek <michal.skrivanek> | ||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Raz Tamir <ratamir> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | high | ||||||
| Version: | 4.2.0 | CC: | bugs, tjelinek, tnisan | ||||
| Target Milestone: | ovirt-4.2.0 | Keywords: | Automation, Regression | ||||
| Target Release: | --- | Flags: | rule-engine:
ovirt-4.2+
rule-engine: 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: | 2017-12-20 11:09:51 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: |
|
||||||
Regression flag because https://bugzilla.redhat.com/show_bug.cgi?id=1461811 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. Verified on ovirt-engine-4.2.0-0.0.master.20171113223918.git25568c3.el7.centos VM started after committing snapshot with memory with no issues This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017. Since the problem described in this bug report should be resolved in oVirt 4.2.0 release, published on Dec 20th 2017, 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 1345408 [details] engine and vdsm logs Description of problem: When I commit a snapshot with memory and start the VM, I see error in, engine.log: 2017-10-30 15:10:35,359+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-5841) [d1d79da1-2344-4dbd-a905-19cf2bbd1254] EVENT_ID: USER_STARTED_VM( 153), VM test was started by admin@internal-authz (Host: host_mixed_1). 2017-10-30 15:10:38,567+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '5d6d82fe-6186-484f-813c-ff310cf0c653' was reported as Down on VDS '3ab7fd5d-e8c4-4b2f-ae7e- 029328d692da'(host_mixed_1) 2017-10-30 15:10:38,574+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-10) [] START, DestroyVDSCommand(HostName = host_mixed_1, DestroyVmVDSCommandParameters:{hostId=' 3ab7fd5d-e8c4-4b2f-ae7e-029328d692da', vmId='5d6d82fe-6186-484f-813c-ff310cf0c653', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='true'}), log id: 3a1a5f36 2017-10-30 15:10:41,297+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-10) [] Failed in 'DestroyVDS' method 2017-10-30 15:10:41,306+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-10) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command DestroyV DS failed: General Exception: ("VM '5d6d82fe-6186-484f-813c-ff310cf0c653' was not defined yet or was undefined",) 2017-10-30 15:10:41,306+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-10) [] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand' return value 'Statu sOnlyReturn [status=Status [code=100, message=General Exception: ("VM '5d6d82fe-6186-484f-813c-ff310cf0c653' was not defined yet or was undefined",)]]' 2017-10-30 15:10:41,306+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-10) [] HostName = host_mixed_1 2017-10-30 15:10:41,306+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-10) [] Command 'DestroyVDSCommand(HostName = host_mixed_1, DestroyVmVDSCommandParameters:{hostId ='3ab7fd5d-e8c4-4b2f-ae7e-029328d692da', vmId='5d6d82fe-6186-484f-813c-ff310cf0c653', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='true'})' execution failed: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = General Exception: ("VM '5d6d82fe-6186-484f-813c-ff310cf0c653' was not defined yet or was undefined",), code = 100 2017-10-30 15:10:41,306+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-10) [] FINISH, DestroyVDSCommand, log id: 3a1a5f36 2017-10-30 15:10:41,306+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '5d6d82fe-6186-484f-813c-ff310cf0c653'(test) moved from 'RestoringState' --> 'Down' 2017-10-30 15:10:41,329+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-10) [] EVENT_ID: VM_DOWN_ERROR(119), VM test is down with error. Exit message: Wake up from hibernation failed:cannot serialize None (type NoneType). 2017-10-30 15:10:41,330+02 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] add VM '5d6d82fe-6186-484f-813c-ff310cf0c653'(test) to rerun treatment 2017-10-30 15:10:41,337+02 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (ForkJoinPool-1-worker-10) [] Rerun VM '5d6d82fe-6186-484f-813c-ff310cf0c653'. Called from VDS 'host_mixed_1' 2017-10-30 15:10:41,361+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-5846) [] EVENT_ID: USER_INITIATED_RUN_VM_FAILED(151), Failed to run VM test on Host host_mixed_1. vdsm.log: 2017-10-30 15:10:38,483+0200 INFO (vm/5d6d82fe) [vds] prepared volume path: /rhev/data-center/mnt/blockSD/abb9fddc-fd26-47f7-b6b3-3daaaad6b0a6/images/510fbf29-8d52-4a55-8727-9ce7bdc79cbf/47745cb3-899f-42b8-98c1-77 87eed75146 (clientIF:439) 2017-10-30 15:10:38,500+0200 DEBUG (check/loop) [storage.check] START check '/dev/db0fdbd3-569c-4bee-a90f-3b240cf4ce2b/metadata' (delay=0.00) (check:283) 2017-10-30 15:10:38,543+0200 ERROR (vm/5d6d82fe) [virt.vm] (vmId='5d6d82fe-6186-484f-813c-ff310cf0c653') The vm start process failed (vm:898) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 827, in _startUnderlyingVm self._run() File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2635, in _run hooks.before_vm_start(self._buildDomainXML(), self._custom) File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2180, in _buildDomainXML self._process_devices() File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2120, in _process_devices deviceXML = vmxml.format_xml(dev_xml) File "/usr/lib/python2.7/site-packages/vdsm/virt/vmxml.py", line 65, in format_xml return etree.tostring(element, encoding='UTF-8') File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 1126, in tostring ElementTree(element).write(file, encoding, method=method) File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 820, in write serialize(write, self._root, encoding, qnames, namespaces) File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 939, in _serialize_xml _serialize_xml(write, e, encoding, qnames, None) File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 932, in _serialize_xml v = _escape_attrib(v, encoding) File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 1092, in _escape_attrib _raise_serialization_error(text) File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 1052, in _raise_serialization_error "cannot serialize %r (type %s)" % (text, type(text).__name__) TypeError: cannot serialize None (type NoneType) 2017-10-30 15:10:38,544+0200 INFO (vm/5d6d82fe) [virt.vm] (vmId='5d6d82fe-6186-484f-813c-ff310cf0c653') Changed state to Down: cannot serialize None (type NoneType) (code=1) (vm:1656) 2017-10-30 15:10:38,560+0200 INFO (vm/5d6d82fe) [virt.vm] (vmId='5d6d82fe-6186-484f-813c-ff310cf0c653') Stopping connection (guestagent:434) 2017-10-30 15:10:38,566+0200 DEBUG (check/loop) [storage.asyncevent] Process <cpopen.CPopen object at 0x30f5d90> terminated (count=1) (asyncevent:659) 2017-10-30 15:10:38,566+0200 DEBUG (check/loop) [storage.check] FINISH check '/dev/db0fdbd3-569c-4bee-a90f-3b240cf4ce2b/metadata' (rc=0, elapsed=0.07) (check:328) 2017-10-30 15:10:38,577+0200 INFO (jsonrpc/4) [api.virt] START destroy(gracefulAttempts=1) from=::ffff:10.35.161.127,52982 (api:46) 2017-10-30 15:10:38,578+0200 INFO (jsonrpc/4) [virt.vm] (vmId='5d6d82fe-6186-484f-813c-ff310cf0c653') Release VM resources (vm:4885) 2017-10-30 15:10:38,578+0200 WARN (jsonrpc/4) [virt.vm] (vmId='5d6d82fe-6186-484f-813c-ff310cf0c653') trying to set state to Powering down when already Down (vm:566) 2017-10-30 15:10:38,579+0200 INFO (jsonrpc/4) [virt.vm] (vmId='5d6d82fe-6186-484f-813c-ff310cf0c653') Stopping connection (guestagent:434) ... 2017-10-30 15:10:41,024+0200 INFO (vdsm.Scheduler) [Executor] Worker discarded: <Worker name=periodic/10 running <Task discardable <Operation action=<VmDispatcher operation=<class 'vdsm.virt.periodic.DriveWatermarkMonitor'> at 0x21edb10> at 0x21edb50> timeout=1.0, duration=1 at 0x2264050> discarded task#=161 at 0x2285d10> (executor:355) 2017-10-30 15:10:41,285+0200 INFO (jsonrpc/4) [root] /usr/libexec/vdsm/hooks/after_vm_destroy/50_vhostmd: rc=0 err= (hooks:109) 2017-10-30 15:10:41,288+0200 ERROR (jsonrpc/4) [api] FINISH destroy error=VM '5d6d82fe-6186-484f-813c-ff310cf0c653' was not defined yet or was undefined (api:127) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 117, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 312, in destroy res = self.vm.destroy(gracefulAttempts) File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4984, in destroy self._deleteVm() File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4973, in _deleteVm self._undefine_domain() File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2296, in _undefine_domain self._dom.undefine() File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 47, in __getattr__ % self.vmid) NotConnectedError: VM '5d6d82fe-6186-484f-813c-ff310cf0c653' was not defined yet or was undefined 2017-10-30 15:10:41,290+0200 INFO (jsonrpc/4) [api.virt] FINISH destroy return={'status': {'message': 'General Exception: ("VM \'5d6d82fe-6186-484f-813c-ff310cf0c653\' was not defined yet or was undefined",)', 'code': 100}} from=::ffff:10.35.161.127,52982 (api:52) 2017-10-30 15:10:41,291+0200 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call VM.destroy failed (error 100) in 2.71 seconds (__init__:630) 2017-10-30 15:10:41,292+0200 INFO (periodic/10) [Executor] Worker was discarded (executor:305) Version-Release number of selected component (if applicable): ovirt-engine-4.2.0-0.0.master.20171027213842.gitded437c.el7.centos How reproducible: 100% Steps to Reproduce: 1. Start VM after committing live snapshot 2. 3. Actual results: It will fail to start Expected results: Additional info: