Bug 1592187
| Summary: | Failed to stop vm with spice + vnc | ||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Virtualization Manager | Reporter: | Israel Pinto <ipinto> | ||||||||||||||
| Component: | ovirt-engine | Assignee: | Tomasz Barański <tbaransk> | ||||||||||||||
| Status: | CLOSED WORKSFORME | QA Contact: | Pedut <pchocron> | ||||||||||||||
| Severity: | high | Docs Contact: | |||||||||||||||
| Priority: | unspecified | ||||||||||||||||
| Version: | unspecified | CC: | fromani, ipinto, lsurette, mavital, michal.skrivanek, ratamir, rbarry, Rhev-m-bugs, srevivo, tbaransk | ||||||||||||||
| Target Milestone: | ovirt-4.3.0 | Keywords: | Automation, AutomationTriaged, Regression | ||||||||||||||
| Target Release: | --- | ||||||||||||||||
| Hardware: | Unspecified | ||||||||||||||||
| OS: | Unspecified | ||||||||||||||||
| Whiteboard: | |||||||||||||||||
| Fixed In Version: | vdsm-4.30.5 | Doc Type: | If docs needed, set a value | ||||||||||||||
| Doc Text: | Story Points: | --- | |||||||||||||||
| Clone Of: | Environment: | ||||||||||||||||
| Last Closed: | 2018-09-12 06:49:25 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 1452505 [details]
logs
Why is it filed as a RHV bug? sadly, we need debug level in vdsm log and/or logs from the ovirt-ga and system logs from the guest still, please improve logging in VmShudown/VmReboot classes, when we call anything in the guest it should be a INFO level message really as we rarely get any logs from guest and won't know when the call silently fails/succeeds but doesn't do anything really. Adding vdsm debug log:
2018-06-19 10:52:51,843+0300 ERROR (Thread-85) [root] Shutdown by QEMU Guest Agent failed (vm:5345)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5336, in qemuGuestAgentShutdown
self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)
File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98, in f
ret = attr(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line 130, in wrapper
ret = f(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 92, in wrapper
return func(inst, *args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2482, in shutdownFlags
if ret == -1: raise libvirtError ('virDomainShutdownFlags() failed', dom=self)
libvirtError: Guest agent is not responding: QEMU guest agent is not connected
2018-06-19 10:52:51,844+0300 DEBUG (Thread-85) [utils.Callback] Calling ovirtGuestAgentCallback with args=() and kwargs={} (utils:260)
and guest logs
Created attachment 1452835 [details]
vdsm_debug_level_log
Created attachment 1452836 [details]
guest_logs
happened also in other settings: like just VNC. Created attachment 1453644 [details]
vnc_case
vdsm log:
2018-06-21 22:21:39,703+0300 ERROR (Thread-2) [root] Shutdown by QEMU Guest Agent failed (vm:5345)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5336, in qemuGuestAgentShutdown
self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)
File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98, in f
ret = attr(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line 130, in wrapper
ret = f(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 92, in wrapper
return func(inst, *args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2482, in shutdownFlags
if ret == -1: raise libvirtError ('virDomainShutdownFlags() failed', dom=self)
libvirtError: Guest agent is not responding: QEMU guest agent is not connected
Created attachment 1453645 [details]
vnc_case_libvirt_qemu_logs
retoring needinfo in comment #4 (In reply to Israel Pinto from comment #5) and what's not working? I see it shut down at 10:55 2018-06-19 10:55:34,304+0300 INFO (libvirt/events) [virt.vm] (vmId='af86797e-aa1e-40be-9f8a-a9738f090433') underlying process disconnected (vm:1057) As i meation on comment 1, i happened in automation cases: see other time it happened, VM failed to shutdown. Engine log (Correlation-id: vms_syncAction_56190c01-1305-4260) 2018-06-15 21:34:37,888+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-25) [] EVENT_ID: USER_RUN_VM(32), VM virt_console_vm started on Host host_mixed_2 2018-06-15 21:34:47,569+03 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] Running command: ShutdownVmCommand internal: false. Entities affected : ID: 287206e4-5bcd-4586-b0eb-d02f0ac1ba44 Type: VMAction group SHUT_DOWN_VM with role type USER 2018-06-15 21:34:47,574+03 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] Entered (VM 'virt_console_vm'). 2018-06-15 21:34:47,575+03 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] Sending shutdown command for VM 'virt_console_vm'. 2018-06-15 21:34:47,578+03 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] START, DestroyVmVDSCommand( DestroyVmVDSCommandParameters:{hostId='7e9e7d5b-e176-4530-aa69-00edc4bb3d2e', vmId='287206e4-5bcd-4586-b0eb-d02f0ac1ba44', secondsToWait='30', gracefully='true', reason='', ignoreNoVm='false'}), log id: 3654de9c 2018-06-15 21:34:47,582+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] START, DestroyVDSCommand(HostName = host_mixed_2, DestroyVmVDSCommandParameters:{hostId='7e9e7d5b-e176-4530-aa69-00edc4bb3d2e', vmId='287206e4-5bcd-4586-b0eb-d02f0ac1ba44', secondsToWait='30', gracefully='true', reason='', ignoreNoVm='false'}), log id: 64265528 2018-06-15 21:34:47,588+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] FINISH, DestroyVDSCommand, log id: 64265528 2018-06-15 21:34:47,592+03 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] FINISH, DestroyVmVDSCommand, return: PoweringDown, log id: 3654de9c 2018-06-15 21:34:47,624+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-63) [vms_syncAction_56190c01-1305-4260] EVENT_ID: USER_INITIATED_SHUTDOWN_VM(73), VM shutdown initiated by admin@internal-authz on VM virt_console_vm (Host: host_mixed_2). 2018-06-15 21:37:19,579+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2018-06-15 21:37:19,580+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 23 threads waiting for tasks and 0 tasks in queue. 2018-06-15 21:37:19,580+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engineScheduled' is using 0 threads out of 100, 100 threads waiting for tasks. 2018-06-15 21:37:19,580+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engineThreadMonitoring' is using 1 threads out of 1, 0 threads waiting for tasks. 2018-06-15 21:37:23,394+03 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [3a81c7ad] Lock Acquired to object 'EngineLock:{exclusiveLocks='[2f62de97-7785-4759-aa08-e8b5afdb629c=PROVIDER]', sharedLocks=''}' 2018-06-15 21:37:23,413+03 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [3a81c7ad] Running command: SyncNetworkProviderCommand internal: true. 2018-06-15 21:37:23,572+03 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-34) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2018-06-15 21:37:23,776+03 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [3a81c7ad] Lock freed to object 'EngineLock:{exclusiveLocks='[2f62de97-7785-4759-aa08-e8b5afdb629c=PROVIDER]', sharedLocks=''}' 2018-06-15 21:39:53,335+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '287206e4-5bcd-4586-b0eb-d02f0ac1ba44'(virt_console_vm) moved from 'PoweringDown' --> 'Up' 2018-06-15 21:39:53,364+03 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] EVENT_ID: VM_POWER_DOWN_FAILED(147), Shutdown of VM virt_console_vm failed. ^^^ --> VM is move to UP. VDSM log (flow_id=vms_syncAction_56190c01-1305-4260): 2018-06-15 21:34:47,583+0300 INFO (jsonrpc/6) [api.virt] START shutdown(delay='30', message='System Administrator has initiated shutdown of this Virtual Machine. Virtual Machine is shutting down.', reboot=False, timeout=None, force=False) from=::ffff:10.46.16.197,34594, flow_id=vms_syncAction_56190c01-1305-4260, vmId=287206e4-5bcd-4586-b0eb-d02f0ac1ba44 (api:46) 2018-06-15 21:34:47,584+0300 INFO (jsonrpc/6) [api.virt] FINISH shutdown return={'status': {'message': 'Machine shutting down', 'code': 0}} from=::ffff:10.46.16.197,34594, flow_id=vms_syncAction_56190c01-1305-4260, vmId=287206e4-5bcd-4586-b0eb-d02f0ac1ba44 (api:52) 2018-06-15 21:34:47,584+0300 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call VM.shutdown succeeded in 0.00 seconds (__init__:573) 2018-06-15 21:34:47,586+0300 ERROR (Thread-3) [root] Shutdown by QEMU Guest Agent failed (vm:5345) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5336, in qemuGuestAgentShutdown self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT) File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line 130, in wrapper ret = f(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 92, in wrapper return func(inst, *args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2482, in shutdownFlags if ret == -1: raise libvirtError ('virDomainShutdownFlags() failed', dom=self) libvirtError: Guest agent is not responding: QEMU guest agent is not connected Adding logs(with debug), about what you ask is was manually check to provide log of VDSM in debug. Created attachment 1456239 [details]
spice_and_vnc_case
restoring the needinfo in comment #4 again;) clearing NEEDINFO since the logs are added in patch https://gerrit.ovirt.org/#/c/92918/ Targeting since this is merged in master. @Israel I've added some more logs. Could you please rerun the tests and provide the new logs if the problem is still reproducible? I tried to reproduce the bug by: 1. Running the test in loop (with automation) - Failed to reproduce it 2 Manually: I stopped the ovirt-guest-engine and quemu-quest-agent and shutdown the VM from the Engine - I saw the libvirtError: Guest agent is not responding: QEMU guest agent is not connected as expected in this case but the VM stoped (failed to reproduce it). Therefore, I recommend to close this bug. In case the problem will happen again we will reopen this bug. |
Description of problem: Failed to stop VM with spice and VNC Version-Release number of selected component (if applicable): Engine: ovirt-engine-4.2.4.4-0.1.el7_3.noarch Host: Red Hat Enterprise Linux Server 7.5 (Maipo) kernel: 3.10.0-862.6.1.el7.x86_64 vdsm: vdsm-4.20.31-1.el7ev.x86_64 libvirt: libvirt-3.9.0-14.el7_5.6.x86_64 qemu-img-rhev: qemu-img-rhev-2.10.0-21.el7_5.4.x86_64 How reproducible: Once in the automation test. Steps to Reproduce: 1. Create template from exist VM 2. Create VM from this template(VM with guest agent and OS installed) 2. Enable SPICE and VNC 3. Start VM 4. Stop VM Actual results: VM failed to stop Manually did not reproduce. Additional info: vdsm log: 2018-06-15 21:34:47,583+0300 INFO (jsonrpc/6) [api.virt] START shutdown(delay='30', message='System Administrator has initiated shutdown of this Virtual Machine. Virtual Machine is shutting down.', reboot=False, timeout=None, force=False) from=::ffff:10.46.16.197,34594, flow_id=vms_syncAction_56190c01-1305-4260, vmId=287206e4-5bcd-4586-b0eb-d02f0ac1ba44 (api:46) 2018-06-15 21:34:47,584+0300 INFO (jsonrpc/6) [api.virt] FINISH shutdown return={'status': {'message': 'Machine shutting down', 'code': 0}} from=::ffff:10.46.16.197,34594, flow_id=vms_syncAction_56190c01-1305-4260, vmId=287206e4-5bcd-4586-b0eb-d02f0ac1ba44 (api:52) 2018-06-15 21:34:47,584+0300 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call VM.shutdown succeeded in 0.00 seconds (__init__:573) 2018-06-15 21:34:47,586+0300 ERROR (Thread-3) [root] Shutdown by QEMU Guest Agent failed (vm:5345) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5336, in qemuGuestAgentShutdown self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT) File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line 130, in wrapper ret = f(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 92, in wrapper return func(inst, *args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2482, in shutdownFlags if ret == -1: raise libvirtError ('virDomainShutdownFlags() failed', dom=self) libvirtError: Guest agent is not responding: QEMU guest agent is not connected engine log: 2018-06-15 21:34:37,888+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-25) [] EVENT_ID: USER_RUN_VM(32), VM virt_console_vm started on Host host_mixed_2 2018-06-15 21:34:47,569+03 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] Running command: ShutdownVmCommand internal: false. Entities affected : ID: 287206e4-5bcd-4586-b0eb-d02f0ac1ba44 Type: VMAction group SHUT_DOWN_VM with role type USER 2018-06-15 21:34:47,574+03 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] Entered (VM 'virt_console_vm'). 2018-06-15 21:34:47,575+03 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] Sending shutdown command for VM 'virt_console_vm'. 2018-06-15 21:34:47,578+03 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] START, DestroyVmVDSCommand( DestroyVmVDSCommandParameters:{hostId='7e9e7d5b-e176-4530-aa69-00edc4bb3d2e', vmId='287206e4-5bcd-4586-b0eb-d02f0ac1ba44', secondsToWait='30', gracefully='true', reason='', ignoreNoVm='false'}), log id: 3654de9c 2018-06-15 21:34:47,582+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] START, DestroyVDSCommand(HostName = host_mixed_2, DestroyVmVDSCommandParameters:{hostId='7e9e7d5b-e176-4530-aa69-00edc4bb3d2e', vmId='287206e4-5bcd-4586-b0eb-d02f0ac1ba44', secondsToWait='30', gracefully='true', reason='', ignoreNoVm='false'}), log id: 64265528 2018-06-15 21:34:47,588+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] FINISH, DestroyVDSCommand, log id: 64265528 2018-06-15 21:34:47,592+03 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-63) [vms_syncAction_56190c01-1305-4260] FINISH, DestroyVmVDSCommand, return: PoweringDown, log id: 3654de9c 2018-06-15 21:34:47,624+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-63) [vms_syncAction_56190c01-1305-4260] EVENT_ID: USER_INITIATED_SHUTDOWN_VM(73), VM shutdown initiated by admin@internal-authz on VM virt_console_vm (Host: host_mixed_2). 2018-06-15 21:37:19,579+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2018-06-15 21:37:19,580+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 23 threads waiting for tasks and 0 tasks in queue. 2018-06-15 21:37:19,580+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engineScheduled' is using 0 threads out of 100, 100 threads waiting for tasks. 2018-06-15 21:37:19,580+03 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engineThreadMonitoring' is using 1 threads out of 1, 0 threads waiting for tasks. 2018-06-15 21:37:23,394+03 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [3a81c7ad] Lock Acquired to object 'EngineLock:{exclusiveLocks='[2f62de97-7785-4759-aa08-e8b5afdb629c=PROVIDER]', sharedLocks=''}' 2018-06-15 21:37:23,413+03 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [3a81c7ad] Running command: SyncNetworkProviderCommand internal: true. 2018-06-15 21:37:23,572+03 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-34) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2018-06-15 21:37:23,776+03 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-19) [3a81c7ad] Lock freed to object 'EngineLock:{exclusiveLocks='[2f62de97-7785-4759-aa08-e8b5afdb629c=PROVIDER]', sharedLocks=''}' 2018-06-15 21:39:53,335+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] VM '287206e4-5bcd-4586-b0eb-d02f0ac1ba44'(virt_console_vm) moved from 'PoweringDown' --> 'Up' 2018-06-15 21:39:53,364+03 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] EVENT_ID: VM_POWER_DOWN_FAILED(147), Shutdown of VM virt_console_vm failed.