Bug 738241

Summary: Qemu sends two SHUTDOWN events when shutting down with -no-shutdown option
Product: Red Hat Enterprise Linux 6 Reporter: Marian Krcmarik <mkrcmari>
Component: qemu-kvmAssignee: Luiz Capitulino <lcapitulino>
Status: CLOSED WONTFIX QA Contact: Virtualization Bugs <virt-bugs>
Severity: low Docs Contact:
Priority: unspecified    
Version: 6.2CC: acathrow, areis, jdenemar, juzhang, michen, mkenneth, qzhang, shu, tburke, virt-maint, xfu
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-03-05 12:45:56 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Marian Krcmarik 2011-09-14 11:54:59 UTC
Description of problem:
When shutting down guest (for example in Windows7: Start -> Shutdown) I can see that libvirt gets SHUTDOWN event, STOP event and then again SHUTDOWN event.
Snip from libvirt log:

13:37:01.048: 22628: debug : qemuMonitorJSONIOProcessLine:118 : Line [{"timestamp": {"seconds": 1316000221, "microseconds": 33477}, "event": "SHUTDOWN"}]
.
.
13:37:02.856: 22628: debug : qemuMonitorJSONIOProcessLine:118 : Line [{"timestamp": {"seconds": 1316000221, "microseconds": 42652}, "event": "STOP"}]
.
.
13:37:02.869: 22628: debug : qemuMonitorJSONIOProcessLine:118 : Line [{"timestamp": {"seconds": 1316000221, "microseconds": 55594}, "event": "SHUTDOWN"}]
.

I think that the last SHUTDOWN event is not needed and should not be there, as far as I know from libvirt guys, It does NOT mind too much if they get many shutdown events, but I guess better not to send the last SHUTDOWN event.

Version-Release number of selected component (if applicable):
qemu-kvm-tools-0.12.1.2-2.184

How reproducible:
Always

Steps to Reproduce:
1. Start guest using libvirt (with -no-shutdown option).
2. Shutdown Guest from the guest.
  
Actual results:
Libvirt debug logs says to get SHUTDOWN, STOP and then again SHUTDOWN event.

Expected results:
I would expect to get SHUTDOWN and then SYOP event only.

Additional info:

Comment 3 Luiz Capitulino 2011-09-27 14:25:11 UTC
Marian,

Can you please try to reproduce it using a Linux guest and provide the libvirt version you're running?

This is likely to be the expected behavior though. What's happening here is that, when you run qemu with -no-shutdown, it will stop the VM instead of exiting when the guest shuts down. This means that it's perfectly possible to resume VM execution and/or try to shutdown again. If you do try to shutdown again, you'll see the same sequence of events (SHUTDOWN followed by STOP).

Comment 4 Jiri Denemark 2011-09-28 10:23:42 UTC
BTW, current libvirt really doesn't care how many SHUTDOWN events are sent by qemu. All but the first one are just ignored.

Comment 5 Luiz Capitulino 2011-09-28 14:48:34 UTC
Thanks for the feedback Jiri.

I won't close it though, I want to confirm it's not a qemu issue. Will move to 6.3, as it's not a blocker (nor exception).

Marian, please note that I still need your feedback.

Comment 6 Marian Krcmarik 2011-09-29 20:07:28 UTC
(In reply to comment #5)
> Thanks for the feedback Jiri.
> 
> I won't close it though, I want to confirm it's not a qemu issue. Will move to
> 6.3, as it's not a blocker (nor exception).
> 
> Marian, please note that I still need your feedback.

OK, I am on my vacation, will update when I get back, It can wait for me obviously.

Comment 7 Marian Krcmarik 2011-10-21 08:04:28 UTC
(In reply to comment #5)
> Thanks for the feedback Jiri.
> 
> I won't close it though, I want to confirm it's not a qemu issue. Will move to
> 6.3, as it's not a blocker (nor exception).
> 
> Marian, please note that I still need your feedback.

Luiz,

I can reproduce with Linux -> the same behaviour, with libvirt-0.9.4-19.el6.x86_64, seems that this version of libvirt has explanation log messages of what Jiri mentioned:
The second SHUTDOWN:
09:51:50.243: 14112: debug : qemuProcessShutdownOrReboot:439 : Ignoring repeated SHUTDOWN event from domain rhel

I am not really sure what feedback you need, can you please specify? I do not understand why the second SHUTDOWN event is sent when It is ignored by libvirt anyway or why the order is SHUTDOWN -> STOP and not STOP -> SHUTDOWN.
Anyway I do not understand qemu events that much and if you consider it to be correct then close this report. Thank you for investigation though.

Comment 9 FuXiangChun 2012-03-02 08:51:44 UTC
reproduced bug with qemu-kvm-0.12.1.2-2.233.el6.x86_64

reproduce to step:
1.boot a windows2008r2 guest with virt-manager
2.change libvirt log level(enable debug mode)
edit /etc/libvirt/libvirtd.conf
  set and add the following two lines
  log_filters="1:qemu_monitor_json 1:qemu_driver"
  log_outputs="1:file:/var/log/libvirt/libvirtd.log"
  service libvirtd restart
3. shutdown guest inside guest

actual result:

16:45:35.541: 19849: debug : qemuMonitorJSONCommandWithFd:228 : Send command '{"execute":"query-balloon","id":"libvirt-284"}' for write with FD -1
16:45:35.542: 19845: debug : qemuMonitorJSONIOProcessLine:119 : Line [{"return": {"actual": 2123366400}, "id": "libvirt-284"}]
16:45:35.542: 19845: debug : qemuMonitorJSONIOProcess:186 : Total used 57 bytes out of 57 available in buffer
16:45:35.542: 19849: debug : qemuMonitorJSONCommandWithFd:233 : Receive command reply ret=0 rxObject=0x11e1b00
16:45:36.268: 19845: debug : qemuMonitorJSONIOProcessLine:119 : Line [{"timestamp": {"seconds": 1330677936, "microseconds": 268408}, "event": "SHUTDOWN"}]
16:45:36.268: 19845: debug : qemuMonitorJSONIOProcessEvent:90 : mon=0x7fa4e800aa00 obj=0x11ea630
16:45:36.268: 19845: debug : qemuMonitorJSONIOProcessEvent:103 : handle SHUTDOWN handler=0x49cc70 data=(nil)
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcess:186 : Total used 85 bytes out of 85 available in buffer
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcessLine:119 : Line [{"timestamp": {"seconds": 1330677936, "microseconds": 268676}, "event": "STOP"}]
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcessEvent:90 : mon=0x7fa4e800aa00 obj=0x11e9a40
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcessEvent:103 : handle STOP handler=0x49cc40 data=(nil)
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcess:186 : Total used 81 bytes out of 81 available in buffer
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcessLine:119 : Line [{"timestamp": {"seconds": 1330677936, "microseconds": 269607}, "event": "SHUTDOWN"}]
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcessEvent:90 : mon=0x7fa4e800aa00 obj=0x11ea370
16:45:36.269: 19845: debug : qemuMonitorJSONIOProcessEvent:103 : handle SHUTDOWN handler=0x49cc70 data=(nil)
16:45:36.270: 19845: debug : qemuMonitorJSONIOProcess:186 : Total used 85 bytes out of 85 available in buffer
16:45:36.457: 19845: error : qemuMonitorIO:583 : internal error End of file from monitor

Comment 11 Jiri Denemark 2012-03-05 08:55:52 UTC
I would just close this issue. Libvirt doesn't care (the second SHUTDOWN event is just ignored) and direct use of qemu-kvm in RHEL is not supported. Thus this bug seems to be just a cleanup thing which can be made upstream but there's no need to push for having it in RHEL.

Comment 12 Luiz Capitulino 2012-03-05 12:45:56 UTC
Yes, comment 11 is right. I let this one opened just to remind me that I had to look at it, but if it doesn't affect RHEL we can close it.