Hi Chao,
  That's interesting - we've had a similar backtrace a few times; bz 1515730 is similar.  But then the bug disappears for a time.

Do you have to do the upgrade/downgrade to cause it to fail?

Christophe: Apparently repeatable version of bz 1515730 ??

(In reply to Dr. David Alan Gilbert from comment #3)
> Hi Chao,
>   That's interesting - we've had a similar backtrace a few times; bz 1515730
> is similar.  But then the bug disappears for a time.
> 
> Do you have to do the upgrade/downgrade to cause it to fail?

Hi David,

Retried several times, reproducible to me when starting migration right after inputting password. The upgrade/downgrade scenario involves rebooting guest too, it actually aborts when migrating right after providing password to the guest.


If I test migration after logging to guest, the ping pong migration only triggers to me the following log, but the guest works fine.

(qemu) red_qxl_loadvm_commands: 
id 0, group 0, virt start 0, virt end ffffffffffffffff, generation 0, delta 0
id 1, group 1, virt start 7fb7c3c00000, virt end 7fb7c7bfe000, generation 0, delta 7fb7c3c00000
id 2, group 1, virt start 7fb7bfa00000, virt end 7fb7c3a00000, generation 0, delta 7fb7bfa00000

(process:30092): Spice-WARNING **: memslot.c:68:memslot_validate_virt: virtual address out of range
    virt=0x4+0x2a slot_id=0 group_id=1
    slot=0x0-0x0 delta=0x0

(process:30092): Spice-WARNING **: red-worker.c:1004:handle_dev_loadvm_commands: failed loadvm command type (3)

And such abort happens too with spice-server-0.14.0-1.el7.x86_64

Is the driver upgrade/downgrade needed to trigger it or is doing a reboot enough?

(In reply to Gerd Hoffmann from comment #7)
> Is the driver upgrade/downgrade needed to trigger it or is doing a reboot
> enough?

Doing a reboot and migrating guest immediately after inputting password to login windows are enough to trigger the issue.

generation != slot->generation //generation=1 while slot.generation=0
in /usr/src/debug/spice-0.14.0/server/memslot.c is true when triggering above abort.

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

build with some debug logging (guest_cursor updates) added.

Please try reproduce the bug with that build.  Add qemu stderr (both source and target) and stacktrace of all threads ("thread apply all bt" in gdb) to this bug.

Hi xiangchun, could you please arrange the reproduce with the build in comment#10? Thanks.

Created attachment 1400765 [details]
logs when coredump happened

(In reply to Gerd Hoffmann from comment #10)
> https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=15270109
> 
> build with some debug logging (guest_cursor updates) added.
> 
> Please try reproduce the bug with that build.  Add qemu stderr (both source
> and target) and stacktrace of all threads ("thread apply all bt" in gdb) to
> this bug.

I have attached what you wanted, please take a look.

source cursor tracking:

qxl_spice_reset_cursor: guest_cursor 0x0
qxl_spice_reset_cursor: guest_cursor 0x0
qxl_track_command: guest_cursor 0x0
qxl_track_command: guest_cursor 0x1000000010016f4

target cursor tracking:

qxl_spice_reset_cursor: guest_cursor 0x0
qxl_spice_reset_cursor: guest_cursor 0x0
qxl_spice_reset_cursor: guest_cursor 0x0
qxl_post_load: guest_cursor 0x1000000010016f4

So that looks fine.

Thread 4 is in qxl post_load:

[ ... ]
#6  0x00007f18ae07b600 in spice_qxl_loadvm_commands (instance=instance@entry=0x5565a6c62970, ext=ext@entry=0x5565a7b96000, count=count@entry=1) at red-qxl.c:727
#7  0x00005565a2de198d in qxl_spice_loadvm_commands (qxl=qxl@entry=0x5565a6c62000, ext=ext@entry=0x5565a7b96000, count=count@entry=1)
    at hw/display/qxl.c:220
#8  0x00005565a2de21c4 in qxl_post_load (opaque=0x5565a6c62000, version=<optimized out>) at hw/display/qxl.c:2296
#9  0x00005565a2e542a7 in vmstate_load_state (f=0x5565a7a76000, vmsd=0x5565a3501980 <qxl_vmstate>, opaque=0x5565a6c62000, version_id=21) at migration/vmstate.c:165
[ ... ]

And thread 1 is the one where spice throws a core:

#0  0x00007f18abf231d7 in raise () at /lib64/libc.so.6
#1  0x00007f18abf248d0 in abort () at /lib64/libc.so.6
#2  0x00007f18ae0a845c in spice_log (log_domain=0x7f18ae119311 "Spice", args=0x7f1797dfe520, format=0x7f18ae12051b "slot_id %d too big, addr=%lx", function=0x7f18ae120650 <__FUNCTION__.15662> "memslot_get_virt", strloc=0x7f18ae120538 "memslot.c:111", log_level=
    G_LOG_LEVEL_CRITICAL) at log.c:183
#3  0x00007f18ae0a845c in spice_log (log_level=log_level@entry=
    G_LOG_LEVEL_CRITICAL, strloc=strloc@entry=0x7f18ae120538 "memslot.c:111", function=function@entry=0x7f18ae120650 <__FUNCTION__.15662> "memslot_get_virt", format=format@entry=0x7f18ae12051b "slot_id %d too big, addr=%lx") at log.c:196
#4  0x00007f18ae06f4b6 in memslot_get_virt (info=info@entry=0x5565a5c0f750, addr=addr@entry=16110501767011106816, add_size=add_size@entry=20, group_id=group_id@entry=1, error=error@entry=0x7f1797dfe694) at memslot.c:111
#5  0x00007f18ae077c47 in red_get_data_chunks_ptr (slots=slots@entry=0x5565a5c0f750, group_id=group_id@entry=1, memslot_id=223, red=red@entry=0x7f1797dfe6f0, qxl=0x7f179864df7a) at red-parse-qxl.c:145
#6  0x00007f18ae07a2ee in red_get_cursor_cmd (addr=144115188084563812, red=0x5565a5c4e560, group_id=1, slots=0x5565a5c0f750)
    at red-parse-qxl.c:1440
#7  0x00007f18ae07a2ee in red_get_cursor_cmd (slots=slots@entry=0x5565a5c0f750, group_id=1, red=red@entry=0x5565a5c4e540, addr=<optimized out>) at red-parse-qxl.c:1481
#8  0x00007f18ae08acdf in red_process_cursor_cmd (worker=worker@entry=0x5565a5c0f6c0, ext=ext@entry=0x5565a7b96000) at red-worker.c:111
#9  0x00007f18ae08ae7b in handle_dev_loadvm_commands (ext=0x5565a7b96000, worker=0x5565a5c0f6c0) at red-worker.c:980
#10 0x00007f18ae08ae7b in handle_dev_loadvm_commands (opaque=0x5565a5c0f6c0, payload=<optimized out>) at red-worker.c:1002
[ ... ]

So the pointer to the cursor command is valid.  Then spice tries to follow the data chunk pointer for the actual pointer image, finds an invalid qxl pointer there, then aborts().

This looks like the guest driver has overwritten the cursor command before disabling or changing the cursor.  So when qxl tries to replay the command on the target machine to set the correct cursor spice finds only garbage there.

Adema, what is the component for the windows qxl drivers?

(In reply to Gerd Hoffmann from comment #18)
> This looks like the guest driver has overwritten the cursor command before
> disabling or changing the cursor.  So when qxl tries to replay the command
> on the target machine to set the correct cursor spice finds only garbage
> there.
> 
> Ademar, what is the component for the windows qxl drivers?

I think it's virtio-win. Amnon?

Please try this build of qxl-wddm-dod driver for win10:
http://file01.intranet.prod.int.rdu2.redhat.com/~ybendito/qxldod/Trials/bz1540919/spice-qxl-wddm-dod-0.0.18.002.zip
(the same on https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=15509375)
This build of the driver allocates cursor payload from DEVRAM bar (regular driver allocates cursor command from DEVRAM, but payload is allocated from VRAM bar)

(In reply to ybendito from comment #22)
> Please try this build of qxl-wddm-dod driver for win10:
> http://file01.intranet.prod.int.rdu2.redhat.com/~ybendito/qxldod/Trials/
> bz1540919/spice-qxl-wddm-dod-0.0.18.002.zip
> (the same on
> https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=15509375)
> This build of the driver allocates cursor payload from DEVRAM bar (regular
> driver allocates cursor command from DEVRAM, but payload is allocated from
> VRAM bar)

Still reproducible

Thread 6 (Thread 0x7f82f5c47b40 (LWP 25519)):
#0  0x00007f82f2c0a76d in read () at /lib64/libpthread.so.0
#1  0x00007f82ec00bc93 in read_safe (__nbytes=4, __buf=0x5585331dfc24, __fd=24) at /usr/include/bits/unistd.h:44
#2  0x00007f82ec00bc93 in read_safe (fd=fd@entry=24, buf=buf@entry=0x5585331dfc24 "", size=size@entry=4, block=1) at dispatcher.c:214
#3  0x00007f82ec00c441 in dispatcher_send_message (block=1, size=4, buf=0x5585331dfc24 "", fd=24) at dispatcher.c:340
#4  0x00007f82ec00c441 in dispatcher_send_message (dispatcher=0x5585330af0a0, message_type=message_type@entry=25, payload=payload@entry=0x5585331dfc60) at dispatcher.c:330
#5  0x00007f82ec02fd6e in red_qxl_loadvm_commands (ext=ext@entry=0x558533568000, count=1, qxl_state=<optimized out>) at red-qxl.c:614
#6  0x00007f82ec030600 in spice_qxl_loadvm_commands (instance=instance@entry=0x5585336ca6f8, ext=ext@entry=0x558533568000, count=<optimized out>) at red-qxl.c:727
#7  0x0000558530fa7f5d in qxl_spice_loadvm_commands (qxl=qxl@entry=0x5585336ca000, ext=ext@entry=0x558533568000, count=<optimized out>)
    at /usr/src/debug/qemu-1.5.3/hw/display/qxl.c:215
#8  0x0000558530fa8768 in qxl_post_load (opaque=0x5585336ca000, version=<optimized out>)
    at /usr/src/debug/qemu-1.5.3/hw/display/qxl.c:2284
#9  0x0000558530fe42a0 in vmstate_load_state (f=0x558533576000, vmsd=0x5585314826c0 <qxl_vmstate>, opaque=0x5585336ca000, version_id=21) at /usr/src/debug/qemu-1.5.3/savevm.c:1939
#10 0x0000558530fe4e56 in qemu_loadvm_state (f=f@entry=0x558533576000) at /usr/src/debug/qemu-1.5.3/savevm.c:2498
#11 0x0000558530f1b25e in process_incoming_migration_co (opaque=0x558533576000) at migration.c:105
#12 0x0000558530e7c1ca in coroutine_trampoline (i0=<optimized out>, i1=<optimized out>) at coroutine-ucontext.c:118
#13 0x00007f82eb29cfa0 in __start_context () at /lib64/libc.so.6
#14 0x00007fff9135b160 in  ()
#15 0x0000000000000000 in  ()

Thread 5 (Thread 0x7f82df0c2700 (LWP 25531)):
#0  0x00007f82f2c078f5 in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x000055853108c9c9 in qemu_cond_wait (cond=<optimized out>, mutex=mutex@entry=0x5585318b2720 <qemu_global_mutex>)
    at util/qemu-thread-posix.c:116
#2  0x0000558530f861db in qemu_kvm_cpu_thread_fn (env=0x55853358c110) at /usr/src/debug/qemu-1.5.3/cpus.c:770
#3  0x0000558530f861db in qemu_kvm_cpu_thread_fn (arg=0x55853358c110) at /usr/src/debug/qemu-1.5.3/cpus.c:807
#4  0x00007f82f2c03dd5 in start_thread () at /lib64/libpthread.so.0
#5  0x00007f82eb3539bd in clone () at /lib64/libc.so.6
---Type <return> to continue, or q <return> to quit---

Thread 4 (Thread 0x7f82de0c0700 (LWP 25535)):
#0  0x00007f82f2c078f5 in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x000055853108c9c9 in qemu_cond_wait (cond=<optimized out>, mutex=mutex@entry=0x5585318b2720 <qemu_global_mutex>)
    at util/qemu-thread-posix.c:116
#2  0x0000558530f861db in qemu_kvm_cpu_thread_fn (env=0x5585335b0110) at /usr/src/debug/qemu-1.5.3/cpus.c:770
#3  0x0000558530f861db in qemu_kvm_cpu_thread_fn (arg=0x5585335b0110) at /usr/src/debug/qemu-1.5.3/cpus.c:807
#4  0x00007f82f2c03dd5 in start_thread () at /lib64/libpthread.so.0
#5  0x00007f82eb3539bd in clone () at /lib64/libc.so.6

Thread 3 (Thread 0x7f82df8c3700 (LWP 25530)):
#0  0x00007f82f2c078f5 in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x000055853108c9c9 in qemu_cond_wait (cond=<optimized out>, mutex=mutex@entry=0x5585318b2720 <qemu_global_mutex>)
    at util/qemu-thread-posix.c:116
#2  0x0000558530f861db in qemu_kvm_cpu_thread_fn (env=0x558533556110) at /usr/src/debug/qemu-1.5.3/cpus.c:770
#3  0x0000558530f861db in qemu_kvm_cpu_thread_fn (arg=0x558533556110) at /usr/src/debug/qemu-1.5.3/cpus.c:807
#4  0x00007f82f2c03dd5 in start_thread () at /lib64/libpthread.so.0
#5  0x00007f82eb3539bd in clone () at /lib64/libc.so.6

Thread 2 (Thread 0x7f82de8c1700 (LWP 25533)):
#0  0x00007f82f2c078f5 in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x000055853108c9c9 in qemu_cond_wait (cond=<optimized out>, mutex=mutex@entry=0x5585318b2720 <qemu_global_mutex>)
    at util/qemu-thread-posix.c:116
#2  0x0000558530f861db in qemu_kvm_cpu_thread_fn (env=0x55853359e110) at /usr/src/debug/qemu-1.5.3/cpus.c:770
#3  0x0000558530f861db in qemu_kvm_cpu_thread_fn (arg=0x55853359e110) at /usr/src/debug/qemu-1.5.3/cpus.c:807
#4  0x00007f82f2c03dd5 in start_thread () at /lib64/libpthread.so.0
#5  0x00007f82eb3539bd in clone () at /lib64/libc.so.6

Thread 1 (Thread 0x7f81d51ff700 (LWP 25551)):
#0  0x00007f82eb28b1d7 in raise () at /lib64/libc.so.6
#1  0x00007f82eb28c8d0 in abort () at /lib64/libc.so.6
#2  0x00007f82ec05d45c in spice_log (log_domain=0x7f82ec0ce311 "Spice", args=0x7f81d51fe750, format=0x7f82ec0d5450 "address generation i---Type <return> to continue, or q <return> to quit---
s not valid, group_id %d, slot_id %d, gen %d, slot_gen %d\n", function=0x7f82ec0d5650 <__FUNCTION__.15662> "memslot_get_virt", strloc=0x7f82ec0d5546 "memslot.c:122", log_level=G_LOG_LEVEL_CRITICAL) at log.c:183
#3  0x00007f82ec05d45c in spice_log (log_level=log_level@entry=
    G_LOG_LEVEL_CRITICAL, strloc=strloc@entry=0x7f82ec0d5546 "memslot.c:122", function=function@entry=0x7f82ec0d5650 <__FUNCTION__.15662> "memslot_get_virt", format=format@entry=0x7f82ec0d5450 "address generation is not valid, group_id %d, slot_id %d, gen %d, slot_gen %d\n") at log.c:196
#4  0x00007f82ec0243df in memslot_get_virt (info=info@entry=0x55853354c410, addr=addr@entry=487083651217665, add_size=add_size@entry=42, group_id=group_id@entry=1, error=error@entry=0x7f81d51fe8ac) at memslot.c:121
#5  0x00007f82ec02f282 in red_get_cursor_cmd (addr=487083651217665, red=0x558533548380, group_id=1, slots=0x55853354c410)
    at red-parse-qxl.c:1426
#6  0x00007f82ec02f282 in red_get_cursor_cmd (slots=slots@entry=0x55853354c410, group_id=1, red=red@entry=0x558533548360, addr=<optimized out>) at red-parse-qxl.c:1481
#7  0x00007f82ec03fcdf in red_process_cursor_cmd (worker=worker@entry=0x55853354c380, ext=ext@entry=0x558533568000) at red-worker.c:111
#8  0x00007f82ec03fe7b in handle_dev_loadvm_commands (ext=0x558533568000, worker=0x55853354c380) at red-worker.c:980
#9  0x00007f82ec03fe7b in handle_dev_loadvm_commands (opaque=0x55853354c380, payload=<optimized out>) at red-worker.c:1002
#10 0x00007f82ec00c29d in dispatcher_handle_recv_read (dispatcher=0x5585330af0a0) at dispatcher.c:284
#11 0x00007f82ec00c29d in dispatcher_handle_recv_read (dispatcher=0x5585330af0a0) at dispatcher.c:304
#12 0x00007f82ec012aab in watch_func (source=<optimized out>, condition=<optimized out>, data=0x5585330270b0) at event-loop.c:128
#13 0x00007f82f3e798f9 in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#14 0x00007f82f3e79c58 in g_main_context_iterate.isra.22 () at /lib64/libglib-2.0.so.0
#15 0x00007f82f3e79f2a in g_main_loop_run () at /lib64/libglib-2.0.so.0
#16 0x00007f82ec040f2a in red_worker_main (arg=0x55853354c380) at red-worker.c:1372
#17 0x00007f82f2c03dd5 in start_thread () at /lib64/libpthread.so.0
#18 0x00007f82eb3539bd in clone () at /lib64/libc.so.6

(In reply to Gerd Hoffmann from comment #18)

> So the pointer to the cursor command is valid.  Then spice tries to follow
> the data chunk pointer for the actual pointer image, finds an invalid qxl
> pointer there, then aborts().
> 
> This looks like the guest driver has overwritten the cursor command before
> disabling or changing the cursor.  So when qxl tries to replay the command
> on the target machine to set the correct cursor spice finds only garbage
> there.

There might be different expectations between QEMU and SPICE here. What spice-server 0.14 (haven't checked 0.12 carefully yet) is doing is:
- call QXLInterface::get_command()
- when it's a QXL_CURSOR_SET command, it sends the cursor data to the guest
- as soon as this is done, it calls QXLInterface::release_resource() as it has successfully processed the cursor data
- this causes QEMU to put that cursor data on the QXL device release ring, which instructs the guest that it can reuse that data

QEMU on the other hand is keeping a pointer to that cursor data when QXLInterface::get_command() is called and it detects a QXL_CURSOR_SET command.
It will reuse that cursor data for migration purpose and it expects it will still be valid until another QXL_CURSOR_SET or a QXL_CURSOR_HIDE command comes through.
Implementing such a delay in spice-server fixes the bug I've been looking at, however since it's QEMU which wants to keep a pointer to that data, I would argue it's up to QEMU to make a copy or ensure it does not get freed too early.
I'm currently trying to write a QEMU patch for that.

(In reply to Christophe Fergeau from comment #24)
> QEMU on the other hand is keeping a pointer to that cursor data when
> QXLInterface::get_command() is called and it detects a QXL_CURSOR_SET
> command.
> It will reuse that cursor data for migration purpose and it expects it will
> still be valid until another QXL_CURSOR_SET or a QXL_CURSOR_HIDE command
> comes through.
> Implementing such a delay in spice-server fixes the bug I've been looking
> at, however since it's QEMU which wants to keep a pointer to that data, I
> would argue it's up to QEMU to make a copy or ensure it does not get freed
> too early.
> I'm currently trying to write a QEMU patch for that.

Actually, SPICE used to be doing this until https://cgit.freedesktop.org/spice/spice/commit/?id=1c6e7cf7 which is v0.13.91~74. RHEL 7.4 has spice-server 0.12.8 while 7.5 was rebased to 0.14.0, which explains why this bug reappeared.

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

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

(In reply to Christophe Fergeau from comment #25)
> (In reply to Christophe Fergeau from comment #24)
> > QEMU on the other hand is keeping a pointer to that cursor data when
> > QXLInterface::get_command() is called and it detects a QXL_CURSOR_SET
> > command.
> > It will reuse that cursor data for migration purpose and it expects it will
> > still be valid until another QXL_CURSOR_SET or a QXL_CURSOR_HIDE command
> > comes through.
> > Implementing such a delay in spice-server fixes the bug I've been looking
> > at, however since it's QEMU which wants to keep a pointer to that data, I
> > would argue it's up to QEMU to make a copy or ensure it does not get freed
> > too early.
> > I'm currently trying to write a QEMU patch for that.
> 
> Actually, SPICE used to be doing this until
> https://cgit.freedesktop.org/spice/spice/commit/?id=1c6e7cf7 which is
> v0.13.91~74. RHEL 7.4 has spice-server 0.12.8 while 7.5 was rebased to
> 0.14.0, which explains why this bug reappeared.

To be precise that patch releases the cursor resources earlier (just after the memory is no more needed by spice-server) so instead of:

- call QXLInterface::get_command()
- when it's a QXL_CURSOR_SET command, it sends the cursor data to the guest
- as soon as this is done, it calls QXLInterface::release_resource() as it has successfully processed the cursor data
- this causes QEMU to put that cursor data on the QXL device release ring, which instructs the guest that it can reuse that data

is:

- call QXLInterface::get_command()
- when it's a QXL_CURSOR_SET command, it copies the cursor and calls QXLInterface::release_resource() as it has successfully processed the cursor data
- this causes QEMU to put that cursor data on the QXL device release ring, which instructs the guest that it can reuse that data

so this make the Qemu problem worse. However I agree that if Qemu wants to retain that memory should filter the release_resource, spice-server is calling Qemu to tell Qemu that spice-server does not need the resource anymore which is correct.

Created attachment 1412225 [details]
Proposed QEMU patch

I haven't written a proper commit log yet, but this QEMU patch is what I have in mind (and it survived several test migrations which usually crashed).

(In reply to Christophe Fergeau from comment #29)
> Created attachment 1412225 [details]
> Proposed QEMU patch
> 
> I haven't written a proper commit log yet, but this QEMU patch is what I
> have in mind (and it survived several test migrations which usually crashed).

Looks good as a proof of concept however I would implement some sort of reference counting. Resource should be released if Qemu quest_cursor is 0 AND spice requested the release. If tomorrow we change the spice code to retain the cursor data and maybe cache last 3 cursors we'll have issues again. Also I would consider the code in interface_release_resource a bit hot and I would avoid the expensive qxl_phys2virt call if we have a cursor, is quite likely we have a cursor. You could simply cache the cmd->release_info.id when you set guest_cursor field, at that time you already have the cmd pointer.
Not sure, maybe the check should be if (ext.info == &cmd->release_info)? QXLReleaseInfo is a strange union, not clear when is "id" or when is "next" (from my understanding is "id" when is not released while is "next" after the release).

Created attachment 1413043 [details]
Proposed patch

Trying to implement my proposed improvements, didn't test the patch.

Christophe, can you check the attached patch?

(In reply to Christophe Fergeau from comment #25)
> (In reply to Christophe Fergeau from comment #24)
> > QEMU on the other hand is keeping a pointer to that cursor data when
> > QXLInterface::get_command() is called and it detects a QXL_CURSOR_SET
> > command.
> > It will reuse that cursor data for migration purpose and it expects it will
> > still be valid until another QXL_CURSOR_SET or a QXL_CURSOR_HIDE command
> > comes through.
> > Implementing such a delay in spice-server fixes the bug I've been looking
> > at, however since it's QEMU which wants to keep a pointer to that data, I
> > would argue it's up to QEMU to make a copy or ensure it does not get freed
> > too early.
> > I'm currently trying to write a QEMU patch for that.
> 
> Actually, SPICE used to be doing this until
> https://cgit.freedesktop.org/spice/spice/commit/?id=1c6e7cf7 which is
> v0.13.91~74. RHEL 7.4 has spice-server 0.12.8 while 7.5 was rebased to
> 0.14.0, which explains why this bug reappeared.

Do I understand it correctly, that when QEMU restores the cursor memory it may damage random memory that earlier was related to cursor command?
Is it correct that also before change in spice server 0.14.0 the cursor command may be not valid if the driver retrieved the command from release ring.
There is a fresh issue that might be related to the same problem: 
https://github.com/daynix/qxl-wddm-dod/issues/1
This is crash on guest immediately after VM resume, that seems related to damaged memory in command retrieved from release ring.

(In reply to ybendito from comment #33)
> (In reply to Christophe Fergeau from comment #25)
> > (In reply to Christophe Fergeau from comment #24)
> > > QEMU on the other hand is keeping a pointer to that cursor data when
> > > QXLInterface::get_command() is called and it detects a QXL_CURSOR_SET
> > > command.
> > > It will reuse that cursor data for migration purpose and it expects it will
> > > still be valid until another QXL_CURSOR_SET or a QXL_CURSOR_HIDE command
> > > comes through.
> > > Implementing such a delay in spice-server fixes the bug I've been looking
> > > at, however since it's QEMU which wants to keep a pointer to that data, I
> > > would argue it's up to QEMU to make a copy or ensure it does not get freed
> > > too early.
> > > I'm currently trying to write a QEMU patch for that.
> > 
> > Actually, SPICE used to be doing this until
> > https://cgit.freedesktop.org/spice/spice/commit/?id=1c6e7cf7 which is
> > v0.13.91~74. RHEL 7.4 has spice-server 0.12.8 while 7.5 was rebased to
> > 0.14.0, which explains why this bug reappeared.
> 
> Do I understand it correctly, that when QEMU restores the cursor memory it
> may damage random memory that earlier was related to cursor command?

Not exactly, QEMU + spice-server 0.14.0 has an issue where QEMU keeps a pointer to guest memory (corresponding to a cursor command) even after adding that memory to the guest release ring. The guest can then reuse that memory, and when QEMU tries to reuse the pointer it kept, its content will no longer be a cursor command.

> Is it correct that also before change in spice server 0.14.0 the cursor
> command may be not valid if the driver retrieved the command from release
> ring.

The issue described above could not happen with spice-server 0.12.x. However, QEMU had a related fix last year, dbb5fb8d3 "qxl: clear guest_cursor on QXL_CURSOR_HIDE"

> There is a fresh issue that might be related to the same problem: 
> https://github.com/daynix/qxl-wddm-dod/issues/1
> This is crash on guest immediately after VM resume, that seems related to
> damaged memory in command retrieved from release ring.

Could be related as I think saving/resuming guests is achieved using live migration.

Created attachment 1413720 [details]
Tested patch (unmodified) with commit log

The patch indeed also fixes the bug, the only change compared to your version is the added commit log.

Looking at the mutex usage maybe would be sensible to merge this:


diff --git a/hw/display/qxl.c b/hw/display/qxl.c
index dd168d36c2..de997cf366 100644
--- a/hw/display/qxl.c
+++ b/hw/display/qxl.c
@@ -803,12 +803,15 @@ static void interface_release_resource(QXLInstance *sin,
     /* As long as we keep a reference to the guest cursor data, we don't
      * want the guest to release that memory and potentially reuse it
      */
+    qemu_mutex_lock(&qxl->track_lock);
     if (ext.info == qxl->guest_cursor_release) {
         qxl->guest_cursor_release = NULL;
         if (qxl->guest_cursor != 0) {
+            qemu_mutex_unlock(&qxl->track_lock);
             return;
         }
     }
+    qemu_mutex_unlock(&qxl->track_lock);

     /*
      * ext->info points into guest-visible memory


This check:

    if (old_guest_cursor == 0 || old_guest_cursor_release != NULL) {

is not clear to read, maybe a comment like:

    /* if there is no cursor or was not freed by spice-server do nothing */

Also maybe in

    if (ext.info == qxl->guest_cursor_release) {
        qxl->guest_cursor_release = NULL;
        if (qxl->guest_cursor != 0) {
            return;
        }
    }

a comment like:

    if (ext.info == qxl->guest_cursor_release) {
        /* do not release if we need to retain the cursor but mark as released by spice-server */
        qxl->guest_cursor_release = NULL;
        if (qxl->guest_cursor != 0) {
            return;
        }
    }

Created attachment 1416730 [details]
Potential spice-server patch if we want to revert to the behaviour it had before

If the QEMU patch is too late/too big/too untested for 7.5, we could temporarily go with a spice-server patch such as this one (haven't tested it yet).

For the record, something similar has suddenly appeared in Fedora lately, for Fedora Rawhide guests with qxl / SPICE graphics - no involvement of Windows:

https://bugzilla.redhat.com/show_bug.cgi?id=1565354

Seems hit the issue when executed stable guest abi tesing

src host(7.4):
[root@hp-dl380g9-03 home]# uname -r
3.10.0-693.25.2.el7.x86_64
[root@hp-dl380g9-03 home]# rpm -qa |grep qemu-kvm-rhev
qemu-kvm-rhev-2.9.0-16.el7_4.16.x86_64
qemu-kvm-rhev-debuginfo-2.9.0-16.el7_4.16.x86_64
[root@hp-dl380g9-03 home]# rpm -qa |grep spice
spice-server-0.12.8-2.el7.x86_64
spice-debuginfo-0.12.8-2.el7.x86_64
[root@hp-dl380g9-03 home]# rpm -aq |grep seabios
seabios-bin-1.10.2-3.el7_4.2.noarch
seabios-1.10.2-3.el7_4.2.x86_64

dst host(7.5):
[root@dell-per730-29 home]# rpm -qa |grep qemu-kvm-rhev
qemu-kvm-rhev-2.10.0-21.el7_5.2.x86_64
qemu-kvm-rhev-debuginfo-2.10.0-21.el7_5.2.x86_64
[root@dell-per730-29 home]# uname -r
3.10.0-862.1.1.el7.x86_64
[root@dell-per730-29 home]# rpm -qa |grep seabios
seabios-bin-1.11.0-2.el7.noarch

guest: win2008r2 64 bits

Reproduce steps:
1. Boot guest in the src host (7.4)
2. migrate to the dst host (7.5)
3. reboot guest after migrate finished
4. then migrate guest to 7.4 host again

Actual result:
qemu core dump after step 4

log info:
(gdb) bt
#0  0x00007f8c6ba891f7 in raise () from /lib64/libc.so.6
#1  0x00007f8c6ba8a8e8 in abort () from /lib64/libc.so.6
#2  0x00007f8c6da7f7bc in spice_logv (log_domain=0x7f8c6dafd495 "SpiceWorker", log_level=SPICE_LOG_LEVEL_ERROR, 
    strloc=0x7f8c6dafda86 "red_worker.c:4953", function=0x7f8c6db00570 <__FUNCTION__.34644> "qxl_process_cursor", 
    format=0x7f8c6dafda6c "invalid cursor command %u", args=args@entry=0x7f8a6bffe6e0) at log.c:109
#3  0x00007f8c6da7f905 in spice_log (log_domain=log_domain@entry=0x7f8c6dafd495 "SpiceWorker", 
    log_level=log_level@entry=SPICE_LOG_LEVEL_ERROR, strloc=strloc@entry=0x7f8c6dafda86 "red_worker.c:4953", 
    function=function@entry=0x7f8c6db00570 <__FUNCTION__.34644> "qxl_process_cursor", 
    format=format@entry=0x7f8c6dafda6c "invalid cursor command %u") at log.c:123
#4  0x00007f8c6da436e0 in qxl_process_cursor (worker=0x5603858ee000, cursor_cmd=0x56037f01b5c0, group_id=<optimized out>)
    at red_worker.c:4953
#5  0x00007f8c6da567ed in loadvm_command (ext=0x560381ec6000, worker=0x5603858ee000) at red_worker.c:11870
#6  handle_dev_loadvm_commands (opaque=0x5603858ee000, payload=<optimized out>) at red_worker.c:11897
#7  0x00007f8c6da361d8 in dispatcher_handle_single_read (dispatcher=0x56037f059f68) at dispatcher.c:142
#8  dispatcher_handle_recv_read (dispatcher=0x56037f059f68) at dispatcher.c:165
#9  0x00007f8c6da5d5f5 in red_worker_main (arg=<optimized out>) at red_worker.c:12269
#10 0x00007f8c6be1ee25 in start_thread () from /lib64/libpthread.so.0
#11 0x00007f8c6bb4c34d in clone () from /lib64/libc.so.6


Hi Gerd
  
   Could you double confirm the issue, is it same with comment 0?

Thanks
Jing

(In reply to jingzhao from comment #39)
> 
> Reproduce steps:
> 1. Boot guest in the src host (7.4)
> 2. migrate to the dst host (7.5)
> 3. reboot guest after migrate finished
> 4. then migrate guest to 7.4 host again
> 
> Actual result:
> qemu core dump after step 4
> 
> log info:
> (gdb) bt
> #0  0x00007f8c6ba891f7 in raise () from /lib64/libc.so.6
> #1  0x00007f8c6ba8a8e8 in abort () from /lib64/libc.so.6
> #2  0x00007f8c6da7f7bc in spice_logv (log_domain=0x7f8c6dafd495
> "SpiceWorker", log_level=SPICE_LOG_LEVEL_ERROR, 
>     strloc=0x7f8c6dafda86 "red_worker.c:4953", function=0x7f8c6db00570
> <__FUNCTION__.34644> "qxl_process_cursor", 
>     format=0x7f8c6dafda6c "invalid cursor command %u",
> args=args@entry=0x7f8a6bffe6e0) at log.c:109
> #3  0x00007f8c6da7f905 in spice_log
> (log_domain=log_domain@entry=0x7f8c6dafd495 "SpiceWorker", 
>     log_level=log_level@entry=SPICE_LOG_LEVEL_ERROR,
> strloc=strloc@entry=0x7f8c6dafda86 "red_worker.c:4953", 
>     function=function@entry=0x7f8c6db00570 <__FUNCTION__.34644>
> "qxl_process_cursor", 
>     format=format@entry=0x7f8c6dafda6c "invalid cursor command %u") at
> log.c:123
> #4  0x00007f8c6da436e0 in qxl_process_cursor (worker=0x5603858ee000,
> cursor_cmd=0x56037f01b5c0, group_id=<optimized out>)
>     at red_worker.c:4953
> #5  0x00007f8c6da567ed in loadvm_command (ext=0x560381ec6000,
> worker=0x5603858ee000) at red_worker.c:11870
> #6  handle_dev_loadvm_commands (opaque=0x5603858ee000, payload=<optimized
> out>) at red_worker.c:11897
> #7  0x00007f8c6da361d8 in dispatcher_handle_single_read
> (dispatcher=0x56037f059f68) at dispatcher.c:142
> #8  dispatcher_handle_recv_read (dispatcher=0x56037f059f68) at
> dispatcher.c:165
> #9  0x00007f8c6da5d5f5 in red_worker_main (arg=<optimized out>) at
> red_worker.c:12269
> #10 0x00007f8c6be1ee25 in start_thread () from /lib64/libpthread.so.0
> #11 0x00007f8c6bb4c34d in clone () from /lib64/libc.so.6
> 
> 
> Hi Gerd
>   
>    Could you double confirm the issue, is it same with comment 0?
> 

loadvm_command/qxl_process_cursor in the backtrace, plus crash happening during migration indicates that it's indeed this issue.

Looks like this will be fixed with bug 1567944.

So do we still need this one?

Thanks!
Martin

(In reply to Martin Tessun from comment #41)
> Looks like this will be fixed with bug 1567944.
> So do we still need this one?

QEMU is making assumptions regarding how spice is managing some guest resources rather than taking ownership of these resources as long as it needs them. So the proper fix in QEMU, but it's not done yet. This is why we agreed to go with a simpler/smaller spice-server workaround for now, with the goal of getting the proper fix in QEMU.

bz 1691701 is feeling similar to this - it's rhel6 guests in X migrating on rhel8 AVE.
Upstream built on rhel8 also breaks, but not the same upstream on rhel7.
The normal symptom in this case is a 'custor_channel_process_cmd: invalid cursor command ...' with varying numbers, and then the guest X server segs in qxl code.

but I have also once seen the destination qemu abort on:
(qemu) red_qxl_loadvm_commands:
id 0, group 0, virt start 0, virt end ffffffffffffffff, generation 0, delta 0
id 1, group 1, virt start 7fab5fc00000, virt end 7fab63bfe000, generation 0, delta 7fab5fc00000
id 2, group 1, virt start 7fab5ba00000, virt end 7fab5fa00000, generation 0, delta 7fab5ba00000

(process:3896): Spice-CRITICAL **: 12:00:05.506: memslot.c:122:memslot_get_virt: address generation is not valid, group_id 1, slot_id 0, gen 6, slot_gen 0

Thread 7 (Thread 0x7fac6ac1b700 (LWP 3905)):
#0  0x00007fac8a8a0b44 in read () at /lib64/libpthread.so.0
#1  0x00007fac8ba57c89 in spice_backtrace_gstack () at /lib64/libspice-server.so.1
#2  0x00007fac8ba5f270 in spice_log () at /lib64/libspice-server.so.1
#3  0x00007fac8ba24351 in memslot_get_virt () at /lib64/libspice-server.so.1
#4  0x00007fac8ba2cbc8 in red_get_data_chunks_ptr () at /lib64/libspice-server.so.1
#5  0x00007fac8ba2f2e4 in red_get_cursor_cmd () at /lib64/libspice-server.so.1
#6  0x00007fac8ba3fc5f in red_process_cursor_cmd () at /lib64/libspice-server.so.1
#7  0x00007fac8ba3fe0b in handle_dev_loadvm_commands () at /lib64/libspice-server.so.1
#8  0x00007fac8ba0d7a8 in dispatcher_handle_recv_read () at /lib64/libspice-server.so.1
#9  0x00007fac8ba141bf in watch_func () at /lib64/libspice-server.so.1
#10 0x00007fac8eba089d in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#11 0x00007fac8eba0c68 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#12 0x00007fac8eba0f92 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#13 0x00007fac8ba40efe in red_worker_main () at /lib64/libspice-server.so.1
#14 0x00007fac8a8972de in start_thread () at /lib64/libpthread.so.0
#15 0x00007fac8a5c7a63 in clone () at /lib64/libc.so.6

Still able to reproduce this issue with below packages:
qemu-kvm-3.1.0-26.module+el8.0.1+3232+83506298.x86_64
4.18.0-80.4.1.el8_0.x86_64
spice-qxl-wddm-dod-0.19-0
windows 10 1903 x64 guest

error logs:
error: internal error: qemu unexpectedly closed the monitor: main_channel_link: add main channel client
red_qxl_set_cursor_peer: 
inputs_connect: inputs channel client create
red_qxl_loadvm_commands: 
id 0, group 0, virt start 0, virt end ffffffffffffffff, generation 0, delta 0
id 1, group 1, virt start 7f5283c00000, virt end 7f5287bfe000, generation 0, delta 7f5283c00000
id 2, group 1, virt start 7f527fa00000, virt end 7f5283a00000, generation 0, delta 7f527fa00000

(process:18843): Spice-CRITICAL **: 06:14:09.772: memslot.c:122:memslot_get_virt: address generation is not valid, group_id 1, slot_id 2, gen 5, slot_gen 0

I am getting similar log message when attempting to restore a saved Windows 10 LTSC 2019 x64 ("Features in Windows 10 Enterprise 2019 LTSC are equivalent to Windows 10, version 1809.", says Microsoft) vm on an Ubuntu host.
Is this because of the same root cause? I did virsh managedsave, powered down to connect a pcie device, then attempted to resume with virsh managedrestore. no packages changes on host. Is there any workaround?

Package: libspice-server1
Version: 0.14.0-1ubuntu2.4

Package: qemu-kvm
Version: 1:2.12+dfsg-0~18.04~ppa0

Package: linux-image-4.18.0-20-generic
Version: 4.18.0-20.21~18.04.1

guest tools version: virtio-win-0.1.164.iso

root@gen8:~# virsh restore /var/lib/libvirt/qemu/save/windows.save --paused
2019-05-29 03:38:55.423+0000: starting up libvirt version: 4.7.0, package: 0~18.04~ppa1 (Jacob Zimmermann <ppa> Tue, 11 Sep 2018 17:06:26 +1000), qemu version: 2.12.0Debian 1:2.12+dfsg-0~18.04~ppa0, kernel: 4.18.0-20-generic, hostname: gen8.domain.tld
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=windows,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-6-windows/master-key.aes -machine pc-q35-2.12,accel=kvm,usb=off,vmport=off,smm=on,dump-guest-core=off -cpu IvyBridge-IBRS,ss=on,vmx=on,pcid=on,hypervisor=on,arat=on,tsc_adjust=on,ssbd=on,xsaveopt=on,hv_time,hv_relaxed,hv_vapic,hv_spinlocks=0x1fff,hv_vpindex,hv_runtime,hv_synic,hv_stimer -m 4096 -realtime mlock=off -smp 4,sockets=1,cores=4,threads=1 -uuid 93b04bec-1d8d-42b4-96a7-fab94001c022 -no-user-config -nodefaults -chardev socket,id=charmonitor,fd=27,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=localtime,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-shutdown -global ICH9-LPC.disable_s3=1 -global ICH9-LPC.disable_s4=1 -boot strict=on -device pcie-root-port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2 -device pcie-pci-bridge,id=pci.2,bus=pci.1,addr=0x0 -device pcie-root-port,port=0x11,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x1 -device pcie-root-port,port=0x12,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x2 -device pcie-root-port,port=0x13,chassis=5,id=pci.5,bus=pcie.0,addr=0x2.0x3 -device pcie-root-port,port=0x14,chassis=6,id=pci.6,bus=pcie.0,addr=0x2.0x4 -device pcie-root-port,port=0x15,chassis=7,id=pci.7,bus=pcie.0,addr=0x2.0x5 -device nec-usb-xhci,id=usb,bus=pci.3,addr=0x0 -device virtio-scsi-pci,id=scsi0,bus=pci.7,addr=0x0 -device virtio-serial-pci,id=virtio-serial0,bus=pci.4,addr=0x0 -drive file=/dev/zvol/gen8/vm/windows,format=raw,if=none,id=drive-scsi0-0-0-0,cache=none,discard=unmap,detect-zeroes=unmap,aio=native -device scsi-hd,bus=scsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,id=scsi0-0-0-0,bootindex=1,write-cache=on -drive file=/srv/gen8/vm/virtio-win-0.1.164.iso,format=raw,if=none,id=drive-sata0-0-2,media=cdrom,readonly=on -device ide-cd,bus=ide.2,drive=drive-sata0-0-2,id=sata0-0-2 -netdev tap,fd=29,id=hostnet0,vhost=on,vhostfd=30 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:66:aa:33,bus=pci.6,addr=0x0 -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,fd=31,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,bus=usb.0,port=1 -spice port=5902,addr=127.0.0.1,disable-ticketing,image-compression=off,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=pcie.0,addr=0x1 -device ich9-intel-hda,id=sound0,bus=pcie.0,addr=0x1b -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -chardev spicevmc,id=charredir0,name=usbredir -device usb-redir,chardev=charredir0,id=redir0,bus=usb.0,port=2 -chardev spicevmc,id=charredir1,name=usbredir -device usb-redir,chardev=charredir1,id=redir1,bus=usb.0,port=3 -incoming defer -device virtio-balloon-pci,id=balloon0,bus=pci.5,addr=0x0,deflate-on-oom=on -sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny -msg timestamp=on
2019-05-29T03:38:55.643894Z qemu-system-x86_64: -chardev pty,id=charserial0: char device redirected to /dev/pts/7 (label charserial0)
red_qxl_loadvm_commands: 
id 0, group 0, virt start 0, virt end ffffffffffffffff, generation 0, delta 0
id 1, group 1, virt start 7f6eefc00000, virt end 7f6ef3bfe000, generation 0, delta 7f6eefc00000
id 2, group 1, virt start 7f6eeba00000, virt end 7f6eefa00000, generation 0, delta 7f6eeba00000

(process:35998): Spice-CRITICAL **: 06:39:11.185: memslot.c:122:memslot_get_virt: address generation is not valid, group_id 1, slot_id 0, gen 2, slot_gen 0

2019-05-29 03:39:11.694+0000: shutting down, reason=crashed
error: Failed to restore domain from /var/lib/libvirt/qemu/save/windows.save
error: operation failed: domain is not running

root@gen8:~# virsh managedsave-dumpxml windows
<domain type='kvm'>
  <name>windows</name>
  <uuid>ac933b88-fc8c-462e-af8f-887f0c169212</uuid>
  <metadata>
    <libosinfo:libosinfo xmlns:libosinfo="http://libosinfo.org/xmlns/libvirt/domain/1.0">
      <libosinfo:os id="http://microsoft.com/win/10"/>
    </libosinfo:libosinfo>
  </metadata>
  <memory unit='KiB'>4194304</memory>
  <currentMemory unit='KiB'>1572864</currentMemory>
  <vcpu placement='static'>4</vcpu>
  <resource>
    <partition>/machine</partition>
  </resource>
  <os>
    <type arch='x86_64' machine='pc-q35-2.12'>hvm</type>
  </os>
  <features>
    <acpi/>
    <apic/>
    <hyperv>
      <relaxed state='on'/>
      <vapic state='on'/>
      <spinlocks state='on' retries='8191'/>
      <vpindex state='on'/>
      <runtime state='on'/>
      <synic state='on'/>
      <stimer state='on'/>
    </hyperv>
    <vmport state='off'/>
    <smm state='on'/>
  </features>
  <cpu mode='custom' match='exact' check='full'>
    <model fallback='forbid'>IvyBridge-IBRS</model>
    <vendor>Intel</vendor>
    <topology sockets='1' cores='4' threads='1'/>
    <feature policy='require' name='ss'/>
    <feature policy='require' name='vmx'/>
    <feature policy='require' name='pcid'/>
    <feature policy='require' name='hypervisor'/>
    <feature policy='require' name='arat'/>
    <feature policy='require' name='tsc_adjust'/>
    <feature policy='require' name='ssbd'/>
    <feature policy='require' name='xsaveopt'/>
  </cpu>
  <clock offset='localtime'>
    <timer name='rtc' tickpolicy='catchup'/>
    <timer name='pit' tickpolicy='delay'/>
    <timer name='hpet' present='yes'/>
    <timer name='hypervclock' present='yes'/>
  </clock>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>restart</on_reboot>
  <on_crash>destroy</on_crash>
  <pm>
    <suspend-to-mem enabled='no'/>
    <suspend-to-disk enabled='no'/>
  </pm>
  <devices>
    <emulator>/usr/bin/kvm-spice</emulator>
    <disk type='block' device='disk'>
      <driver name='qemu' type='raw' cache='none' io='native' discard='unmap' detect_zeroes='unmap'/>
      <source dev='/dev/zvol/gen8/vm/windows'/>
      <backingStore/>
      <target dev='sda' bus='scsi'/>
      <boot order='1'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </disk>
    <disk type='file' device='cdrom'>
      <driver name='qemu' type='raw'/>
      <source file='/srv/gen8/vm/virtio-win-0.1.164.iso'/>
      <backingStore/>
      <target dev='sdc' bus='sata'/>
      <readonly/>
      <address type='drive' controller='0' bus='0' target='0' unit='2'/>
    </disk>
    <controller type='usb' index='0' model='nec-xhci'>
      <address type='pci' domain='0x0000' bus='0x03' slot='0x00' function='0x0'/>
    </controller>
    <controller type='sata' index='0'>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x1f' function='0x2'/>
    </controller>
    <controller type='pci' index='0' model='pcie-root'/>
    <controller type='pci' index='1' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='1' port='0x10'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0' multifunction='on'/>
    </controller>
    <controller type='pci' index='2' model='pcie-to-pci-bridge'>
      <model name='pcie-pci-bridge'/>
      <address type='pci' domain='0x0000' bus='0x01' slot='0x00' function='0x0'/>
    </controller>
    <controller type='pci' index='3' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='3' port='0x11'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x1'/>
    </controller>
    <controller type='pci' index='4' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='4' port='0x12'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x2'/>
    </controller>
    <controller type='pci' index='5' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='5' port='0x13'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x3'/>
    </controller>
    <controller type='pci' index='6' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='6' port='0x14'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x4'/>
    </controller>
    <controller type='pci' index='7' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='7' port='0x15'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x5'/>
    </controller>
    <controller type='scsi' index='0' model='virtio-scsi'>
      <address type='pci' domain='0x0000' bus='0x07' slot='0x00' function='0x0'/>
    </controller>
    <controller type='virtio-serial' index='0'>
      <address type='pci' domain='0x0000' bus='0x04' slot='0x00' function='0x0'/>
    </controller>
    <interface type='network'>
      <mac address='52:54:00:66:aa:33'/>
      <source network='routed'/>
      <model type='virtio'/>
      <address type='pci' domain='0x0000' bus='0x06' slot='0x00' function='0x0'/>
    </interface>
    <serial type='pty'>
      <target type='isa-serial' port='0'>
        <model name='isa-serial'/>
      </target>
    </serial>
    <console type='pty'>
      <target type='serial' port='0'/>
    </console>
    <channel type='spicevmc'>
      <target type='virtio' name='com.redhat.spice.0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>
    <channel type='unix'>
      <target type='virtio' name='org.qemu.guest_agent.0'/>
      <address type='virtio-serial' controller='0' bus='0' port='2'/>
    </channel>
    <input type='tablet' bus='usb'>
      <address type='usb' bus='0' port='1'/>
    </input>
    <input type='mouse' bus='ps2'/>
    <input type='keyboard' bus='ps2'/>
    <graphics type='spice' autoport='yes'>
      <listen type='address'/>
      <image compression='off'/>
    </graphics>
    <sound model='ich9'>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x1b' function='0x0'/>
    </sound>
    <video>
      <model type='qxl' ram='65536' vram='65536' vgamem='16384' heads='1' primary='yes'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x0'/>
    </video>
    <redirdev bus='usb' type='spicevmc'>
      <address type='usb' bus='0' port='2'/>
    </redirdev>
    <redirdev bus='usb' type='spicevmc'>
      <address type='usb' bus='0' port='3'/>
    </redirdev>
    <memballoon model='virtio' autodeflate='on'>
      <address type='pci' domain='0x0000' bus='0x05' slot='0x00' function='0x0'/>
    </memballoon>
  </devices>
  <seclabel type='dynamic' model='apparmor' relabel='yes'/>
</domain>

QEMU has been recently split into sub-components and as a one-time operation to avoid breakage of tools, we are setting the QEMU sub-component of this BZ to "General". Please review and change the sub-component if necessary the next time you review this BZ. Thanks

this still occurs even with recent qemu such as 4.2 and libvirt 5.4...

(In reply to Mai Ling from comment #55)
> this still occurs even with recent qemu such as 4.2 and libvirt 5.4...

Mai Ling, if this issue is critical or in any way time sensitive for you, please raise a ticket through your regular Red Hat support channels to make certain it receives the proper attention and prioritization that will result in a timely resolution. For information on how to contact the Red Hat production support team, please visit: https://www.redhat.com/support/process/production/#howto

Hi. I've been investigating exactly this same problem for a couple of last weeks.
The problem happens during migration(suspend/resume) of Debian 9 ,kernel is vmlinuz-4.9.0-13-amd64.

I've investigated both QEMU and kernel-4.9 sources and added logs in both places.
I've got some insight of what's going on and want to share and have some discussion.

So.
For reproduce I've used this sequence:
1. Start VM with the specified kernel on Debian 9 
2. Observe vm boot process via VNC until Debian login screen comes out.
3. Suspend VM
4. Resume VM.
5. repeat 3 and 4 approx 20-30 tries. 
6. if no reproduce, kill VM process start VM and repeat from 1

As it is discussed in this thread, the problem is:
- At restore qxl's vm state is being restored from a dump of some sort.
- In this dump there is a QXL state, that restores the whole memory region of qxl's video memory, a pointer to the last QXLCursorCmd (guest_cursor),
  that points somewhere in the same restored video memory
- In QXLCursorCmd has ->u.set.shape field that points to one more address in video memory and is expected to point at QXLCursor object. 
- At the last step of restore, qemu wants to restore the last state of cursor, for that it uses QXLCursorCmd that is stored in guest_cursor and sends it to spice server (replays the command).
- Spice server starts parsing QXLCursorCmd and follows ->u.set.shape pointer to parse QXLCursor under this address.
- Spice server detects that ->u.set.shape does not point to a valid QXLCursor object. It know's that because QXLCursor object has more pointers into videomemory that should hold chunks of data that form raw data of cursor image and those pointers do not pass memslot checks, thus the title of a bug and a callstack.  

I've added tonns of logs and made an investigation.
In this thread, one of the proposals was that guest_cursor outlives the address regions for that cursor command, so the area under ->u.set.shape is released in interface_release_resource function in hw/display/qxl.c, and guest_cursor is not zeroed out, but later it's put into dump and reused at suspend, resulting in the obvious use of released memory.
But my investigation has shown that it's probably not the case. Please correct or recheck my version.
My version is:
1. guest os sends QXLCursorCmd with command = QXL_CURSOR_SET.
2. spice server polls cursor_ring in cursor command ring until it sees that new command. it does something like this
   while(should_poll) {
     cmd = interface->get_cursor_command();
     process_cursor_command();
   }
   inteface is a structre filled with functions that implement various display and cursor stuff. In our case whole implementation of this interface is done by qemu in hw/display/qxl.c code
3. During interface_get_cursor_command qemu takes out cursor command from cursor ring, it also stores this command into guest_cursor state field it then returs this command to spice_server 
4. Spice server now processes the cursor command, for that it parses the whole command, by travelling into each pointer and copying cursor data in it's own format. It then stores the cursor state into it's cursor_channel object. There the cursor leaves the whole time until next cursor command arrives, in which case previous cursor (in spice server format) has to leave cursor_channel. It's being unrefed, and as part of destroy procedure interface->release_resource is called for the evicted cursor. 
5. So interface->release_resource is called with PREVIOUS cursor command (not the current one). The release_id of a previously stored cursor is sent into release_ring by qemu implementation of release_resource. It is worth to mention that the release is not immediately being placed into the release_ring. Instead, one slot of release_ring is actually a bucket into the linked list of releases, this linked list of release info's is first filled with 32 items and only then the first release info is placed into release_ring. So the guest will see 32 releases at once by popping one release_ring slot.  
6. Now the guests garbage_collect polling function will detect a new slot in release_ring and will pop it and exhaust the whole linked list of release items in a loop. Each item is just an interger value of unique release_id. The guest will find the corresponding release_record by it's retrieved release_id. 
7. In linux kernel that release record has type 'struct qxl_release'. It holds a list of qxl_bo (buffer object) objects. Each qxl_bo is the actual representation of some memory space in qxl's vram. At minimum each qxl_release will have a single qxl_bo - that is pointing to the memory page, where data from cursor ring is located.
In case of cursor command, each qxl_bo has refcounting, that when release is no needed all bo's get unrefed, and possibly destroyed. For a cursor command qxl_release should have 2 bos added to it's list to maintain a reference all the time while the command is not released.        
8. Now while the last cursor command could possibly be released, the CURRENT cursor command is not and it's now written into "guest_cursor" field.
The only way to release the current cursor is to make it previous by receiving new cursor command or by calling spice_qxl_reset_cursor. Qemu calls spice_qxl_reset_cursor inside of qxl_spice_reset_cursor, there it also zeroes out guest_cursor. That's why there is no inconsistency between QEMU's video memory and pointers from the last cursor command.


I've found that the actual inconsistency between the pointer of guest_cursor->u.set.shape and the actual contents of the corellating memory region is in guest kernel, and the implementation of qxl_bo. struct qxl_bo is a wrapper around struct ttm_bo, and qxl implements some of the functions of ttm driver. The logic of what ttm does is not 100% clear to me, but the problem is that ttm can MOVE it's bo's under some circumstances. That is exactly what it does in our case. While qemu qxl and spice server still hold a legitimate pointer to cursor command to it's data it actually sometimes move's qxl_bo that represents memory area under guest_cursor->u.set.shape address.
The code is in drivers/gpu/drm/ttm/ttm_bo.c
This is a callstack of how this can happen for example:

\drm_ioctl
 \drm_mode_page_flip_ioctl
  \qxl_crtc_page_flip
   \qxl_draw_dirty_fb
    \qxl_image_alloc_objects
     \qxl_alloc_bo_reserved
      \qxl_bo_create
       \ttm_bo_init
        \ttm_bo_validate
         \ttm_bo_move_buffer
          \ttm_bo_mem_space
           \ttm_bo_mem_force_space
            \ttm_mem_evict_first 
             \ttm_bo_evict
              \ttm_bo_handle_move_mem
               \qxl_bo_move 
   
I've logged that and I see that qxl_bo_move is called for bo that has valid cursor data in it which is not yet destroyed.
After qxl_bo_move has happened, qxl_image_alloc_object returns new qxl_bo to qxl_draw_dirty_fb that laters fills this bo with
some other data, while cursor bo is not yet released and is valid in the eyes of qemu.
qxl_bo_move and qxl_bo_move_notify are both implementations of this movement mechanism.
For surface bo's qxl_surface_evict is called, but for cursor bo nothing interesting is done.

I've checked with the later kernels and have found that the functions that actually generate QXL_CURSOR_SET commands have been renamed lately, but the logic more or less remains.
So in debian 9 the functions generating QXL_CURSOR_SET are 
qxl_crtc_cursor_set2
qxl_crtc_apply_cursor

have later turned into:
qxl_cursor_atomic_update
qxl_primary_apply_cursor

I've noticed 2 things in qxl_crtc_cursor_set2
1. In the later qxl_cursor_atomic_update there is a patch that calls qxl_bo_pin(cursor_bo) for qxl_bo, that represents our problematic ->u.set.shape
2. In qxl_crtc_cursor_set2, there is a code that allocates new cursor_bo but it is not inserted into list of bos, managed by qxl_release.

To me it seemed natural that qxl_bo_pin is probably does what it sounds to do - forbid cursor_bo to be moved around in videomemory, thus eliminating the problem.
I've rechecked this idea and the problem really goes away. After I've put a call to qxl_bo_pin I immediately started to see new dmesg logs where same physical adderess, previously occupied by cursor data is only being reused AFTER qxl_bo_destroy is called for cursor_bo.

But looking at the actuall ttm code in drivers/gpu/drm/ttm/ttm_bo.c and ttm_bo_utils.c I've failed to understand why this actually happens.
qxl_bo_pin / qxl_bo_unpin manipulates flag TTM_PL_FLAG_NO_EVICT, which does not seem to influence ttm's decision to move the bo in ttm_bo_handle_move_mem in any way.

Here is kernel commit that adds qxl_bo_pin call to a proper place.

commit 0081cdfe63f0b5e72b14d13f45a93ca7b0b8092f
Author: Christophe Fergeau <cfergeau>
Date:   Tue Nov 20 17:20:04 2018 +0100

    qxl: Make sure qxl_cursor memory is pinned

This commit seems to do it's job for this bug, but I don't understand how.
If anyone has a clear picture of how this fixes the problem, I'd be glad to here that.

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

I would advise we still keep this bz as WONTFIX as bz 1849563 shows that SPICE has been deprecated on RHEL-8.3. 
Bug 1849563 - [Docs] Document SPICE as deprecated as it will be removed in a future major release of RHEL - still being supported for RHV

Now QE only tests several cases about SPICE on RHEL-8 and SPICE may be fully removed on RHEL9.

Please reopen if you have other opinions. Thanks

Given Valeriy's debug,adding a needinfo on Christophe for the question at the end.


(In reply to Valeriy Vdovin from comment #58)
> Hi. I've been investigating exactly this same problem for a couple of last
> weeks.
> The problem happens during migration(suspend/resume) of Debian 9 ,kernel is
> vmlinuz-4.9.0-13-amd64.
> 
> I've investigated both QEMU and kernel-4.9 sources and added logs in both
> places.
> I've got some insight of what's going on and want to share and have some
> discussion.
> 
> So.
> For reproduce I've used this sequence:
> 1. Start VM with the specified kernel on Debian 9 
> 2. Observe vm boot process via VNC until Debian login screen comes out.
> 3. Suspend VM
> 4. Resume VM.
> 5. repeat 3 and 4 approx 20-30 tries. 
> 6. if no reproduce, kill VM process start VM and repeat from 1
> 
> As it is discussed in this thread, the problem is:
> - At restore qxl's vm state is being restored from a dump of some sort.
> - In this dump there is a QXL state, that restores the whole memory region
> of qxl's video memory, a pointer to the last QXLCursorCmd (guest_cursor),
>   that points somewhere in the same restored video memory
> - In QXLCursorCmd has ->u.set.shape field that points to one more address in
> video memory and is expected to point at QXLCursor object. 
> - At the last step of restore, qemu wants to restore the last state of
> cursor, for that it uses QXLCursorCmd that is stored in guest_cursor and
> sends it to spice server (replays the command).
> - Spice server starts parsing QXLCursorCmd and follows ->u.set.shape pointer
> to parse QXLCursor under this address.
> - Spice server detects that ->u.set.shape does not point to a valid
> QXLCursor object. It know's that because QXLCursor object has more pointers
> into videomemory that should hold chunks of data that form raw data of
> cursor image and those pointers do not pass memslot checks, thus the title
> of a bug and a callstack.  
> 
> I've added tonns of logs and made an investigation.
> In this thread, one of the proposals was that guest_cursor outlives the
> address regions for that cursor command, so the area under ->u.set.shape is
> released in interface_release_resource function in hw/display/qxl.c, and
> guest_cursor is not zeroed out, but later it's put into dump and reused at
> suspend, resulting in the obvious use of released memory.
> But my investigation has shown that it's probably not the case. Please
> correct or recheck my version.
> My version is:
> 1. guest os sends QXLCursorCmd with command = QXL_CURSOR_SET.
> 2. spice server polls cursor_ring in cursor command ring until it sees that
> new command. it does something like this
>    while(should_poll) {
>      cmd = interface->get_cursor_command();
>      process_cursor_command();
>    }
>    inteface is a structre filled with functions that implement various
> display and cursor stuff. In our case whole implementation of this interface
> is done by qemu in hw/display/qxl.c code
> 3. During interface_get_cursor_command qemu takes out cursor command from
> cursor ring, it also stores this command into guest_cursor state field it
> then returs this command to spice_server 
> 4. Spice server now processes the cursor command, for that it parses the
> whole command, by travelling into each pointer and copying cursor data in
> it's own format. It then stores the cursor state into it's cursor_channel
> object. There the cursor leaves the whole time until next cursor command
> arrives, in which case previous cursor (in spice server format) has to leave
> cursor_channel. It's being unrefed, and as part of destroy procedure
> interface->release_resource is called for the evicted cursor. 
> 5. So interface->release_resource is called with PREVIOUS cursor command
> (not the current one). The release_id of a previously stored cursor is sent
> into release_ring by qemu implementation of release_resource. It is worth to
> mention that the release is not immediately being placed into the
> release_ring. Instead, one slot of release_ring is actually a bucket into
> the linked list of releases, this linked list of release info's is first
> filled with 32 items and only then the first release info is placed into
> release_ring. So the guest will see 32 releases at once by popping one
> release_ring slot.  
> 6. Now the guests garbage_collect polling function will detect a new slot in
> release_ring and will pop it and exhaust the whole linked list of release
> items in a loop. Each item is just an interger value of unique release_id.
> The guest will find the corresponding release_record by it's retrieved
> release_id. 
> 7. In linux kernel that release record has type 'struct qxl_release'. It
> holds a list of qxl_bo (buffer object) objects. Each qxl_bo is the actual
> representation of some memory space in qxl's vram. At minimum each
> qxl_release will have a single qxl_bo - that is pointing to the memory page,
> where data from cursor ring is located.
> In case of cursor command, each qxl_bo has refcounting, that when release is
> no needed all bo's get unrefed, and possibly destroyed. For a cursor command
> qxl_release should have 2 bos added to it's list to maintain a reference all
> the time while the command is not released.        
> 8. Now while the last cursor command could possibly be released, the CURRENT
> cursor command is not and it's now written into "guest_cursor" field.
> The only way to release the current cursor is to make it previous by
> receiving new cursor command or by calling spice_qxl_reset_cursor. Qemu
> calls spice_qxl_reset_cursor inside of qxl_spice_reset_cursor, there it also
> zeroes out guest_cursor. That's why there is no inconsistency between QEMU's
> video memory and pointers from the last cursor command.
> 
> 
> I've found that the actual inconsistency between the pointer of
> guest_cursor->u.set.shape and the actual contents of the corellating memory
> region is in guest kernel, and the implementation of qxl_bo. struct qxl_bo
> is a wrapper around struct ttm_bo, and qxl implements some of the functions
> of ttm driver. The logic of what ttm does is not 100% clear to me, but the
> problem is that ttm can MOVE it's bo's under some circumstances. That is
> exactly what it does in our case. While qemu qxl and spice server still hold
> a legitimate pointer to cursor command to it's data it actually sometimes
> move's qxl_bo that represents memory area under guest_cursor->u.set.shape
> address.
> The code is in drivers/gpu/drm/ttm/ttm_bo.c
> This is a callstack of how this can happen for example:
> 
> \drm_ioctl
>  \drm_mode_page_flip_ioctl
>   \qxl_crtc_page_flip
>    \qxl_draw_dirty_fb
>     \qxl_image_alloc_objects
>      \qxl_alloc_bo_reserved
>       \qxl_bo_create
>        \ttm_bo_init
>         \ttm_bo_validate
>          \ttm_bo_move_buffer
>           \ttm_bo_mem_space
>            \ttm_bo_mem_force_space
>             \ttm_mem_evict_first 
>              \ttm_bo_evict
>               \ttm_bo_handle_move_mem
>                \qxl_bo_move 
>    
> I've logged that and I see that qxl_bo_move is called for bo that has valid
> cursor data in it which is not yet destroyed.
> After qxl_bo_move has happened, qxl_image_alloc_object returns new qxl_bo to
> qxl_draw_dirty_fb that laters fills this bo with
> some other data, while cursor bo is not yet released and is valid in the
> eyes of qemu.
> qxl_bo_move and qxl_bo_move_notify are both implementations of this movement
> mechanism.
> For surface bo's qxl_surface_evict is called, but for cursor bo nothing
> interesting is done.
> 
> I've checked with the later kernels and have found that the functions that
> actually generate QXL_CURSOR_SET commands have been renamed lately, but the
> logic more or less remains.
> So in debian 9 the functions generating QXL_CURSOR_SET are 
> qxl_crtc_cursor_set2
> qxl_crtc_apply_cursor
> 
> have later turned into:
> qxl_cursor_atomic_update
> qxl_primary_apply_cursor
> 
> I've noticed 2 things in qxl_crtc_cursor_set2
> 1. In the later qxl_cursor_atomic_update there is a patch that calls
> qxl_bo_pin(cursor_bo) for qxl_bo, that represents our problematic
> ->u.set.shape
> 2. In qxl_crtc_cursor_set2, there is a code that allocates new cursor_bo but
> it is not inserted into list of bos, managed by qxl_release.
> 
> To me it seemed natural that qxl_bo_pin is probably does what it sounds to
> do - forbid cursor_bo to be moved around in videomemory, thus eliminating
> the problem.
> I've rechecked this idea and the problem really goes away. After I've put a
> call to qxl_bo_pin I immediately started to see new dmesg logs where same
> physical adderess, previously occupied by cursor data is only being reused
> AFTER qxl_bo_destroy is called for cursor_bo.
> 
> But looking at the actuall ttm code in drivers/gpu/drm/ttm/ttm_bo.c and
> ttm_bo_utils.c I've failed to understand why this actually happens.
> qxl_bo_pin / qxl_bo_unpin manipulates flag TTM_PL_FLAG_NO_EVICT, which does
> not seem to influence ttm's decision to move the bo in
> ttm_bo_handle_move_mem in any way.
> 
> Here is kernel commit that adds qxl_bo_pin call to a proper place.
> 
> commit 0081cdfe63f0b5e72b14d13f45a93ca7b0b8092f
> Author: Christophe Fergeau <cfergeau>
> Date:   Tue Nov 20 17:20:04 2018 +0100
> 
>     qxl: Make sure qxl_cursor memory is pinned
> 
> This commit seems to do it's job for this bug, but I don't understand how.
> If anyone has a clear picture of how this fixes the problem, I'd be glad to
> here that.

The needinfo request[s] on this closed bug have been removed as they have been unresolved for 500 days