QEMU random crash caused by libspice-server

[Premysl Kouril]

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

[Christian Ehrhardt  (paelzer)]

Hi Premysl,
this has similarities to [1] which was fixed long ago.
In case it is reproducible for you - as it was asked back then - it might be helpful attaching SPICE_DEBUG=1 log, using remote-viewer.

And if reproducible in general also worth a quick check to try with the latest qemu version which atm is 3.1 that you have in Debian Buster.

[1]: https://bugzilla.redhat.com/show_bug.cgi?id=980714#c8

[Premysl Kouril (premysl-kouril)]

Hi Christian,

thanks for reply, chmmm, what makes you think there are similarities? To me
it looks like a different problem.

Regards,
Premysl

On Mon, Mar 18, 2019 at 8:15 AM Christian Ehrhardt  <
<email address hidden>> wrote:

> Hi Premysl,
> this has similarities to [1] which was fixed long ago.
> In case it is reproducible for you - as it was asked back then - it might
> be helpful attaching SPICE_DEBUG=1 log, using remote-viewer.
>
> And if reproducible in general also worth a quick check to try with the
> latest qemu version which atm is 3.1 that you have in Debian Buster.
>
> [1]: https://bugzilla.redhat.com/show_bug.cgi?id=980714#c8
>
> ** Bug watch added: Red Hat Bugzilla #980714
> https://bugzilla.redhat.com/show_bug.cgi?id=980714
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1820247
>
> Title:
> QEMU random crash caused by libspice-server
>
> Status in QEMU:
> New
>
> Bug description:
> 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
...

[Christian Ehrhardt  (paelzer)]

Hi,
the warnings around "duplicate channel type 2 id 0" where present in the other bug as well.
And since that often means it passes the same area of code I wanted to suggest to provide the same debug data.

The actual crash is a different one for sure as the stack traces look different and also the old one is fixed quite some time.

[Thomas Huth (th-huth)]

The QEMU project is currently considering to move its bug tracking to another system. For this we need to know which bugs are still valid and which could be closed already. Thus we are setting older bugs to "Incomplete" now.
If you still think this bug report here is valid, then please switch the state back to "New" within the next 60 days, otherwise this report will be marked as "Expired". Or mark it as "Fix Released" if the problem has been solved with a newer version of QEMU already. Thank you and sorry for the inconvenience.

[Launchpad Janitor (janitor)]

[Expired for QEMU because there has been no activity for 60 days.]