[libvirt] [RFC] duplicate suspend/resume lifecycle events with QEMU

[Philipp Hahn]

Hello,

I'm using the libvirt event mechanism and noticed, that several events
are reported twice:

> $ python examples/event-test.py qemu:///session
> Using uri:qemu:///session
> myDomainEventCallback1 EVENT: Domain installer(2) Resumed Unpaused
> myDomainEventCallback2 EVENT: Domain installer(2) Resumed Unpaused
> myDomainEventCallback1 EVENT: Domain installer(2) Resumed Unpaused
> myDomainEventCallback2 EVENT: Domain installer(2) Resumed Unpaused
> myDomainEventCallback1 EVENT: Domain installer(2) Suspended Paused
> myDomainEventCallback2 EVENT: Domain installer(2) Suspended Paused
> myDomainEventCallback1 EVENT: Domain installer(2) Suspended Paused
> myDomainEventCallback2 EVENT: Domain installer(2) Suspended Paused
> myDomainEventCallback1 EVENT: Domain installer(-1) Stopped Destroyed
> myDomainEventCallback2 EVENT: Domain installer(-1) Stopped Destroyed

(the Python example program registers 2 handlers, so each event is
printed twice, but each handler gets the suspend/resume event twice itself.)
Interestingly enough it only "suspend" and "resume", but not "created"
or "destroyed".

But it isn't Python specific, virsh shows the same behaviour:

> $ virsh  event --loop --event lifecycle
> event 'lifecycle' for domain installer: Started Booted
> event 'lifecycle' for domain installer: Suspended Paused
> event 'lifecycle' for domain installer: Resumed Unpaused
> event 'lifecycle' for domain installer: Resumed Unpaused
> event 'lifecycle' for domain installer: Suspended Paused
> event 'lifecycle' for domain installer: Suspended Paused
> event 'lifecycle' for domain installer: Stopped Destroyed

After shutting down libvirtd I used `socat stdio unix-connect:...` to
connect the the qemu UNIX socket and used
  {"execute": "stop"}
and
  {"execute": "cont"}
to verify, that QEMU only send one event. So to me it looks like libvirt
is duplicating the event.


Enabling DEBUG for »log_filters="1:qemu_monitor_json"« shows noting
wrong with QEMU:

> qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"cont","id":"libvirt-9"}' for write with FD -1
> qemuMonitorSend:972 : QEMU_MONITOR_SEND_MSG: mon=0x7f1940000910 msg={"execute":"cont","id":"libvirt-9"}
>  fd=-1
> qemuMonitorIOWrite:503 : QEMU_MONITOR_IO_WRITE: mon=0x7f1940000910 buf={"execute":"cont","id":"libvirt-9"}
>  len=37 ret=37 errno=11
> qemuMonitorIOProcess:399 : QEMU_MONITOR_IO_PROCESS: mon=0x7f1940000910 buf={"timestamp": {"seconds": 1497326279, "microseconds": 688619}, "event": "RESUME"}
> {"return": {}, "id": "libvirt-9"}
>  len=118
> qemuMonitorJSONIOProcessLine:179 : Line [{"timestamp": {"seconds": 1497326279, "microseconds": 688619}, "event": "RESUME"}]
> qemuMonitorJSONIOProcessLine:194 : QEMU_MONITOR_RECV_EVENT: mon=0x7f1940000910 event={"timestamp": {"seconds": 1497326279, "microseconds": 688619}, "event": "RESUME"}
> qemuMonitorJSONIOProcessEvent:138 : mon=0x7f1940000910 obj=0x5636fa1f1f00
> qemuMonitorEmitEvent:1186 : mon=0x7f1940000910 event=RESUME
> qemuMonitorJSONIOProcessEvent:165 : handle RESUME handler=0x7f19535903d0 data=(nil)
> qemuMonitorEmitResume:1237 : mon=0x7f1940000910


Looking at src/qemu/qemu_monitor_json.c:qemuMonitorJSONIOProcessEvent:

>  141 qemuMonitorJSONIOProcessEvent(qemuMonitorPtr mon,
>  142                               virJSONValuePtr obj)
>  143 {
...
>  170     qemuMonitorEmitEvent(mon, type, seconds, micros, details);

This seems to send the first event

>  171     VIR_FREE(details);
>  172
>  173     handler = bsearch(type, eventHandlers, ARRAY_CARDINALITY(eventHandlers),
>  174                       sizeof(eventHandlers[0]), qemuMonitorEventCompare);
>  175     if (handler) {
>  176         VIR_DEBUG("handle %s handler=%p data=%p", type,
>  177                   handler->handler, data);
>  178         (handler->handler)(mon, data);

and this the second instance.

>  179     }
>  180     return 0;
>  181 }

Looking deeper into the GIT source code I see this:

>   98 static qemuEventHandler eventHandlers[] = {
...
> 113     { "RESUME", qemuMonitorJSONHandleResume, },

> 544 static void qemuMonitorJSONHandleResume(qemuMonitorPtr mon, virJSONValuePtr data ATTRIBUTE_UNUSED)
> 546     qemuMonitorEmitResume(mon);
...
> 1267 qemuMonitorEmitEvent(qemuMonitorPtr mon, const char *event,                                                                                                                                                                 
> 1268                      long long seconds, unsigned int micros,
> 1269                      const char *details)
...
> 1274     QEMU_MONITOR_CALLBACK(mon, ret, domainEvent, mon->vm, event, seconds,
> 1275                           micros, details);
...
> 1325 qemuMonitorEmitResume(qemuMonitorPtr mon)
> 1330     QEMU_MONITOR_CALLBACK(mon, ret, domainResume, mon->vm);

but this doesn't yet completely explain, why only some events are
reported twice.

Is there some way to get rid of the duplication (in Python) or at least
to distinguish them, so I can ignore the second one?


I've observed this behaviour with both Debian-Jessie

> Compiled against library: libvirt 1.2.9
> Using library: libvirt 1.2.9
> Using API: QEMU 1.2.9
> Running hypervisor: QEMU 2.6.0

and also with the newer Debian-Sid

> Compiled against library: libvirt 3.0.0
> Using library: libvirt 3.0.0
> Using API: QEMU 3.0.0
> Running hypervisor: QEMU 2.8.1

Thank you in advance.

Philipp
-- 
Philipp Hahn
Open Source Software Engineer

Univention GmbH
be open.
Mary-Somerville-Str. 1
D-28359 Bremen
Tel.: +49 421 22232-0
Fax : +49 421 22232-99
hahn at univention.de

http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876