On 07/19/16 20:41, Markus Armbruster wrote:
> From: Paolo Bonzini <pbonz...@redhat.com>
>
> This saves a lot of memory compared to a statically-sized array,
> or at least 24kb could be considered a lot on an Atari ST.
> It also makes the code more similar to QmpOutputVisitor.
>
> This removes the limit on the depth of a QObject that can be processed
> into a QAPI tree. This is not a problem because QObjects can be
> considered trusted; the text received on the QMP wire is untrusted
> input, but the JSON parser already takes pains to limit the QObject tree
> it creates. We don't need the QMP input visitor to limit it again.
>
> Signed-off-by: Paolo Bonzini <pbonz...@redhat.com>
> Message-Id: <1467906798-5312-3-git-send-email-pbonz...@redhat.com>
> Reviewed-by: Markus Armbruster <arm...@redhat.com>
> Reviewed-by: Eric Blake <ebl...@redhat.com>
> [Commit message typo fixed]
> Signed-off-by: Markus Armbruster <arm...@redhat.com>
> ---
> qapi/qmp-input-visitor.c | 59
> ++++++++++++++++++++++++------------------------
> 1 file changed, 29 insertions(+), 30 deletions(-)
This patch breaks VM shutdown for me, with libvirt. The symptom is that
I issue the "poweroff" command in the Fedora guest, the shutdown
proceeds normally, and at the very end, the QEMU process hangs, and
virt-manager seems to hang too, with the VM state stuck in "Shutting
Down".
NB: VM shutdown is not generally broken for me by this patch. Most of my
other VMs don't care, but this one specific VM, it is very consistent.
* First, some version numbers:
- host kernel: 3.10.0-464.el7.x86_64
- libvirt: 2.0.0-2.el7.x86_64
- virt manager: 1.4.0-1.el7.noarch
* configure command line:
./configure \
--audio-drv-list=alsa \
--target-list=x86_64-softmmu,aarch64-softmmu,i386-softmmu,arm-softmmu \
--disable-vde \
--enable-spice \
--prefix=/opt/qemu-installed \
--disable-gtk \
--enable-debug \
--enable-trace-backends=log
* QEMU command line:
/opt/qemu-installed/bin/qemu-system-x86_64 \
-name guest=ovmf.fedora.q35,debug-threads=on \
-S \
-object
secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-31-ovmf.fedora.q35/master-key.aes
\
-machine pc-q35-2.5,accel=kvm,usb=off \
-cpu Haswell-noTSX,+vmx \
-drive
file=/home/virt-images/OVMF_CODE.3264.fd,if=pflash,format=raw,unit=0,readonly=on
\
-drive
file=/var/lib/libvirt/qemu/nvram/ovmf.fedora.q35_VARS.fd,if=pflash,format=raw,unit=1
\
-m 4096 \
-realtime mlock=off \
-smp 4,sockets=1,cores=2,threads=2 \
-uuid a51c0e4c-93b1-4485-811e-ea9727eb748c \
-no-user-config \
-nodefaults \
-chardev
socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-31-ovmf.fedora.q35/monitor.sock,server,nowait
\
-mon chardev=charmonitor,id=monitor,mode=control \
-rtc base=utc \
-no-shutdown \
-global ICH9-LPC.disable_s3=0 \
-global ICH9-LPC.disable_s4=1 \
-boot menu=on,splash-time=1000,strict=on \
-device i82801b11-bridge,id=pci.1,bus=pcie.0,addr=0x1e \
-device pci-bridge,chassis_nr=2,id=pci.2,bus=pci.1,addr=0x1 \
-device ich9-usb-ehci1,id=usb,bus=pci.2,addr=0x2.0x7 \
-device
ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.2,multifunction=on,addr=0x2 \
-device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.2,addr=0x2.0x1 \
-device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.2,addr=0x2.0x2 \
-device virtio-scsi-pci,id=scsi0,bus=pci.2,addr=0x5 \
-device virtio-serial-pci,id=virtio-serial0,bus=pci.2,addr=0x6 \
-drive
file=/mnt/data/virt-images-big/ovmf.fedora.q35.zimg,format=qcow2,if=none,id=drive-virtio-disk0,cache=writeback
\
-device
virtio-blk-pci,scsi=off,bus=pci.2,addr=0x3,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2
\
-drive
file=/mnt/data/isos/iso-bits/bits-2073.iso,format=raw,if=none,media=cdrom,id=drive-sata0-0-0,readonly=on,cache=writeback
\
-device ide-cd,bus=ide.0,drive=drive-sata0-0-0,id=sata0-0-0 \
-drive
file=/usr/share/OVMF/UefiShell.iso,format=raw,if=none,id=drive-scsi0-0-0-1,readonly=on,cache=writeback
\
-device
scsi-cd,bus=scsi0.0,channel=0,scsi-id=0,lun=1,drive=drive-scsi0-0-0-1,id=scsi0-0-0-1,bootindex=1
\
-netdev tap,fd=26,id=hostnet0,vhost=on,vhostfd=28 \
-device
virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:29:80:ae,bus=pci.2,addr=0x1,rombar=1,romfile=/usr/share/ipxe/1af41000.rom
\
-chardev pty,id=charserial0 \
-device isa-serial,chardev=charserial0,id=serial0 \
-chardev
socket,id=charchannel0,path=/var/lib/libvirt/qemu/channel/target/domain-31-ovmf.fedora.q35/org.qemu.guest_agent.0,server,nowait
\
-device
virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0
\
-chardev spicevmc,id=charchannel1,name=vdagent \
-device
virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=com.redhat.spice.0
\
-device usb-tablet,id=input0 \
-spice
port=5900,addr=127.0.0.1,disable-ticketing,streaming-video=off,seamless-migration=on
\
-device
qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,bus=pcie.0,addr=0x1
\
-device intel-hda,id=sound0,bus=pci.2,addr=0x7 \
-device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 \
-device virtio-balloon-pci,id=balloon0,bus=pci.2,addr=0x4 \
-global isa-debugcon.iobase=0x402 \
-debugcon file:/tmp/ovmf.fedora.q35.log \
-global driver=cfi.pflash01,property=secure,value=on \
-fw_cfg name=opt/ovmf/PcdResizeXterm,string=y \
-msg timestamp=on
* Bisection log:
> git bisect start
> # bad: [51313fe4f4afea65970a20b32ed2d35b44fbf993] Merge remote-tracking
> branch
> 'remotes/stefanha/tags/CVE-2016-5403-virtio-unbounded-allocation-pull-request'
> into staging
> git bisect bad 51313fe4f4afea65970a20b32ed2d35b44fbf993
> # bad: [e0ce97f896ac752b734c22a6d0d1b3e1739d1158] Merge remote-tracking
> branch 'remotes/cody/tags/block-pull-request' into staging
> git bisect bad e0ce97f896ac752b734c22a6d0d1b3e1739d1158
> # good: [6b3532b20b787cbd697a68b383232f5c3b39bd1e] Merge remote-tracking
> branch 'remotes/kraxel/tags/pull-ui-20160603-1' into staging
> git bisect good 6b3532b20b787cbd697a68b383232f5c3b39bd1e
> # skip: [3638439d541835f20fb76346f14549800046af76] MC146818 RTC: add GPIO
> access to output IRQ
> git bisect skip 3638439d541835f20fb76346f14549800046af76
> # skip: [52d4c8ee93cc599fecf817d403f125f4c7c036c6] linux-user: Update
> preprocessor constants for Mips-specific e_flags bits
> git bisect skip 52d4c8ee93cc599fecf817d403f125f4c7c036c6
> # good: [e7ed11f083015bf34a121cfff31540cf9c2bae23] crypto: remove temp files
> on completion of secrets test
> git bisect good e7ed11f083015bf34a121cfff31540cf9c2bae23
> # good: [dde35bc966ef8c1afb4f4e0f3c0e99fc0f27ca04] spapr: fix
> write-past-end-of-array error in cpu core device init code
> git bisect good dde35bc966ef8c1afb4f4e0f3c0e99fc0f27ca04
> # skip: [f1ef55786691a1bf79db0b74ba1e5347a0d38c1b] Merge remote-tracking
> branch 'remotes/cohuck/tags/s390x-20160711' into staging
> git bisect skip f1ef55786691a1bf79db0b74ba1e5347a0d38c1b
> # good: [720ff280e73ebdc6751a9c5ae741fdcdd092a5a0] block: Convert
> bdrv_pwrite_zeroes() to BdrvChild
> git bisect good 720ff280e73ebdc6751a9c5ae741fdcdd092a5a0
> # good: [0b8b8753e4d94901627b3e86431230f2319215c4] coroutine: move entry
> argument to qemu_coroutine_create
> git bisect good 0b8b8753e4d94901627b3e86431230f2319215c4
> # skip: [4815185902971c41fcdd700fa1fc3e1d9299900f] trace: Add per-vCPU
> tracing states for events with the 'vcpu' property
> git bisect skip 4815185902971c41fcdd700fa1fc3e1d9299900f
> # good: [4fb8320a2efb2216c7ddcc929ad0362f4e285681] avx2 configure: Use
> primitives in test
> git bisect good 4fb8320a2efb2216c7ddcc929ad0362f4e285681
> # good: [338404d061144956b76f9893ca3434d057dff2d4] Merge remote-tracking
> branch 'remotes/pmaydell/tags/pull-target-arm-20160719' into staging
> git bisect good 338404d061144956b76f9893ca3434d057dff2d4
> # bad: [0e55c381f69f302d09ab1e18f3c1156cca56f4a6] net: Use correct type for
> bool flag
> git bisect bad 0e55c381f69f302d09ab1e18f3c1156cca56f4a6
> # bad: [b6167706829c6e0d3572daa2b6769594ced276f7] qapi: Add type.is_empty()
> helper
> git bisect bad b6167706829c6e0d3572daa2b6769594ced276f7
> # bad: [cebea510579ed43724156cc596a8ff14ba208740] net: use Netdev instead of
> NetClientOptions in client init
> git bisect bad cebea510579ed43724156cc596a8ff14ba208740
> # bad: [3d344c2aabb7bc9b414321e3c52872901edebdda] qapi: change
> QmpInputVisitor to QSLIST
> git bisect bad 3d344c2aabb7bc9b414321e3c52872901edebdda
> # good: [fc76ae8b38783e82c109834573ba5d6f080440b5] qapi: change
> QmpOutputVisitor to QSLIST
> git bisect good fc76ae8b38783e82c109834573ba5d6f080440b5
> # first bad commit: [3d344c2aabb7bc9b414321e3c52872901edebdda] qapi: change
> QmpInputVisitor to QSLIST
I repeatedly tested this, and the parent commit of 3d344c2aabb7 works.
The bug reproduces at current master (v2.7.0-rc0-21-g51313fe4f4af) --
that's where I noticed it (see it at the top of the bisection log). If I
revert 3d344c2aabb7 on top of master, then the issue is *not* fixed; it
persists.
This tells me that 3d344c2aabb7 may not be the real culprit, it just
exposes a bug elsewhere, perhaps.
* Nonetheless, because 3d344c2aabb7 is QAPI related, I looked at my
libvirt log. (I constantly capture all QMP and QGA traffic, as a
principle.) Here's the snippet that is logged by libvirtd right after I
enter the "poweroff" command in the guest. First, the working case
(i.e., when QEMU is built at the parent of 3d344c2aabb7):
> 2016-07-27 20:19:28.188+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650768, "microseconds": 188028},
> "event": "VSERPORT_CHANGE", "data": {"open": false, "id": "channel0"}}]
> 2016-07-27 20:19:28.188+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc17c2b9b50 event={"timestamp": {"seconds":
> 1469650768, "microseconds": 188028}, "event": "VSERPORT_CHANGE", "data":
> {"open": false, "id": "channel0"}}
> 2016-07-27 20:19:28.188+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc17c2b9b50 obj=0x7fc19b7364e0
> 2016-07-27 20:19:28.188+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle VSERPORT_CHANGE handler=0x7fc186260a80 data=0x7fc19b740200
> 2016-07-27 20:19:28.188+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 135 bytes out of 135 available in buffer
> 2016-07-27 20:19:28.188+0000: 1588: debug : qemuAgentNotifyClose:817 :
> mon=0x7fc158000c50
> 2016-07-27 20:19:28.188+0000: 1588: debug : qemuAgentClose:830 :
> mon=0x7fc158000c50
> 2016-07-27 20:19:28.188+0000: 1576: debug : qemuAgentDispose:163 :
> mon=0x7fc158000c50
> 2016-07-27 20:19:28.922+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650768, "microseconds": 922231},
> "event": "SHUTDOWN"}]
> 2016-07-27 20:19:28.922+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc17c2b9b50 event={"timestamp": {"seconds":
> 1469650768, "microseconds": 922231}, "event": "SHUTDOWN"}
> 2016-07-27 20:19:28.922+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc17c2b9b50 obj=0x7fc19b736ad0
> 2016-07-27 20:19:28.922+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle SHUTDOWN handler=0x7fc186260bc0 data=(nil)
> 2016-07-27 20:19:28.922+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 85 bytes out of 85 available in buffer
> 2016-07-27 20:19:28.926+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650768, "microseconds": 926025},
> "event": "STOP"}]
> 2016-07-27 20:19:28.926+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc17c2b9b50 event={"timestamp": {"seconds":
> 1469650768, "microseconds": 926025}, "event": "STOP"}
> 2016-07-27 20:19:28.926+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc17c2b9b50 obj=0x7fc19b761b90
> 2016-07-27 20:19:28.926+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle STOP handler=0x7fc186260ba0 data=(nil)
> 2016-07-27 20:19:28.926+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 81 bytes out of 81 available in buffer
> 2016-07-27 20:19:28.927+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650768, "microseconds": 927492},
> "event": "SHUTDOWN"}]
> 2016-07-27 20:19:28.927+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc17c2b9b50 event={"timestamp": {"seconds":
> 1469650768, "microseconds": 927492}, "event": "SHUTDOWN"}
> 2016-07-27 20:19:28.927+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc17c2b9b50 obj=0x7fc19b736ef0
> 2016-07-27 20:19:28.927+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle SHUTDOWN handler=0x7fc186260bc0 data=(nil)
> 2016-07-27 20:19:28.927+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 85 bytes out of 85 available in buffer
> 2016-07-27 20:19:28.965+0000: 1576: error : qemuMonitorIO:692 : internal
> error: End of file from monitor
> 2016-07-27 20:19:29.170+0000: 1588: warning :
> virSecuritySELinuxRestoreFileLabel:1053 : cannot lookup default selinux label
> for /mnt/data/virt-images-big/ovmf.fedora.q35.zimg
Second, the same snippet for the broken case (i.e., when QEMU is built
at 3d344c2aabb7):
> 2016-07-27 20:20:30.390+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650830, "microseconds": 390652},
> "event": "VSERPORT_CHANGE", "data": {"open": false, "id": "channel0"}}]
> 2016-07-27 20:20:30.390+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc160012210 event={"timestamp": {"seconds":
> 1469650830, "microseconds": 390652}, "event": "VSERPORT_CHANGE", "data":
> {"open": false, "id": "channel0"}}
> 2016-07-27 20:20:30.390+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc160012210 obj=0x7fc19b7609e0
> 2016-07-27 20:20:30.390+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle VSERPORT_CHANGE handler=0x7fc186260a80 data=0x7fc19b739a60
> 2016-07-27 20:20:30.390+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 135 bytes out of 135 available in buffer
> 2016-07-27 20:20:30.390+0000: 1588: debug : qemuAgentNotifyClose:817 :
> mon=0x7fc158000c50
> 2016-07-27 20:20:30.391+0000: 1588: debug : qemuAgentClose:830 :
> mon=0x7fc158000c50
> 2016-07-27 20:20:30.391+0000: 1576: debug : qemuAgentDispose:163 :
> mon=0x7fc158000c50
> 2016-07-27 20:20:31.169+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650831, "microseconds": 169050},
> "event": "SHUTDOWN"}]
> 2016-07-27 20:20:31.169+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc160012210 event={"timestamp": {"seconds":
> 1469650831, "microseconds": 169050}, "event": "SHUTDOWN"}
> 2016-07-27 20:20:31.169+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc160012210 obj=0x7fc19b734f90
> 2016-07-27 20:20:31.169+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle SHUTDOWN handler=0x7fc186260bc0 data=(nil)
> 2016-07-27 20:20:31.169+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 85 bytes out of 85 available in buffer
> 2016-07-27 20:20:31.172+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650831, "microseconds": 172041},
> "event": "STOP"}]
> 2016-07-27 20:20:31.172+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc160012210 event={"timestamp": {"seconds":
> 1469650831, "microseconds": 172041}, "event": "STOP"}
> 2016-07-27 20:20:31.172+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc160012210 obj=0x7fc19b761b90
> 2016-07-27 20:20:31.172+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle STOP handler=0x7fc186260ba0 data=(nil)
> 2016-07-27 20:20:31.172+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 81 bytes out of 81 available in buffer
> 2016-07-27 20:20:31.174+0000: 1576: debug : qemuMonitorJSONIOProcessLine:191
> : Line [{"timestamp": {"seconds": 1469650831, "microseconds": 174169},
> "event": "SHUTDOWN"}]
> 2016-07-27 20:20:31.174+0000: 1576: info : qemuMonitorJSONIOProcessLine:206 :
> QEMU_MONITOR_RECV_EVENT: mon=0x7fc160012210 event={"timestamp": {"seconds":
> 1469650831, "microseconds": 174169}, "event": "SHUTDOWN"}
> 2016-07-27 20:20:31.174+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:152
> : mon=0x7fc160012210 obj=0x7fc19b73f5a0
> 2016-07-27 20:20:31.174+0000: 1576: debug : qemuMonitorJSONIOProcessEvent:177
> : handle SHUTDOWN handler=0x7fc186260bc0 data=(nil)
> 2016-07-27 20:20:31.174+0000: 1576: debug : qemuMonitorJSONIOProcess:260 :
> Total used 85 bytes out of 85 available in buffer
This is where things hang. When I send a SIGKILL to the QEMU process, it
dies (of course) and then libvirtd logs:
> 2016-07-27 20:20:46.005+0000: 1576: error : qemuMonitorIO:692 : internal
> error: End of file from monitor
* Here's a stack dump from QEMU when it is hung:
> (gdb) thread apply all bt full
>
> Thread 7 (Thread 0x7f935812f700 (LWP 20802)):
> #0 0x00007f9360423f4d in __lll_lock_wait () from /lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007f936041fd02 in _L_lock_791 () from /lib64/libpthread.so.0
> No symbol table info available.
> #2 0x00007f936041fc08 in pthread_mutex_lock () from /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f9363b9c2cd in qemu_mutex_lock (mutex=0x7f93641d9c00
> <qemu_global_mutex>) at util/qemu-thread-posix.c:64
> err = 0
> __func__ = "qemu_mutex_lock"
> #4 0x00007f936377a6a3 in qemu_mutex_lock_iothread () at
> /home/lacos/src/upstream/qemu/cpus.c:1271
> No locals.
> #5 0x00007f9363bb0fc3 in call_rcu_thread (opaque=0x0) at util/rcu.c:258
> tries = 1
> n = 52
> node = 0x7f933c4e8dc0
> #6 0x00007f936041ddc5 in start_thread () from /lib64/libpthread.so.0
> No symbol table info available.
> #7 0x00007f935d9c7ced in clone () from /lib64/libc.so.6
> No symbol table info available.
>
> Thread 6 (Thread 0x7f9355518700 (LWP 20809)):
> #0 0x00007f9360423f4d in __lll_lock_wait () from /lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007f93604264bc in _L_cond_lock_792 () from /lib64/libpthread.so.0
> No symbol table info available.
> #2 0x00007f9360426398 in __pthread_mutex_cond_lock () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f9360421765 in pthread_cond_wait@@GLIBC_2.3.2 () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #4 0x00007f9363b9c42f in qemu_cond_wait (cond=0x7f9365f8bfa0,
> mutex=0x7f93641d9c00 <qemu_global_mutex>) at util/qemu-thread-posix.c:123
> err = 32659
> __func__ = "qemu_cond_wait"
> #5 0x00007f9363779fed in qemu_kvm_wait_io_event (cpu=0x7f9365f65c70) at
> /home/lacos/src/upstream/qemu/cpus.c:1044
> No locals.
> #6 0x00007f936377a123 in qemu_kvm_cpu_thread_fn (arg=0x7f9365f65c70) at
> /home/lacos/src/upstream/qemu/cpus.c:1083
> cpu = 0x7f9365f65c70
> r = 65536
> #7 0x00007f936041ddc5 in start_thread () from /lib64/libpthread.so.0
> No symbol table info available.
> #8 0x00007f935d9c7ced in clone () from /lib64/libc.so.6
> No symbol table info available.
>
> Thread 5 (Thread 0x7f9354d17700 (LWP 20810)):
> #0 0x00007f9360423f4d in __lll_lock_wait () from /lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007f93604264bc in _L_cond_lock_792 () from /lib64/libpthread.so.0
> No symbol table info available.
> #2 0x00007f9360426398 in __pthread_mutex_cond_lock () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f9360421765 in pthread_cond_wait@@GLIBC_2.3.2 () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #4 0x00007f9363b9c42f in qemu_cond_wait (cond=0x7f9365fe7a70,
> mutex=0x7f93641d9c00 <qemu_global_mutex>) at util/qemu-thread-posix.c:123
> err = 32659
> __func__ = "qemu_cond_wait"
> #5 0x00007f9363779fed in qemu_kvm_wait_io_event (cpu=0x7f9365fcb400) at
> /home/lacos/src/upstream/qemu/cpus.c:1044
> No locals.
> #6 0x00007f936377a123 in qemu_kvm_cpu_thread_fn (arg=0x7f9365fcb400) at
> /home/lacos/src/upstream/qemu/cpus.c:1083
> cpu = 0x7f9365fcb400
> r = 65536
> #7 0x00007f936041ddc5 in start_thread () from /lib64/libpthread.so.0
> No symbol table info available.
> #8 0x00007f935d9c7ced in clone () from /lib64/libc.so.6
> No symbol table info available.
>
> Thread 4 (Thread 0x7f934ffff700 (LWP 20811)):
> #0 0x00007f9360423f4d in __lll_lock_wait () from /lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007f93604264bc in _L_cond_lock_792 () from /lib64/libpthread.so.0
> No symbol table info available.
> #2 0x00007f9360426398 in __pthread_mutex_cond_lock () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f9360421765 in pthread_cond_wait@@GLIBC_2.3.2 () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #4 0x00007f9363b9c42f in qemu_cond_wait (cond=0x7f93660051d0,
> mutex=0x7f93641d9c00 <qemu_global_mutex>) at util/qemu-thread-posix.c:123
> err = 32659
> __func__ = "qemu_cond_wait"
> #5 0x00007f9363779fed in qemu_kvm_wait_io_event (cpu=0x7f9365fe8dc0) at
> /home/lacos/src/upstream/qemu/cpus.c:1044
> No locals.
> #6 0x00007f936377a123 in qemu_kvm_cpu_thread_fn (arg=0x7f9365fe8dc0) at
> /home/lacos/src/upstream/qemu/cpus.c:1083
> cpu = 0x7f9365fe8dc0
> r = 65536
> #7 0x00007f936041ddc5 in start_thread () from /lib64/libpthread.so.0
> No symbol table info available.
> #8 0x00007f935d9c7ced in clone () from /lib64/libc.so.6
> No symbol table info available.
>
> Thread 3 (Thread 0x7f934f7fe700 (LWP 20812)):
> #0 0x00007f9360423f4d in __lll_lock_wait () from /lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007f93604264bc in _L_cond_lock_792 () from /lib64/libpthread.so.0
> No symbol table info available.
> #2 0x00007f9360426398 in __pthread_mutex_cond_lock () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f9360421765 in pthread_cond_wait@@GLIBC_2.3.2 () from
> /lib64/libpthread.so.0
> No symbol table info available.
> #4 0x00007f9363b9c42f in qemu_cond_wait (cond=0x7f93660230e0,
> mutex=0x7f93641d9c00 <qemu_global_mutex>) at util/qemu-thread-posix.c:123
> err = 32659
> __func__ = "qemu_cond_wait"
> #5 0x00007f9363779fed in qemu_kvm_wait_io_event (cpu=0x7f9366006520) at
> /home/lacos/src/upstream/qemu/cpus.c:1044
> No locals.
> #6 0x00007f936377a123 in qemu_kvm_cpu_thread_fn (arg=0x7f9366006520) at
> /home/lacos/src/upstream/qemu/cpus.c:1083
> cpu = 0x7f9366006520
> r = 65536
> #7 0x00007f936041ddc5 in start_thread () from /lib64/libpthread.so.0
> No symbol table info available.
> #8 0x00007f935d9c7ced in clone () from /lib64/libc.so.6
> No symbol table info available.
>
> Thread 2 (Thread 0x7f934e5ff700 (LWP 20826)):
> #0 0x00007f935d9bd69d in poll () from /lib64/libc.so.6
> No symbol table info available.
> #1 0x00007f935f2671c7 in red_worker_main () from /lib64/libspice-server.so.1
> No symbol table info available.
> #2 0x00007f936041ddc5 in start_thread () from /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f935d9c7ced in clone () from /lib64/libc.so.6
> No symbol table info available.
>
> Thread 1 (Thread 0x7f93634f0c00 (LWP 20784)):
> #0 0x00007f9360423f4d in __lll_lock_wait () from /lib64/libpthread.so.0
> No symbol table info available.
> #1 0x00007f936041fd02 in _L_lock_791 () from /lib64/libpthread.so.0
> No symbol table info available.
> #2 0x00007f936041fc08 in pthread_mutex_lock () from /lib64/libpthread.so.0
> No symbol table info available.
> #3 0x00007f9363b9c2cd in qemu_mutex_lock (mutex=0x7f9365ed1a50) at
> util/qemu-thread-posix.c:64
> err = 32659
> __func__ = "qemu_mutex_lock"
> #4 0x00007f936389324d in qemu_chr_fe_write (s=0x7f9365ed1a50,
> buf=0x7f9365f50530 "{\"timestamp\": {\"seconds\": 1469650920,
> \"microseconds\": 469371}, \"event\": \"SPICE_DISCONNECTED\", \"data\":
> {\"server\": {\"port\": \"\", \"family\": \"unix\", \"host\": \"localhost\"},
> \"client\": {\"port\": \"\", \"family\": \""..., len=231) at qemu-char.c:280
> ret = 32659
> __PRETTY_FUNCTION__ = "qemu_chr_fe_write"
> #5 0x00007f936377bf52 in monitor_flush_locked (mon=0x7f9365f50690) at
> /home/lacos/src/upstream/qemu/monitor.c:311
> rc = 32659
> len = 231
> buf = 0x7f9365f50530 "{\"timestamp\": {\"seconds\": 1469650920,
> \"microseconds\": 469371}, \"event\": \"SPICE_DISCONNECTED\", \"data\":
> {\"server\": {\"port\": \"\", \"family\": \"unix\", \"host\": \"localhost\"},
> \"client\": {\"port\": \"\", \"family\": \""...
> #6 0x00007f936377c0e4 in monitor_puts (mon=0x7f9365f50690,
> str=0x7f9365ed28b6 "") at /home/lacos/src/upstream/qemu/monitor.c:353
> c = 10 '\n'
> #7 0x00007f936377c347 in monitor_json_emitter (mon=0x7f9365f50690,
> data=0x7f93666e2c00) at /home/lacos/src/upstream/qemu/monitor.c:401
> json = 0x7f9365f8d4b0
> __PRETTY_FUNCTION__ = "monitor_json_emitter"
> #8 0x00007f936377c513 in monitor_qapi_event_emit
> (event=QAPI_EVENT_SPICE_DISCONNECTED, qdict=0x7f93666e2c00) at
> /home/lacos/src/upstream/qemu/monitor.c:472
> mon = 0x7f9365f50690
> #9 0x00007f936377c5c0 in monitor_qapi_event_queue
> (event=QAPI_EVENT_SPICE_DISCONNECTED, qdict=0x7f93666e2c00,
> errp=0x7ffe5234beb0) at /home/lacos/src/upstream/qemu/monitor.c:497
> evconf = 0x7f9364072a88 <monitor_qapi_event_conf+200>
> evstate = 0x7f93666e2c00
> __PRETTY_FUNCTION__ = "monitor_qapi_event_queue"
> #10 0x00007f9363b8c28e in qapi_event_send_spice_disconnected
> (server=0x7f93660c64c0, client=0x7f93660c7050, errp=0x7f93646105e8
> <error_abort>) at qapi-event.c:1038
> qmp = 0x7f93666e2c00
> err = 0x0
> emit = 0x7f936377c52b <monitor_qapi_event_queue>
> obj = 0x7f9365f29420
> v = 0x7f9366112330
> param = {server = 0x7f93660c64c0, client = 0x7f93660c7050}
> #11 0x00007f9363aac5b0 in channel_event (event=3, info=0x7f93666e3c20) at
> ui/spice-core.c:248
> server = 0x7f93660c64c0
> client = 0x7f93660c7050
> need_lock = false
> __func__ = "channel_event"
> #12 0x00007f935f269ed3 in reds_handle_channel_event () from
> /lib64/libspice-server.so.1
> No symbol table info available.
> #13 0x00007f935f24607a in main_dispatcher_channel_event () from
> /lib64/libspice-server.so.1
> No symbol table info available.
> #14 0x00007f935f27093e in reds_stream_free () from /lib64/libspice-server.so.1
> No symbol table info available.
> #15 0x00007f935f27a4f3 in snd_disconnect_channel () from
> /lib64/libspice-server.so.1
> No symbol table info available.
> #16 0x00007f935f27ac3e in snd_detach_common () from
> /lib64/libspice-server.so.1
> No symbol table info available.
> #17 0x00007f935f27d0bd in snd_detach_playback () from
> /lib64/libspice-server.so.1
> No symbol table info available.
> #18 0x00007f935f26d648 in spice_server_remove_interface () from
> /lib64/libspice-server.so.1
> No symbol table info available.
> #19 0x00007f93638c821d in line_out_fini (hw=0x7f93677d9220) at
> audio/spiceaudio.c:152
> out = 0x7f93677d9220
> #20 0x00007f93638c3b8c in audio_atexit () at audio/audio.c:1754
> sc = 0x0
> s = 0x7f93641e1420 <glob_audio_state>
> hwo = 0x7f93677d9220
> hwi = 0x0
> #21 0x00007f935d909e69 in __run_exit_handlers () from /lib64/libc.so.6
> No symbol table info available.
> #22 0x00007f935d909eb5 in exit () from /lib64/libc.so.6
> No symbol table info available.
> #23 0x00007f935d8f2b1c in __libc_start_main () from /lib64/libc.so.6
> No symbol table info available.
> #24 0x00007f9363745619 in _start ()
> No symbol table info available.
It seems to me that QEMU deadlocks when it tries to emit the
SPICE_DISCONNECTED event.
(Note that I can't find "handle SPICE_DISCONNECTED" in the libvirtd log
even in the successful case (i.e., when QEMU is built at the parent of
3d344c2aabb7).)
Apparently audio_atexit() is triggered when QEMU is returning from
main() -- or calling exit() --, which somehow results in QEMU trying to
send a SPICE_DISCONNECTED event through the monitor? I guess the monitor
has been long dead by then.
Hmmm, this gives me an idea... What happens if I remove the following
fragment from my domain XML?
<sound model='ich6'>
<address type='pci' domain='0x0000' bus='0x02' slot='0x07'
function='0x0'/>
</sound>
Yeah, the hang disappears, shutdown works just fine. It's a spice audio
bug after all, apparently. Sorry for reporting it in this thread! :) I'm
adding Gerd to the address list.
To reiterate: this patch (commit 3d344c2aabb7) does *not* cause the
symptom, it only exposes an independent bug that causes the symptom.
And, I can work around that for now, by removing sound devices.
Thanks,
Laszlo
