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