1691721 – RHEL6 guest didn't Synchronize in destination after postcopy migration

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1691721 - RHEL6 guest didn't Synchronize in destination after postcopy migration

Summary: RHEL6 guest didn't Synchronize in destination after postcopy migration

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 8
Classification:	Red Hat
Component:	spice
Sub Component:
Version:	8.2
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	8.2
Assignee:	Frediano Ziglio
QA Contact:	SPICE QE bug list
Docs Contact:
URL:
Whiteboard:
Duplicates (1):	1692225 (view as bug list)
Depends On:	1691701 1840240
Blocks:
TreeView+	depends on / blocked

Reported:	2019-03-22 10:34 UTC by jingzhao
Modified:	2020-11-04 04:07 UTC (History)
CC List:	16 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2020-11-04 04:07:31 UTC
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
Log file from source (9.04 KB, text/plain) 2019-09-09 17:36 UTC, Dr. David Alan Gilbert	no flags	Details
Log file from dest (7.90 KB, text/plain) 2019-09-09 17:37 UTC, Dr. David Alan Gilbert	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHEA-2020:4818	0	None	None	None	2020-11-04 04:07:52 UTC

Description jingzhao 2019-03-22 10:34:04 UTC

Description of problem:
RHEL6 guest didn't  Synchronize in destination after postcopy migration



Version-Release number of selected component (if applicable):
source host(rhel7.6):
kernel-3.10.0-957.12.1.el7.x86_64
qemu-kvm-rhev-2.12.0-18.el7_6.3.x86_64

Destination host(rhel8):
kernel-4.18.0-80.el8.x86_64
qemu-kvm-3.1.0-20.module+el8+2888+cdc893a8.x86_64


How reproducible:
3/3

Steps to Reproduce:
1. Boot guest with qemu command line [1]

2. migrate_set_capability postcopy-ram on on src and dest host

3. migrate -d tcp: destination host ip:5800

4. migrate_start_postcopy


Actual results:
RHEL6 guest didn't  Synchronize in destination after postcopy migration

Didn't see the desktop of rhel6 on destination, only see the waiting display, then you can see the rhel6 desktop after migration finished

Expected results:
RHEL6 guest didn't  Synchronize in destination immediately after postcopy migration


Additional info:
[1]/usr/libexec/qemu-kvm \
-name rhel7 \
-machine pc-i440fx-rhel7.6.0,accel=kvm,usb=off \
-realtime mlock=off \
-cpu SandyBridge,+x2apic,hv_spinlocks=0x1fff,hv_relaxed,hv_vapic,hv_time \
-sandbox off \
-m 7680   \
-smp 8,cores=1,threads=1,sockets=8  \
-uuid 49a3438a-70a3-4ba8-92ce-3a05e0934608 \
-no-user-config \
-nodefaults \
-chardev socket,id=charmonitor,path=/mnt/tmp1,server,nowait \
-mon chardev=charmonitor,id=monitor,mode=control \
-rtc base=utc,driftfix=slew \
-no-hpet \
-no-shutdown \
-global PIIX4_PM.disable_s3=1 \
-global PIIX4_PM.disable_s4=1 \
-boot order=c,menu=on,splash-time=3000,strict=on \
-device ich9-usb-ehci1,id=usb0,bus=pci.0,addr=0x5.0x7 \
-device ich9-usb-uhci1,masterbus=usb0.0,firstport=0,bus=pci.0,multifunction=on,addr=0x5 \
-device ich9-usb-uhci2,masterbus=usb0.0,firstport=2,bus=pci.0,addr=0x5.0x1 \
-device ich9-usb-uhci3,masterbus=usb0.0,firstport=4,bus=pci.0,addr=0x5.0x2 \
-device virtio-scsi-pci,id=scsi0,cmd_per_lun=234,bus=pci.0,addr=0x8 \
-device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x7 \
-drive file=/mnt/virtio-win-1.9.4.iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw \
-device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 \
-drive file=/mnt/virtio-win-1.9.6_x86.vfd,if=none,id=drive-fdc0-0-0,format=raw,cache=none \
-global isa-fdc.driveA=drive-fdc0-0-0 \
-drive file=/mnt/rhel6.10.raw,if=none,id=drive-virtio-disk0,format=raw,cache=none,discard=unmap,werror=stop,rerror=stop,aio=threads \
-device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x9,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 \
-drive file=/mnt/virtio-scsi-disk,if=none,id=drive-scsi-disk,format=qcow2,cache=none,werror=stop,rerror=stop \
-device virtio-scsi-pci,id=scsi1,addr=0x13 \
-device scsi-hd,drive=drive-scsi-disk,bus=scsi1.0,id=data-disk2 \
-chardev pty,id=charserial0 -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 \
-chardev socket,id=charchannel1,path=/mnt/tmp2,server,nowait \
-device virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=org.qemu.guest_agent.0 \
-device usb-tablet,id=input0 \
-device intel-hda,id=sound0,bus=pci.0,addr=0x4 \
-device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 \
-device intel-hda,id=sound1,bus=pci.0,addr=0x6 \
-device hda-micro,id=sound1-codec0,bus=sound1.0 \
-device intel-hda,id=sound2,bus=pci.0,addr=0x17 \
-device hda-output,id=sound2-codec0,bus=sound2.0,cad=0 \
-device ich9-intel-hda,id=sound3,bus=pci.0,addr=0x18 \
-device hda-duplex,id=sound3-codec0,bus=sound3.0,cad=0 \
-chardev spicevmc,id=charredir0,name=usbredir \
-device usb-redir,chardev=charredir0,id=redir0 \
-chardev spicevmc,id=charredir1,name=usbredir \
-device usb-redir,chardev=charredir1,id=redir1 \
-chardev spicevmc,id=charredir2,name=usbredir \
-device usb-redir,chardev=charredir2,id=redir2 \
-chardev spicevmc,id=charredir3,name=usbredir \
-device usb-redir,chardev=charredir3,id=redir3 \
-device usb-host,id=hostdev0 \
-device pvpanic,ioport=1285 -msg timestamp=on \
-netdev tap,id=hostnet0,vhost=on,id=hostnet0,script=/etc/qemu-ifup \
-device virtio-net-pci,netdev=hostnet0,id=virtio-net-pci0,mac=b6:af:42:c8:66:18,bus=pci.0,addr=0x14 \
-netdev tap,id=hostnet1,vhost=on,script=/etc/qemu-ifup  \
-device e1000,netdev=hostnet1,id=virtio-net-pci1,mac=b6:2f:a8:85:82:7c,bus=pci.0,addr=0x15,multifunction=off \
-netdev tap,id=hostnet2,vhost=on,script=/etc/qemu-ifup \
-device rtl8139,netdev=hostnet2,id=virtio-net-pci2,mac=4e:63:28:bc:c1:75,bus=pci.0,addr=0x16,multifunction=off \
-drive file=/mnt/ide-disk,if=none,id=drive-data-disk,format=raw,cache=none,aio=native,werror=stop,rerror=stop,copy-on-read=off,media=disk \
-device ide-hd,drive=drive-data-disk,id=system-disk,logical_block_size=512,physical_block_size=512,min_io_size=32,opt_io_size=64,discard_granularity=512,ver=fuxc-ver,bus=ide.0,unit=0  \
-device ich9-usb-uhci6,id=uhci6,bus=pci.0,addr=0xa \
-device usb-kbd,id=kdb0,bus=uhci6.0 \
-device ich9-usb-uhci5,id=uhci5,bus=pci.0,addr=0xb \
-device usb-mouse,id=mouse0,bus=uhci5.0 \
-device nec-usb-xhci,id=xhci,bus=pci.0,addr=0xd \
-device usb-bot,id=bot1,bus=xhci.0 \
-drive file=/mnt/virtio-win-126.iso,if=none,id=usb-cdrom1,format=raw \
-device scsi-cd,bus=bot1.0,scsi-id=0,lun=1,drive=usb-cdrom1,id=usb-cdrom1 \
-drive file=/mnt/bot-disk1,id=usb-disk1,if=none,format=qcow2 \
-device scsi-hd,bus=bot1.0,scsi-id=0,lun=0,drive=usb-disk1,id=usb-disk1 \
-device usb-ehci,id=ehci,bus=pci.0,addr=0xe \
-device usb-bot,id=bot2,bus=ehci.0 \
-drive file=/mnt/virtio-win-126-cp1.iso,if=none,id=usb-cdrom2,format=raw \
-device scsi-cd,bus=bot2.0,scsi-id=0,lun=1,drive=usb-cdrom2,id=usb-cdrom2 \
-drive file=/mnt/bot-disk2,id=usb-disk2,if=none,format=qcow2 \
-device scsi-hd,bus=bot2.0,scsi-id=0,lun=0,drive=usb-disk2,id=usb-disk2 \
-device piix3-usb-uhci,id=usb,bus=pci.0,addr=0xf \
-device usb-bot,id=bot3,bus=usb.0 \
-drive file=/mnt/virtio-win-126-cp2.iso,if=none,id=usb-cdrom3,format=raw \
-device scsi-cd,bus=bot3.0,scsi-id=0,lun=1,drive=usb-cdrom3,id=usb-cdrom3 \
-drive file=/mnt/bot-disk3,id=usb-disk3,if=none,format=qcow2 \
-device scsi-hd,bus=bot3.0,scsi-id=0,lun=0,drive=usb-disk3,id=usb-disk3 \
-device ich9-usb-uhci3,id=uhci,bus=pci.0,addr=0x10 \
-device usb-storage,drive=drive-usb-0,id=usb-0,removable=on,bus=uhci.0,port=1 \
-drive file=/mnt/usb-uhci,if=none,id=drive-usb-0,media=disk,format=qcow2 \
-device ich9-usb-ehci1,id=ehci1,bus=pci.0,addr=0x11 \
-device usb-storage,drive=drive-usb-1,id=usb-1,removable=on,bus=ehci1.0,port=1 \
-drive file=/mnt/usb-ehci,if=none,id=drive-usb-1,media=disk,format=qcow2 \
-device nec-usb-xhci,id=xhci1,bus=pci.0,addr=0x12 \
-device usb-storage,drive=drive-usb-2,id=usb-2,removable=on,bus=xhci1.0,port=1 \
-drive file=/mnt/usb-xhci,if=none,id=drive-usb-2,media=disk,format=qcow2 \
-watchdog ib700 -watchdog-action reset \
-device virtio-rng-pci,id=rng0,bus=pci.0,addr=0x1c \
-device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x1d \
-monitor stdio \
-qmp tcp:0:4466,server,nowait -serial unix:/tmp/ttym,server,nowait \
-spice port=5910,addr=0.0.0.0,disable-ticketing,seamless-migration=on \
-k en-us \
-device qxl-vga,id=video0,ram_size=134217728,vram_size=67108864,vgamem_mb=16,bus=pci.0,addr=0x2 \
-chardev socket,id=seabioslog_id,path=/home/seabios,server,nowait \
-device isa-debugcon,chardev=seabioslog_id,iobase=0x402 \


[2] can reproduce it with qemu-kvm-2.12.0-63.module+el8+2833+c7d6d092.x86_64 on destination rhel8 host

[3] can reproduce it when migrate from rhel8 host to rhel8 host

[4] can reproduce it using vnc:0 -vga qxl

Comment 1 jingzhao 2019-03-22 10:36:20 UTC

I am not sure I using vga cirrus is right since rhel8 had been deprecated cirrus driver.
But I tried it with "-vnc :0 -vga cirrus" and didn't reproduce the issue

Comment 2 jingzhao 2019-03-22 10:41:54 UTC

Also didn't reproduce the issue if we used RHEL.7.6 host on above test scenario

Comment 3 jingzhao 2019-03-22 10:53:13 UTC

simple command line when migrate from rhel8.0 to rhel8.0

/usr/libexec/qemu-kvm -name rhel6.10 \
-M pc \
-cpu SandyBridge -m 4G \
-smp 4,sockets=1,cores=4,threads=1 \
-device virtio-scsi-pci,id=virtio_scsi_pci0 \
-drive id=drive_image1,if=none,snapshot=off,aio=threads,cache=none,format=qcow2,file=/mnt/rhel610-64-virtio-scsi.qcow2 \
-device scsi-hd,drive=drive_image1,id=image1,bus=virtio_scsi_pci0.0 \
-spice port=5910,addr=0.0.0.0,disable-ticketing,seamless-migration=on \
-k en-us \
-device qxl-vga,id=video0,ram_size=134217728,vram_size=67108864,vgamem_mb=16,bus=pci.0 \
-monitor stdio \
-netdev tap,id=hostnet0,vhost=on \
-device virtio-net-pci,netdev=hostnet0,id=net0,mac=18:66:da:5f:d1:02 \

Comment 7 Dr. David Alan Gilbert 2019-04-17 10:26:57 UTC

I can't reproduce this with a rhel7 guest, and rhel6 guests suffer from bz 1691701.
So I think we need to wait for bz 1691701 to be fixed first before we can investigate this more.

Comment 8 Dr. David Alan Gilbert 2019-09-06 09:17:29 UTC

I've reproduced this:
/usr/libexec/qemu-kvm -M pc -cpu SandyBridge -m 4G -smp 4 -device virtio-scsi-pci,id=vsp -drive id=di1,if=none,snapshot=off,aio=threads,cache=none,format=qcow2,file=/home/vms/rhel6-10-ws.qcow2 -device scsi-hd,drive=di1,id=i1,bus=vsp.0 -spice port=5910,addr=0.0.0.0,disable-ticketing,seamless-migration=on -device qxl-vga,id=video0,ram_size=134217728,vram_size=67108864,vgamem_mb=16,bus=pci.0 -monitor stdio -netdev user,id=net -device virtio-net-pci,netdev=net -incoming tcp:0:4444

what's interesting is that for me the 'remote-viewer' hangs at 'connected to graphic server' with nothing displayed - it's not even a black screen

Using qemu-kvm-4.1.0-5.el8.bz1746790a.x86_64

spice-server-0.14.2-1.el8.x86_64

Comment 9 Dr. David Alan Gilbert 2019-09-06 10:21:50 UTC

This is temperamental; I've had it fail 2 or 3 times; but only when I migrate twice (like bz 1722022 ???)

remote-view --spice-debug output from the dead destion; I think in this case I connected after the migrate had finished:

(remote-viewer:25004): GSpice-DEBUG: 11:18:06.059: ../src/spice-session.c:288 New session (compiled from package spice-gtk 0.37)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.059: ../src/spice-session.c:292 Supported channels: main, display, inputs, cursor, playback, record, smartcard, usbredir, webdav
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.059: ../src/usb-device-manager.c:485 auto-connect filter set to 0x03,-1,-1,-1,0|-1,-1,-1,-1,1
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.064: ../src/spice-session.c:1814 no migration in progress
Spice-INFO: 11:18:06.065: ../src/channel-main.c:334:spice_main_set_property: SpiceMainChannel::color-depth has been deprecated. Property is ignored
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.065: ../src/spice-channel.c:141 main-1:0: spice_channel_constructed
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.065: ../src/spice-session.c:2309 main-1:0: new main channel, switching
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.065: ../src/spice-gtk-session.c:1089 Changing main channel from (nil) to 0x561128f733a0
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.115: ../src/usb-device-manager.c:950 device added 0bda:0316 (0x561128d73a60)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.115: ../src/usb-device-manager.c:950 device added 5986:2113 (0x561128ed22e0)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/usb-device-manager.c:950 device added 8087:0a2b (0x561128debf50)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/usb-device-manager.c:950 device added 1050:0407 (0x561128ec8870)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/usb-device-manager.c:950 device added 0d3d:0001 (0x561128ec8ba0)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/usb-device-manager.c:950 device added 093a:2510 (0x561128e47560)
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/spice-channel.c:2707 main-1:0: Open coroutine starting 0x561128f733a0
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/spice-channel.c:2544 main-1:0: Started background coroutine 0x561128f729e0
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/spice-session.c:2246 main-1:0: Using plain text, port 5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/spice-session.c:2177 open host virtlab414.virt.lab.eng.bos.redhat.com:5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.116: ../src/spice-session.c:2099 main-1:0: connecting 0x7f3dc3fffa50...
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.350: ../src/spice-session.c:2083 main-1:0: connect ready
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.350: ../src/spice-channel.c:1363 main-1:0: channel type 1 id 0 num common caps 1 num caps 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.522: ../src/spice-channel.c:1389 main-1:0: Peer version: 2:2
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.522: ../src/spice-channel.c:1947 main-1:0: spice_channel_recv_link_msg: 2 caps
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.522: ../src/spice-channel.c:1961 main-1:0: got remote common caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:1897 	0:0xB
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:1968 main-1:0: got remote channel caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:1897 	0:0x9
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:2926 test cap 0 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:2926 test cap 2 in 0xB: no
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:2926 test cap 1 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:2926 test cap 3 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.523: ../src/spice-channel.c:2000 main-1:0: use mini header: 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.691: ../src/spice-channel.c:1298 main-1:0: channel up, state 3
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.692: ../src/spice-session.c:2413 set mm time: 3167496706
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.692: ../src/spice-session.c:2416 spice_session_set_mm_time: mm-time-reset, old 8435312, new 3167496706
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.692: ../src/channel-main.c:1692 server name: QEMU 4.1.0
(remote-viewer:25004): GSpice-DEBUG: 11:18:06.692: ../src/channel-main.c:1703 server uuid: 00000000-0000-0000-0000-000000000000
(remote-viewer:25004): Spice-DEBUG: 11:18:07.378: ../src/channel-display-gst.c:773:gstvideo_debug_available_decoders: From  12 video decoder elements,  1 can handle caps   image/jpeg: jpegdec
(remote-viewer:25004): Spice-DEBUG: 11:18:07.379: ../src/channel-display-gst.c:773:gstvideo_debug_available_decoders: From  12 video decoder elements,  1 can handle caps  video/x-vp8: vp8dec
(remote-viewer:25004): Spice-DEBUG: 11:18:07.379: ../src/channel-display-gst.c:802:gstvideo_has_codec: From 12 decoders, none can handle 'video/x-h264'
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.379: ../src/channel-display.c:894 GStreamer does not support the h264 codec
(remote-viewer:25004): Spice-DEBUG: 11:18:07.379: ../src/channel-display-gst.c:773:gstvideo_debug_available_decoders: From  12 video decoder elements,  1 can handle caps  video/x-vp9: vp9dec
(remote-viewer:25004): Spice-DEBUG: 11:18:07.380: ../src/channel-display-gst.c:802:gstvideo_has_codec: From 12 decoders, none can handle 'video/x-h265'
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.380: ../src/channel-display.c:894 GStreamer does not support the h265 codec
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.380: ../src/spice-channel.c:141 display-2:0: spice_channel_constructed
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.380: ../src/spice-channel.c:141 cursor-4:0: spice_channel_constructed
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.380: ../src/spice-channel.c:141 inputs-3:0: spice_channel_constructed
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.380: ../src/spice-gtk-session.c:156 inputs-3:0: client_modifiers:0x0, guest_modifiers:0x0
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.380: ../src/spice-channel.c:2707 display-2:0: Open coroutine starting 0x56112903b6b0
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.381: ../src/spice-channel.c:2544 display-2:0: Started background coroutine 0x56112903acf0
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.381: ../src/spice-session.c:2246 display-2:0: Using plain text, port 5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.381: ../src/spice-session.c:2177 open host virtlab414.virt.lab.eng.bos.redhat.com:5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.381: ../src/spice-session.c:2099 display-2:0: connecting 0x7f3dc1ffda50...
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.619: ../src/spice-session.c:2083 display-2:0: connect ready
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.620: ../src/spice-channel.c:1363 display-2:0: channel type 2 id 0 num common caps 1 num caps 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:1389 display-2:0: Peer version: 2:2
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:1947 display-2:0: spice_channel_recv_link_msg: 2 caps
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:1961 display-2:0: got remote common caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:1897 	0:0xB
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:1968 display-2:0: got remote channel caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:1897 	0:0x1052
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:2926 test cap 0 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:2926 test cap 2 in 0xB: no
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:2926 test cap 1 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:2926 test cap 3 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:07.874: ../src/spice-channel.c:2000 display-2:0: use mini header: 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.045: ../src/spice-channel.c:1298 display-2:0: channel up, state 3
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.045: ../src/channel-display.c:1068 display-2:0: spice_display_channel_up: cache_size 83886080, glz_window_size 58716160 (bytes)
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:356 0:0 keypress-delay is set to 100 ms
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:2546 0:0 mouse mode 2 (client)
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.047: ../src/spice-widget.c:1296 0:0 recalc geom monitor: 0:0, guest +0+0:0x0, window 0x0, zoom 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-channel.c:2707 inputs-3:0: Open coroutine starting 0x561129199600
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-channel.c:2544 inputs-3:0: Started background coroutine 0x561129198c40
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-session.c:2246 inputs-3:0: Using plain text, port 5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-channel.c:2707 cursor-4:0: Open coroutine starting 0x561129198b70
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-channel.c:2544 cursor-4:0: Started background coroutine 0x5611291981b0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-session.c:2246 cursor-4:0: Using plain text, port 5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-session.c:2177 open host virtlab414.virt.lab.eng.bos.redhat.com:5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.048: ../src/spice-session.c:2099 inputs-3:0: connecting 0x7f3dbbfffa50...
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.049: ../src/spice-session.c:2177 open host virtlab414.virt.lab.eng.bos.redhat.com:5910
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.049: ../src/spice-session.c:2099 cursor-4:0: connecting 0x7f3dbafffa50...
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.256: ../src/channel-display.c:1909 surface flags: 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.256: ../src/channel-display.c:947 display-2:0: Create primary canvas
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.257: ../src/spice-widget.c:300 0:0 update monitor area
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.257: ../src/spice-widget.c:313 0:0 update monitor: no monitor 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.257: ../src/spice-channel.c:2926 test cap 1 in 0x1052: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.257: ../src/spice-widget.c:317 0:0 waiting until MonitorsConfig is received
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.257: ../src/spice-channel.c:2926 test cap 1 in 0x1052: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.281: ../src/spice-session.c:2083 cursor-4:0: connect ready
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.281: ../src/spice-channel.c:1363 cursor-4:0: channel type 4 id 0 num common caps 1 num caps 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.287: ../src/spice-session.c:2083 inputs-3:0: connect ready
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.288: ../src/spice-channel.c:1363 inputs-3:0: channel type 3 id 0 num common caps 1 num caps 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.523: ../src/spice-channel.c:1389 cursor-4:0: Peer version: 2:2
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.523: ../src/spice-channel.c:1947 cursor-4:0: spice_channel_recv_link_msg: 1 caps
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.523: ../src/spice-channel.c:1961 cursor-4:0: got remote common caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.523: ../src/spice-channel.c:1897 	0:0xB
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.523: ../src/spice-channel.c:1968 cursor-4:0: got remote channel caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.523: ../src/spice-channel.c:2926 test cap 0 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.524: ../src/spice-channel.c:2926 test cap 2 in 0xB: no
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.524: ../src/spice-channel.c:2926 test cap 1 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.524: ../src/spice-channel.c:2926 test cap 3 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.524: ../src/spice-channel.c:2000 cursor-4:0: use mini header: 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.574: ../src/spice-channel.c:1389 inputs-3:0: Peer version: 2:2
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.574: ../src/spice-channel.c:1947 inputs-3:0: spice_channel_recv_link_msg: 2 caps
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.574: ../src/spice-channel.c:1961 inputs-3:0: got remote common caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:1897 	0:0xB
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:1968 inputs-3:0: got remote channel caps:
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:1897 	0:0x1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:2926 test cap 0 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:2926 test cap 2 in 0xB: no
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:2926 test cap 1 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:2926 test cap 3 in 0xB: yes
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.575: ../src/spice-channel.c:2000 inputs-3:0: use mini header: 1
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.680: ../src/spice-channel.c:1298 cursor-4:0: channel up, state 3
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.681: ../src/channel-cursor.c:386 cursor-4:0: set_cursor: flags 0, size 2304
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.681: ../src/channel-cursor.c:392 cursor-4:0: set_cursor: type alpha(0), 0, 24x24
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.740: ../src/channel-base.c:78 main-1:0: spice_channel_handle_notify -- warn!!! #0: keyboard channel is insecure
(remote-viewer:25004): GSpice-DEBUG: 11:18:08.740: ../src/spice-channel.c:1298 inputs-3:0: channel up, state 3
(remote-viewer:25004): GSpice-DEBUG: 11:18:09.275: ../src/channel-display.c:1975 display-2:0: received empty monitor config
(remote-viewer:25004): GSpice-DEBUG: 11:18:09.275: ../src/channel-display.c:1123 display-2:0: display_handle_mark
(remote-viewer:25004): GSpice-DEBUG: 11:18:09.275: ../src/spice-widget.c:2852 0:0 widget mark: 1, display 0x56112919c3e0
(remote-viewer:25004): GSpice-DEBUG: 11:18:09.277: ../src/decode-glz.c:349 decode_header: 642x156, id 0, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:12.237: ../src/decode-glz.c:349 decode_header: 642x410, id 1, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:15.093: ../src/decode-glz.c:349 decode_header: 642x410, id 2, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:18.112: ../src/decode-glz.c:349 decode_header: 642x410, id 3, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:21.131: ../src/decode-glz.c:349 decode_header: 642x410, id 4, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:24.143: ../src/decode-glz.c:349 decode_header: 642x173, id 5, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:27.168: ../src/decode-glz.c:349 decode_header: 642x410, id 6, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:30.187: ../src/decode-glz.c:349 decode_header: 642x410, id 7, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:33.205: ../src/decode-glz.c:349 decode_header: 642x410, id 8, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:36.227: ../src/decode-glz.c:349 decode_header: 642x410, id 9, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:39.235: ../src/decode-glz.c:349 decode_header: 642x156, id 10, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:42.260: ../src/decode-glz.c:349 decode_header: 642x410, id 11, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:45.280: ../src/decode-glz.c:349 decode_header: 642x410, id 12, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:48.301: ../src/decode-glz.c:349 decode_header: 642x410, id 13, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:51.318: ../src/decode-glz.c:349 decode_header: 642x410, id 14, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:555 clipboard_get_targets:
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "TIMESTAMP"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "TARGETS"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "MULTIPLE"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "UTF8_STRING"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "COMPOUND_TEXT"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "TEXT"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "STRING"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "text/plain;charset=utf-8"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.139: ../src/spice-gtk-session.c:590  "text/plain"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:555 clipboard_get_targets:
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "TIMESTAMP"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "TARGETS"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "MULTIPLE"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "SAVE_TARGETS"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "UTF8_STRING"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "COMPOUND_TEXT"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "TEXT"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "STRING"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "text/plain;charset=utf-8"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.140: ../src/spice-gtk-session.c:590  "text/plain"
(remote-viewer:25004): GSpice-DEBUG: 11:18:54.329: ../src/decode-glz.c:349 decode_header: 642x156, id 15, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:57.358: ../src/decode-glz.c:349 decode_header: 642x410, id 16, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:18:57.362: ../src/decode-glz.c:95 glz_decoder_window_resize: array resize 16 -> 32
(remote-viewer:25004): GSpice-DEBUG: 11:19:00.441: ../src/decode-glz.c:349 decode_header: 642x410, id 17, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:03.333: ../src/decode-glz.c:349 decode_header: 158x24, id 18, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:03.387: ../src/decode-glz.c:349 decode_header: 642x156, id 19, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:06.404: ../src/decode-glz.c:349 decode_header: 642x156, id 20, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:09.434: ../src/decode-glz.c:349 decode_header: 642x410, id 21, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:12.451: ../src/decode-glz.c:349 decode_header: 642x410, id 22, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:15.469: ../src/decode-glz.c:349 decode_header: 642x410, id 23, ref 0
(remote-viewer:25004): GSpice-DEBUG: 11:19:17.171: ../src/spice-gtk-session.c:156 inputs-3:0: client_modifiers:0x0, guest_modifiers:0x0
^C

Comment 10 Dr. David Alan Gilbert 2019-09-06 17:25:33 UTC

Hi Victor,
  David B suggested you could parse the log file in the previous comment;  it's a remote viewer connected after a migrate and it's sitting there
showing the 'connected' message but not actually drawn anything in the guest (not even a black screen).
Anything that looks badly wrong?
Can you suggest what spice debug would be good to turn on in qemu?

Comment 11 Victor Toso 2019-09-09 08:36:07 UTC

Hi David,

> it's a remote viewer connected after a migrate and it's sitting there showing the 'connected'
> message but not actually drawn anything in the guest (not even a black screen).
> Anything that looks badly wrong?

 | GSpice-DEBUG: 11:18:09.275: ../src/channel-display.c:1975 display-2:0: received empty monitor config

With empty monitors we don't have anything to update. I think this is not usual, unless it is a temporary state. I'm unsure because this is RHEL6 guest and the monitor's config path is different between RHEL6 and RHEL7/RHEL8 depending on configuration of host for video. A expected output would be

 | GSpice-DEBUG: 10:22:31.923: ../src/channel-display.c:2038 display-2:0: received new monitors config from guest: n: 1/1

Weird thing is that you seem to be interacting with the host/guest just fine.

> Can you suggest what spice debug would be good to turn on in qemu?

Just the usual spice server log from both hosts, G_MESSAGES_DEBUG=all should work fine in RHEL8.

--

Connection while on migration and the original scenario from comment #0 could trigger different bugs, I guess. Based on "can reproduce it using vnc:0 -vga qxl" I'm not sure it is client releated but perhaps worth to test the scratch build below that fix a different scenario where remote-viewer was hanging too.

https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=23415379

Comment 12 Dr. David Alan Gilbert 2019-09-09 17:36:16 UTC

Created attachment 1613276 [details]
Log file from source

Comment 13 Dr. David Alan Gilbert 2019-09-09 17:37:19 UTC

Created attachment 1613277 [details]
Log file from dest

Attached src/dst log files.
Not tried new spice-gtk yet; just building myself a f30 version.
(RHEL8 src/dst, migration; my laptop where I'm running the viewer is f30)

Comment 14 Dr. David Alan Gilbert 2019-09-09 17:51:23 UTC

Modified client didn't seem to help.
Observation: Where previously it only failed sometimes, at the moment it failed 2 out of 2;
Is this turning G_MESSAGE_DEBUG=all changed the timing a bit??

Comment 15 Dr. David Alan Gilbert 2019-09-09 18:58:32 UTC

bp on marshall_monitors_config on destination:
(gdb) bt full
#0  0x00007f38ff6fce84 in marshall_monitors_config (monitors_config=0x7f37c4005e90, base_marshaller=0x7f37c402a690, rcc=0x7f37c402a610) at dcc-send.c:2288
        heads_size = 0
        i = <optimized out>
        msg = <optimized out>
        count = <optimized out>
        monconf_item = <optimized out>
        dcc = 0x7f37c402a610
        m = 0x7f37c402a690
        __FUNCTION__ = "dcc_send_item"
#1  0x00007f38ff6fce84 in dcc_send_item (rcc=0x7f37c402a610, pipe_item=<optimized out>) at dcc-send.c:2445
        monconf_item = <optimized out>
        dcc = 0x7f37c402a610
        m = 0x7f37c402a690
        __FUNCTION__ = "dcc_send_item"
#2  0x00007f38ff71da6a in red_channel_client_send_item (item=0x7f37c4027de0, rcc=0x7f37c402a610) at red-channel-client.c:613
        __FUNCTION__ = "red_channel_client_send_item"
        pipe_item = 0x7f37c4027de0
#3  0x00007f38ff71da6a in red_channel_client_push (rcc=0x7f37c402a610) at red-channel-client.c:1324
        pipe_item = 0x7f37c4027de0
#4  0x00007f38ff71da6a in red_channel_client_push (rcc=0x7f37c402a610) at red-channel-client.c:1303
#5  0x00007f38ff71dc0d in red_channel_client_event (fd=<optimized out>, event=<optimized out>, data=<optimized out>) at red-channel-client.c:828
        rcc = 0x7f37c402a610
#6  0x00007f38ff70579f in watch_func (source=<optimized out>, condition=<optimized out>, data=0x7f37c4059a30) at event-loop.c:119
        watch = 0x7f37c4059a30
        fd = <optimized out>
#7  0x00007f390234567d in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#8  0x00007f3902345a48 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#9  0x00007f3902345d72 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#10 0x00007f38ff73347b in red_worker_main (arg=0x5590913d5aa0) at red-worker.c:1139
        worker = 0x5590913d5aa0
        __FUNCTION__ = "red_worker_main"
        loop = 0x7f37c4002530
#11 0x00007f38fd85d2de in start_thread () at /lib64/libpthread.so.0
#12 0x00007f38fd58e2e3 in clone () at /lib64/libc.so.6
(gdb) where
#0  0x00007f38ff6fce84 in marshall_monitors_config (monitors_config=0x7f37c4005e90, base_marshaller=0x7f37c402a690, rcc=0x7f37c402a610) at dcc-send.c:2288
#1  0x00007f38ff6fce84 in dcc_send_item (rcc=0x7f37c402a610, pipe_item=<optimized out>) at dcc-send.c:2445
#2  0x00007f38ff71da6a in red_channel_client_send_item (item=0x7f37c4027de0, rcc=0x7f37c402a610) at red-channel-client.c:613
#3  0x00007f38ff71da6a in red_channel_client_push (rcc=0x7f37c402a610) at red-channel-client.c:1324
#4  0x00007f38ff71da6a in red_channel_client_push (rcc=0x7f37c402a610) at red-channel-client.c:1303
#5  0x00007f38ff71dc0d in red_channel_client_event (fd=<optimized out>, event=<optimized out>, data=<optimized out>) at red-channel-client.c:828
#6  0x00007f38ff70579f in watch_func (source=<optimized out>, condition=<optimized out>, data=0x7f37c4059a30) at event-loop.c:119
#7  0x00007f390234567d in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#8  0x00007f3902345a48 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#9  0x00007f3902345d72 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#10 0x00007f38ff73347b in red_worker_main (arg=0x5590913d5aa0) at red-worker.c:1139
#11 0x00007f38fd85d2de in start_thread () at /lib64/libpthread.so.0
#12 0x00007f38fd58e2e3 in clone () at /lib64/libc.so.6
(gdb) list
2283	in dcc-send.c
(gdb) up
#1  dcc_send_item (rcc=0x7f37c402a610, pipe_item=<optimized out>) at dcc-send.c:2445
2445	in dcc-send.c
(gdb) list
2440	in dcc-send.c
(gdb) down
#0  marshall_monitors_config (monitors_config=0x7f37c4005e90, base_marshaller=0x7f37c402a690, rcc=0x7f37c402a610) at dcc-send.c:2288
2288	in dcc-send.c
(gdb) list
2283	in dcc-send.c
(gdb) p monitors_config
$1 = (MonitorsConfig *) 0x7f37c4005e90
(gdb) p *monitors_config
$2 = {refs = 2, count = 0, max_allowed = 0, heads = 0x7f37c4005e9c}
(gdb) p monitors_config->heads
$3 = 0x7f37c4005e9c
(gdb) p *monitors_config->heads
$4 = {id = 0, surface_id = 1852793632, width = 6777190, height = 37, x = 0, y = 0, flags = 0}

Comment 16 Dr. David Alan Gilbert 2019-09-09 19:04:26 UTC

I see there's some recent changes in that area in qxl_spice_monitors_config_async in qemu

be812c0 from Lukas changes it to use a newer interface; I'll see what happens if I forcibly revert that and play around in there.

Comment 17 Dr. David Alan Gilbert 2019-09-10 13:54:28 UTC

At the moment I can reproduce this failure much more simply; no migration involved:

   a) Start qemu, let it boot
   b) connect remote-viewer
   c) close remote-viewer
   d) Reconnect remote-viewer

the thing is I can see a :

qemu-system-x86_64: info: Spice: display-channel.c:179:monitors_config_unref: freeing monitors config
qemu-system-x86_64: info: Spice: display-channel.c:187:monitors_config_debug: monitors config count:1 max:1
qemu-system-x86_64: info: Spice: display-channel.c:191:monitors_config_debug: head #0 +0+0 1024x768
qemu-system-x86_64: info: Spice: display-channel.c:179:monitors_config_unref: freeing monitors config
qemu-system-x86_64: info: Spice: display-channel.c:187:monitors_config_debug: monitors config count:0 max:0
qemu-system-x86_64: info: Spice: display-channel.c:179:monitors_config_unref: freeing monitors config
qemu-system-x86_64: info: Spice: display-channel.c:187:monitors_config_debug: monitors config count:0 max:0

even before the disconnection of the client; so I think that's already confused?

Comment 18 Dr. David Alan Gilbert 2019-09-10 16:58:12 UTC

Hi Jingzhao,
  If I change:
      -device qxl-vga,id=video0,ram_size=134217728,vram_size=67108864,vgamem_mb=16,bus=pci.0 \
to
     -device qxl-vga,id=video0,ram_size=134217728,vram_size=67108864,vgamem_mb=16,bus=pci.0,max_outputs=1 \

the bug goes away for me; can you confirm that also fixes it for you?

Comment 19 Dr. David Alan Gilbert 2019-09-10 17:35:17 UTC

(Observation: Running a RHEL8 guest instead, remote-viewer prints:
MonitorConfig max_allowed is not within permitted range, clamping

and the value it has is 0)

Comment 20 Dr. David Alan Gilbert 2019-09-10 18:48:11 UTC

I'm tempted to change qemu to default max_outputs=1 as default instead of 0 - is that ever bad?

Comment 21 Dr. David Alan Gilbert 2019-09-17 17:31:09 UTC

Maybe unrelated, but nother upstream bug related to monitor configs: https://bugs.launchpad.net/qemu/+bug/1843151

Comment 22 Dr. David Alan Gilbert 2019-09-17 18:03:37 UTC

Reverting qemu's be812c0  seems to fix this for me.

commit be812c0ab7d5ab741d0d87387a75a0e8bb6461e7
Author: Lukáš Hrázký <lhrazky>
Date:   Fri Feb 15 16:09:19 2019 +0100

    spice: set device address and device display ID in QXL interface

Comment 23 Dr. David Alan Gilbert 2019-09-17 18:28:15 UTC

Hi Lukáš,
  It looks like reverting your patch fixes this and the upstream bug I mention in comment 21 - any ideas?

Comment 24 Dr. David Alan Gilbert 2019-09-17 19:01:04 UTC

Specifically I think if I remove the call in qxl_realize_common to  spice_qxl_set_device_info, I think it fixes it.

Comment 25 Lukáš Hrázký 2019-09-18 11:30:48 UTC

Hello David,

the memory is hazy. So I think since this is (AFAIU) only happening with RHEL6 guest, it must be a difference in the QXL driver, where IIRC there were changes on how multiple monitors and the max_outputs number was handled. As my guesses grow wilder, maybe the qxl->max_outputs that's being passed to spice_qxl_set_device_info() in the patch is 0 and that could effectively be telling spice there are no monitors?

If you've got the setup to test it, could you try to find out what is being passed to SPICE in that call to spice_qxl_set_device_info() when it's working and when it isn't and compare the two? That might be enough to figure out what to do about it.

HTH

Comment 26 Dr. David Alan Gilbert 2019-09-18 13:17:22 UTC

For both my rhel6 & rhel8 guest I'm seeing:

qxl_realize_common: pre set-device-info device_address=pci/0000/03.0 max_outputs=0

but see comment #19 where I get a warning with a rhel8 guest but it doesn't cause a problem

Note that the old code in qxl_spice_monitors_config_async that calls spice_qxl_set_max_monitors is guarded with
a 'if (qxl->max_outputs) {'

perhaps this is why!

Comment 27 Lukáš Hrázký 2019-09-18 13:43:29 UTC

> but see comment #19 where I get a warning with a rhel8 guest but it doesn't cause a problem

I'll assume that you don't get that warning with a rhel6 guest then.

So, another wild guess, there's some fail-safe mechanism on the SPICE side that kicks in for RHEL8 when max_monitors is 0 and doesn't kick in for RHEL6, which is a bit strange.

On the other hand (assuming the 0 is the cause for the rest of the post), the question that we should ask is probably what does the max_outputs variable mean and what does it mean when it's 0? My memory fails me here, I can't remember the exact semantics anymore. For the case it is 0, does it mean unlimited? It seems to me SPICE interprets 0 as literal 0 and I think SPICE actually needs a positive upper limit on the number of monitors so that it knows how many monitors the user can turn on.

Under that reasoning QEMU shouldn't pass 0 to SPICE (unless it expects to have 0 monitors), it should pass an actual number. You should definitely confirm this with the SPICE team, but I think passing either 1 or 4 as the default when max_outputs is not set by the user might be the right thing to do?

Comment 28 Dr. David Alan Gilbert 2019-09-18 14:12:00 UTC

OK, so lets ask Victor what the spice team would like us to do.

Victor: So what do you reckon we should do in our default case where no one has told us the number of outputs and our default is 0;
Lukas's newer code calls 'spice_qxl_set_device_info' to set both the path and the number of outputs in one go even if the number
of outputs is our default 0; where as the old code that called spice_qxl_set_max_monitors used to avoid calling that if we
had 0.  I guess Lukas really still wants to set the device path/name - but we don't have a max_outputs to play with.

Also; I don't think this is urgent, because modern libvirt's set max_outputs by default; so we should be OK.

Comment 29 Victor Toso 2019-09-19 09:21:15 UTC

So, just to clarify again:
* Old code path in QEMU uses spice_qxl_set_max_monitors(), that does allow but ignores a 0 value as it is implemented with MAX(1u, max_monitors)
* Old code path in QEMU also had a small check on max_monitor == 0 and would not call spice_qxl_set_max_monitors() in that case
* New code path in QEMU uses spice_qxl_set_device_info(), that does allow set QXLInstance's max_monitors to 0.
* New code path in QEMU does not check that we have max_monitor == 0.
* RHEL 6 monitor's configuration uses spice's guest agent but that changed in RHEL 7 (this is a client <-> agent message actually!)

I would ask Gerd/Frediano, around different configuration scenarios that might be in QEMU if we should allow max monitors to be 0 and handle that in spice better or adding a guard in spice and checks in QEMU to avoid this to happen based on configuration too.

> Also; I don't think this is urgent, because modern libvirt's set max_outputs by default; so we should be OK.

So we can have a nice tech discussion about it, if needed! Thanks and sorry.
I'll set info to Gerd and ping Frediano.

Comment 30 Frediano Ziglio 2019-09-19 10:19:09 UTC

Propose a patch, see https://lists.freedesktop.org/archives/spice-devel/2019-September/050859.html

Comment 31 Dr. David Alan Gilbert 2019-09-19 11:06:55 UTC

Thanks; that worked nicely with a postcopy.

Comment 32 Dr. David Alan Gilbert 2019-09-19 11:09:05 UTC

OK, flipped to rhel/spice

Comment 33 Dr. David Alan Gilbert 2019-09-19 11:23:13 UTC

*** Bug 1692225 has been marked as a duplicate of this bug. ***

Comment 46 errata-xmlrpc 2020-11-04 04:07:31 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (spice bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2020:4818

Note You need to log in before you can comment on or make changes to this bug.