QEMU random crash caused by libspice-server

Hi,

One of our OpenStack instances crashed. It seems there was some problem related to SPICE. Attaching what we had in qemu log. Also sending our versions:

Linux pre-node1 4.18.0-13-generic #14~18.04.1-Ubuntu SMP Thu Dec 6 14:09:52 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

QEMU emulator version 2.11.1(Debian 1:2.11+dfsg-1ubuntu7.9)
Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers


root@pre-node1:~# cat /var/log/libvirt/qemu/instance-00000038.log 
2019-03-10 20:39:36.510+0000: starting up libvirt version: 4.0.0, package: 1ubuntu8.6 (Christian Ehrhardt <email address hidden> Fri, 09 Nov 2018 07:42:01 +0100), qemu version: 2.11.1(Debian 1:2.11+dfsg-1ubuntu7.9), hostname: pre-node1
LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin QEMU_AUDIO_DRV=spice /usr/bin/kvm-spice -name guest=instance-00000038,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-5-instance-00000038/master-key.aes -machine pc-i440fx-bionic,accel=kvm,usb=off,dump-guest-core=off,mem-merge=off -cpu Skylake-Server-IBRS,ss=on,hypervisor=on,tsc_adjust=on,clflushopt=on,pku=on,ssbd=on,xsaves=on -m 2048 -realtime mlock=on -smp 2,sockets=1,cores=1,threads=2 -object memory-backend-file,id=ram-node0,prealloc=yes,mem-path=/dev/hugepages/libvirt/qemu/5-instance-00000038,share=yes,size=2147483648,host-nodes=0,policy=bind -numa node,nodeid=0,cpus=0-1,memdev=ram-node0 -uuid 3c3d04f3-4b25-4ea5-8836-0e06eef9dcb7 -smbios 'type=1,manufacturer=OpenStack Foundation,product=OpenStack Nova,version=18.1.1,serial=93fa1a55-ba3a-4a99-80b3-3a7bb4e964af,uuid=3c3d04f3-4b25-4ea5-8836-0e06eef9dcb7,family=Virtual Machine' -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-5-instance-00000038/monitor.sock,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -boot strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x3 -drive file=/var/lib/nova/instances/3c3d04f3-4b25-4ea5-8836-0e06eef9dcb7/disk,format=qcow2,if=none,id=drive-virtio-disk0,cache=none,discard=ignore,throttling.iops-read=5000,throttling.iops-write=5000 -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -add-fd set=0,fd=29 -chardev pty,id=charserial0,logfile=/dev/fdset/0,logappend=on -device isa-serial,chardev=charserial0,id=serial0 -chardev spicevmc,id=charchannel0,name=vdagent -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.spice.0 -spice port=5900,addr=10.252.0.101,disable-ticketing,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,max_outputs=1,bus=pci.0,addr=0x2 -device vfio-pci,host=25:04.1,id=hostdev0,bus=pci.0,addr=0x5 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x6 -msg timestamp=on
2019-03-10T20:39:36.568276Z qemu-system-x86_64: -chardev pty,id=charserial0,logfile=/dev/fdset/0,logappend=on: char device redirected to /dev/pts/2 (label charserial0)
inputs_channel_detach_tablet: 
main_channel_link: add main channel client
main_channel_client_handle_pong: net test: latency 32.760000 ms, bitrate 33384953 bps (31.838372 Mbps)
red_qxl_set_cursor_peer: 
inputs_connect: inputs channel client create

(process:65324): Spice-WARNING **: 16:35:23.769: Failed to create channel client: Client 0x55e7c157e970: duplicate channel type 2 id 0
red_qxl_set_cursor_peer: 

(process:65324): Spice-WARNING **: 16:35:24.142: Failed to create channel client: Client 0x55e7c157e970: duplicate channel type 4 id 0

(process:65324): Spice-CRITICAL **: 16:35:24.142: cursor-channel.c:353:cursor_channel_connect: condition `ccc != NULL' failed
2019-03-13 15:35:31.785+0000: shutting down, reason=crashed




I am also attaching some gdb information extracted from qemu crash dump file. These are backtraces of particular threads within the crashed QEMU process.


Thread 9 (Thread 0x7f69649ea5c0 (LWP 65324)):
#0  0x00007f695f02d2b7 in __libc_write (fd=26, buf=0x7ffc33f5b330, nbytes=56) at ../sysdeps/unix/sysv/linux/write.c:27
#1  0x00007f695ff30ed3 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#2  0x00007f695ff316ce in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#3  0x00007f695ff52db6 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#4  0x00007f695ff58e38 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#5  0x00007f695ff5f463 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#6  0x00007f695ff5f7bb in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#7  0x000055e7bec94584 in  ()
#8  0x000055e7bec94e58 in aio_dispatch ()
#9  0x000055e7bec91e3e in  ()
#10 0x00007f695fa45387 in g_main_context_dispatch () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#11 0x000055e7bec940a7 in main_loop_wait ()
#12 0x000055e7be8b8486 in main ()

Thread 8 (Thread 0x7f68b78fc700 (LWP 61873)):
#0  0x00007f695f02c8c2 in futex_abstimed_wait_cancelable (private=0, abstime=0x7f68b78fb900, expected=0, futex_word=0x55e7c1531d78)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  0x00007f695f02c8c2 in do_futex_wait (sem=sem@entry=0x55e7c1531d78, abstime=abstime@entry=0x7f68b78fb900) at sem_waitcommon.c:111
#2  0x00007f695f02c9d3 in __new_sem_wait_slow (sem=0x55e7c1531d78, abstime=0x7f68b78fb900) at sem_waitcommon.c:181
#3  0x000055e7bec976cf in qemu_sem_timedwait ()
#4  0x000055e7bec928bc in  ()
#5  0x00007f695f0236db in start_thread (arg=0x7f68b78fc700) at pthread_create.c:463
#6  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 7 (Thread 0x7f688f7fe700 (LWP 61366)):
#0  0x00007f695f02c8c2 in futex_abstimed_wait_cancelable (private=0, abstime=0x7f688f7fd900, expected=0, futex_word=0x55e7c1531d78)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  0x00007f695f02c8c2 in do_futex_wait (sem=sem@entry=0x55e7c1531d78, abstime=abstime@entry=0x7f688f7fd900) at sem_waitcommon.c:111
#2  0x00007f695f02c9d3 in __new_sem_wait_slow (sem=0x55e7c1531d78, abstime=0x7f688f7fd900) at sem_waitcommon.c:181
#3  0x000055e7bec976cf in qemu_sem_timedwait ()
#4  0x000055e7bec928bc in  ()
#5  0x00007f695f0236db in start_thread (arg=0x7f688f7fe700) at pthread_create.c:463
#6  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 6 (Thread 0x7f687effd700 (LWP 61362)):
#0  0x00007f695f02c8c2 in futex_abstimed_wait_cancelable (private=0, abstime=0x7f687effc900, expected=0, futex_word=0x55e7c1531d78)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  0x00007f695f02c8c2 in do_futex_wait (sem=sem@entry=0x55e7c1531d78, abstime=abstime@entry=0x7f687effc900) at sem_waitcommon.c:111
#2  0x00007f695f02c9d3 in __new_sem_wait_slow (sem=0x55e7c1531d78, abstime=0x7f687effc900) at sem_waitcommon.c:181
#3  0x000055e7bec976cf in qemu_sem_timedwait ()
#4  0x000055e7bec928bc in  ()
#5  0x00007f695f0236db in start_thread (arg=0x7f687effd700) at pthread_create.c:463
#6  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 5 (Thread 0x7f68b58f1700 (LWP 60991)):
#0  0x00007f695f02c8c2 in futex_abstimed_wait_cancelable (private=0, abstime=0x7f68b58f0900, expected=0, futex_word=0x55e7c1531d78)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#1  0x00007f695f02c8c2 in do_futex_wait (sem=sem@entry=0x55e7c1531d78, abstime=abstime@entry=0x7f68b58f0900) at sem_waitcommon.c:111
#2  0x00007f695f02c9d3 in __new_sem_wait_slow (sem=0x55e7c1531d78, abstime=0x7f68b58f0900) at sem_waitcommon.c:181
#3  0x000055e7bec976cf in qemu_sem_timedwait ()
#4  0x000055e7bec928bc in  ()
#5  0x00007f695f0236db in start_thread (arg=0x7f68b58f1700) at pthread_create.c:463
#6  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 4 (Thread 0x7f69564a2700 (LWP 65331)):
#0  0x00007f695ed46839 in syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x000055e7bec9790b in qemu_event_wait ()
#2  0x000055e7beca7ebe in  ()
#3  0x00007f695f0236db in start_thread (arg=0x7f69564a2700) at pthread_create.c:463
#4  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 3 (Thread 0x7f695449d700 (LWP 65363)):
#0  0x00007f695ed415d7 in ioctl () at ../sysdeps/unix/syscall-template.S:78
#1  0x000055e7be910547 in kvm_vcpu_ioctl ()
#2  0x000055e7be910684 in kvm_cpu_exec ()
#3  0x000055e7be8ed3f4 in  ()
#4  0x00007f695f0236db in start_thread (arg=0x7f695449d700) at pthread_create.c:463
#5  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7f6952b4f700 (LWP 65366)):
#0  0x00007f695ed415d7 in ioctl () at ../sysdeps/unix/syscall-template.S:78
#1  0x000055e7be910547 in kvm_vcpu_ioctl ()
---Type <return> to continue, or q <return> to quit---
#2  0x000055e7be910684 in kvm_cpu_exec ()
#3  0x000055e7be8ed3f4 in  ()
#4  0x00007f695f0236db in start_thread (arg=0x7f6952b4f700) at pthread_create.c:463
#5  0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7f6951a40700 (LWP 65368)):
#0  0x00007f695ec69e97 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f695ec6b801 in __GI_abort () at abort.c:79
#2  0x00007f695ff81cc9 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#3  0x00007f695ff63929 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#4  0x00007f695ff314f1 in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#5  0x00007f695ff37d7b in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#6  0x00007f695fa451f5 in g_main_context_dispatch () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#7  0x00007f695fa455c0 in  () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#8  0x00007f695fa458d2 in g_main_loop_run () at /usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#9  0x00007f695ff63b3a in  () at /usr/lib/x86_64-linux-gnu/libspice-server.so.1
#10 0x00007f695f0236db in start_thread (arg=0x7f6951a40700) at pthread_create.c:463
#11 0x00007f695ed4c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Regards,
Premysl