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@xxxxxxxxxxxxx
http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876
--
libvir-list mailing list
libvir-list@xxxxxxxxxx
https://www.redhat.com/mailman/listinfo/libvir-list
