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@univention.de http://www.univention.de/ Geschäftsführer: Peter H. Ganten HRB 20755 Amtsgericht Bremen Steuer-Nr.: 71-597-02876