Bug 1746790 - qemu core dump while migrate from RHEL7.6 to RHEL8.1
Summary: qemu core dump while migrate from RHEL7.6 to RHEL8.1
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux Advanced Virtualization
Classification: Red Hat
Component: qemu-kvm
Version: 8.1
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: rc
: ---
Assignee: Dr. David Alan Gilbert
QA Contact: jingzhao
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-08-29 09:37 UTC by jingzhao
Modified: 2019-11-06 07:19 UTC (History)
13 users (show)

Fixed In Version: qemu-kvm-4.1.0-8.module+el8.1.0+4199+446e40fc
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-06 07:19:01 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2019:3723 0 None None None 2019-11-06 07:19:24 UTC

Description jingzhao 2019-08-29 09:37:54 UTC
Description of problem:
qemu core dump while migrate from RHEL7.6 to RHEL8.1

Version-Release number of selected component (if applicable):
source host version:
kernel-3.10.0-957.35.1.el7.x86_64
qemu-kvm-rhev-2.12.0-18.el7_6.7.x86_64

destination host version:
kernel-4.18.0-139.el8.x86_64


How reproducible:
3/3

Steps to Reproduce:
1.Boot guest with qemu command line[1] in source host
2.Boot guest with qemu command line[1] & -incoming tcp:0:5800 in destination host
3.Migrate from source host to destination host

Actual results:
qemu core dump while migrate finished
note: source host disply migrate complete
qemu-kvm: hw/usb/core.c:719: usb_ep_get: Assertion `dev != NULL' failed.
/home/1: line 100: 15941 Aborted                 (core dumped) /usr/libexec/qemu-kvm -rtc base=utc,clock=host -qmp tcp

(gdb) bt
#0  0x00007ffff2bc6a24 in __pthread_mutex_cond_lock () from /lib64/libpthread.so.0
#1  0x00007ffff2bc836d in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#2  0x0000555555bbb86d in qemu_cond_wait_impl (cond=<optimized out>, mutex=0x555556417f60 <qemu_global_mutex>, file=0x555555c5e038 "/builddir/build/BUILD/qemu-4.1.0/cpus.c", line=1245)
    at util/qemu-thread-posix.c:161
#3  0x000055555589abb7 in qemu_wait_io_event (cpu=0x55555656b850) at /usr/src/debug/qemu-kvm-4.1.0-5.module+el8.1.0+4076+b5e41ebc.x86_64/cpus.c:1245
#4  0x000055555589c548 in qemu_kvm_cpu_thread_fn (arg=0x55555656b850) at /usr/src/debug/qemu-kvm-4.1.0-5.module+el8.1.0+4076+b5e41ebc.x86_64/cpus.c:1290
#5  0x0000555555bbb4b4 in qemu_thread_start (args=0x555556590180) at util/qemu-thread-posix.c:502
#6  0x00007ffff2bc22de in start_thread () from /lib64/libpthread.so.0
#7  0x00007ffff28f3133 in clone () from /lib64/libc.so.6


Expected results:
migrate successfully and no core dump

Additional info:
Didn't reproduce it with qemu-kvm-4.1.0-4.module+el8.1.0+4020+16089f93.x86_64


[1] /usr/libexec/qemu-kvm  \
-rtc base=utc,clock=host \
-qmp tcp:0:3333,server,nowait \
-enable-kvm  \
-cpu EPYC,+x2apic,hv_spinlocks=0x1fff,hv_relaxed,hv_vapic,hv_time \
-watchdog i6300esb \
-serial tcp:0:4444,server,nowait \
-monitor stdio \
-boot order=cdn,once=c,menu=on,strict=on \
-vga qxl \
-smp 8,cores=1,threads=1,sockets=8 \
-machine pc-i440fx-rhel7.6.0 \
-vnc :10 \
-watchdog-action reset \
-object memory-backend-ram,policy=bind,id=mem-1,size=2048M,prealloc=yes,host-nodes=0 -numa node,memdev=mem-1 \
-object memory-backend-ram,policy=bind,id=mem-2,size=2048M,prealloc=yes,host-nodes=0 -numa node,memdev=mem-2 \
-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-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x7 \
-device virtio-scsi-pci,id=scsi0,cmd_per_lun=234,bus=pci.0,addr=0x8 \
-device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 \
-device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x9,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 \
-device virtio-scsi-pci,id=scsi1,addr=0x13 \
-device scsi-hd,drive=drive-scsi-disk,bus=scsi1.0,id=data-disk2 \
-device isa-serial,chardev=charserial0,id=serial0 \
-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.spice.0 \
-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 \
-device usb-host,id=hostdev0 \
-device pvpanic,ioport=1285 \
-device virtio-net-pci,netdev=hostnet0,id=virtio-net-pci0,mac=b6:af:42:c8:66:18,bus=pci.0,addr=0x14 \
-device e1000,netdev=hostnet1,id=virtio-net-pci1,mac=b6:2f:a8:85:82:7c,bus=pci.0,addr=0x15,multifunction=off \
-device rtl8139,netdev=hostnet2,id=virtio-net-pci2,mac=4e:63:28:bc:c1:75,bus=pci.0,addr=0x16,multifunction=off \
-device e1000e,netdev=hostnet4,id=virtio-net-pci4,mac=4e:63:28:bc:c1:85,bus=pci.0,addr=0x19,multifunction=off \
-device e1000-82540em,netdev=hostnet3,id=virtio-net-pci3,mac=4e:63:28:bc:c1:86,bus=pci.0,addr=0x1e,multifunction=off \
-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,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 \
-device scsi-cd,bus=bot1.0,scsi-id=0,lun=1,drive=usb-cdrom1,id=usb-cdrom1 \
-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 \
-device scsi-cd,bus=bot2.0,scsi-id=0,lun=1,drive=usb-cdrom2,id=usb-cdrom2 \
-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 \
-device scsi-cd,bus=bot3.0,scsi-id=0,lun=1,drive=usb-cdrom3,id=usb-cdrom3 \
-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 \
-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 \
-device virtio-rng-pci,id=rng0,bus=pci.0,addr=0x1c \
-device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x1d \
-device isa-debugcon,chardev=seabioslog_id,iobase=0x402 \
-nodefaults  \
-name "mouse-vm" \
-netdev tap,id=hostnet0,vhost=on,id=hostnet0,script=/etc/qemu-ifup,downscript=/etc/qemu-ifdown \
-netdev tap,id=hostnet1,vhost=on,script=/etc/qemu-ifup,downscript=/etc/qemu-ifdown \
-netdev tap,id=hostnet2,vhost=on,script=/etc/qemu-ifup,downscript=/etc/qemu-ifdown \
-netdev tap,id=hostnet4,vhost=on,script=/etc/qemu-ifup,downscript=/etc/qemu-ifdown \
-netdev tap,id=hostnet3,vhost=on,script=/etc/qemu-ifup,downscript=/etc/qemu-ifdown \
-m 4096,slots=256,maxmem=32G \
-drive file=/home/migration/a1.iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw \
-drive file=/home/migration/a2.iso,if=none,id=drive-fdc0-0-0,format=raw,cache=none \
-drive file=/home/migration/rhel76-64-virtio-scsi.qcow2,if=none,id=drive-virtio-disk0,format=qcow2,cache=none,discard=unmap,werror=stop,rerror=stop,aio=threads \
-drive file=/home/migration/d2.qcow2,if=none,id=drive-scsi-disk,format=qcow2,cache=none,werror=stop,rerror=stop \
-drive file=/home/migration/d3.raw,if=none,id=drive-data-disk,format=raw,cache=none,aio=native,werror=stop,rerror=stop,copy-on-read=off,media=disk \
-drive file=/home/migration/a3.iso,if=none,id=usb-cdrom1,format=raw \
-drive file=/home/migration/d4.qcow2,id=usb-disk1,if=none,format=qcow2 \
-drive file=/home/migration/a4.iso,if=none,id=usb-cdrom2,format=raw \
-drive file=/home/migration/d5.qcow2,id=usb-disk2,if=none,format=qcow2 \
-drive file=/home/migration/a5.iso,if=none,id=usb-cdrom3,format=raw \
-drive file=/home/migration/d6.qcow2,id=usb-disk3,if=none,format=qcow2  \
-drive file=/home/migration/d7.qcow2,if=none,id=drive-usb-0,media=disk,format=qcow2 \
-drive file=/home/migration/d8.qcow2,if=none,id=drive-usb-1,media=disk,format=qcow2 \
-drive file=/home/migration/d9.qcow2,if=none,id=drive-usb-2,media=disk,format=qcow2 \
-sandbox off \
-chardev socket,id=charmonitor,path=/home/tmp1,server,nowait \
-chardev pty,id=charserial0 \
-chardev spicevmc,id=charchannel0,name=vdagent \
-chardev socket,id=charchannel1,path=/home/tmp2,server,nowait \
-chardev spicevmc,id=charredir0,name=usbredir \
-chardev socket,id=seabioslog_id,path=/home/seabios,server,nowait \

Comment 5 Laurent Vivier 2019-08-30 07:10:55 UTC
Perhaps it's not migration specific but related to USB reset?

Gerd, any suggestion?

Comment 6 Gerd Hoffmann 2019-08-30 11:22:15 UTC
upstream commit 1be344b7ad25d572dadeee46d80f0103354352b2 might help

stack trace looks bogous, assert says usb_ep_get() but that function isn't in the stacktrace ...

Comment 7 Dr. David Alan Gilbert 2019-09-03 11:18:17 UTC
Hi,
  Can you please:
    a) Instead of using 'bt' use   
          t a a bt full

       that gives a lot more information

    b) What guest are you running exactly?

    c) Can you please see if you can get it to reproduce using a simpler command line; less devices.

Thanks!

Comment 8 Dr. David Alan Gilbert 2019-09-04 12:29:52 UTC
I've tried a simple 7.6->8.1 migrate using a 7.1 (server) guest and it seems OK.
WIll try a graphical setup.

Comment 10 Dr. David Alan Gilbert 2019-09-04 13:53:37 UTC
That's really odd because that backtrace doesn't show any crashing thread.

Comment 11 Dr. David Alan Gilbert 2019-09-04 14:04:36 UTC
OK, reproduced on virtlab403 (rhel7) ->413 (rhel8)  - needs to have the guest running in the desktop and VNC connected to the source.

Comment 12 Dr. David Alan Gilbert 2019-09-04 14:10:57 UTC
Backtrace:
(gdb) bt  full
#0  0x00007f89e9d3887f in raise () at /lib64/libc.so.6
#1  0x00007f89e9d22c95 in abort () at /lib64/libc.so.6
#2  0x00007f89e9d22b69 in _nl_load_domain.cold.0 () at /lib64/libc.so.6
#3  0x00007f89e9d30e36 in .annobin_assert.c_end () at /lib64/libc.so.6
#4  0x00005576867a9691 in usb_ep_get (dev=<optimized out>, pid=<optimized out>, ep=<optimized out>) at hw/usb/core.c:719
        eps = <optimized out>
        __PRETTY_FUNCTION__ = "usb_ep_get"
#5  0x00005576867afabc in ehci_execute (action=0x557686ab38cc "process", p=0x5576883e2a10) at hw/usb/hcd-ehci.c:1363
        ep = <optimized out>
        endp = <optimized out>
        spd = <optimized out>
        __PRETTY_FUNCTION__ = "ehci_execute"
        __PRETTY_FUNCTION__ = "ehci_execute"
#6  0x00005576867afabc in ehci_execute (p=0x5576883e2a10, action=0x557686ab38cc "process") at hw/usb/hcd-ehci.c:1337
        __PRETTY_FUNCTION__ = "ehci_execute"
#7  0x00005576867b15b2 in ehci_state_execute (q=<optimized out>) at hw/usb/hcd-ehci.c:1936
        p = 0x5576883e2a10
        again = 0
        __PRETTY_FUNCTION__ = "ehci_state_execute"
        q = <optimized out>
        itd_count = <optimized out>
        again = <optimized out>
        __PRETTY_FUNCTION__ = "ehci_advance_state"
        __func__ = "ehci_advance_state"
#8  0x00005576867b15b2 in ehci_advance_state (ehci=ehci@entry=0x55768915e360, async=async@entry=0) at hw/usb/hcd-ehci.c:2077
        q = <optimized out>
        itd_count = <optimized out>
        again = <optimized out>
        __PRETTY_FUNCTION__ = "ehci_advance_state"
        __func__ = "ehci_advance_state"
#9  0x00005576867b2d5b in ehci_advance_periodic_state (ehci=0x55768915e360) at hw/usb/hcd-ehci.c:2209
        entry = 1994232386
        list = <optimized out>
        async = 0
        __func__ = "ehci_advance_periodic_state"
        need_timer = 1
        expire_time = <optimized out>
        t_now = 161815062737
        ns_elapsed = <optimized out>
        uframes = 1024
        i = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--
        skipped_uframes = <optimized out>
        ehci = 0x55768915e360
#10 0x00005576867b2d5b in ehci_work_bh (opaque=0x55768915e360) at hw/usb/hcd-ehci.c:2295
        need_timer = 1
        expire_time = <optimized out>
        t_now = 161815062737
        ns_elapsed = <optimized out>
        uframes = 1024
        i = <optimized out>
        skipped_uframes = <optimized out>
        ehci = 0x55768915e360
#11 0x00005576867b2d5b in ehci_work_bh (opaque=0x55768915e360) at hw/usb/hcd-ehci.c:2247
        ehci = 0x55768915e360
#12 0x000055768690ac26 in aio_bh_call (bh=0x5576891e1550) at util/async.c:117
        bh = 0x5576891e1550
        bhp = <optimized out>
        next = 0x557688de6b60
        ret = 1
        deleted = false
#13 0x000055768690ac26 in aio_bh_poll (ctx=ctx@entry=0x557688276e30) at util/async.c:117
        bh = 0x5576891e1550
        bhp = <optimized out>
        next = 0x557688de6b60
        ret = 1
        deleted = false
#14 0x000055768690e064 in aio_dispatch (ctx=0x557688276e30) at util/aio-posix.c:459
#15 0x000055768690ab02 in aio_ctx_dispatch (source=<optimized out>, callback=<optimized out>, user_data=<optimized out>) at util/async.c:260
        ctx = <optimized out>
        __PRETTY_FUNCTION__ = "aio_ctx_dispatch"
#16 0x00007f89eebb372d in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#17 0x000055768690d118 in glib_pollfds_poll () at util/main-loop.c:218
        context = 0x5576882782a0
        pfds = <optimized out>
        context = 0x5576882782a0
        ret = 0
        mlpoll = {state = 0, timeout = 1000, pollfds = 0x557688277210}
        ret = <optimized out>
        timeout_ns = <optimized out>
#18 0x000055768690d118 in os_host_main_loop_wait (timeout=<optimized out>) at util/main-loop.c:241
        context = 0x5576882782a0
        ret = 0
        mlpoll = {state = 0, timeout = 1000, pollfds = 0x557688277210}
        ret = <optimized out>
        timeout_ns = <optimized out>
#19 0x000055768690d118 in main_loop_wait (nonblocking=<optimized out>) at util/main-loop.c:517
        mlpoll = {state = 0, timeout = 1000, pollfds = 0x557688277210}
        ret = <optimized out>
        timeout_ns = <optimized out>
#20 0x00005576866f6169 in main_loop () at vl.c:1809
#21 0x00005576865a5fd3 in main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at vl.c:4506
        i = <optimized out>
        snapshot = 0
        linux_boot = <optimized out>
        initrd_filename = 0x0
        kernel_filename = 0x0
        kernel_cmdline = <optimized out>
        boot_order = 0x5576881eb840 "cdn"
        boot_once = <optimized out>
        ds = <optimized out>
        opts = <optimized out>
        machine_opts = <optimized out>
        icount_opts = <optimized out>
        accel_opts = 0x0
        olist = <optimized out>
        optind = 197
        optarg = 0x7fffd0d0759c "tcp::4333"
--Type <RET> for more, q to quit, c to continue without paging--
        loadvm = 0x0
        machine_class = 0x5576882321b0
        cpu_option = 0x7fffd0d05f60 "SandyBridge,+x2apic,hv_spinlocks=0x1fff,hv_relaxed,hv_vapic,hv_time"
        vga_model = 0x7fffd0d06015 "qxl"
        qtest_chrdev = 0x0
        qtest_log = 0x0
        incoming = 0x7fffd0d0759c "tcp::4333"
        userconfig = <optimized out>
        nographic = false
        display_remote = <optimized out>
        log_mask = <optimized out>
        log_file = <optimized out>
        trace_file = <optimized out>
        maxram_size = <optimized out>
        ram_slots = 256
        vmstate_dump_file = 0x0
        main_loop_err = 0x0
        err = 0x0
        list_data_dirs = false
        dir = <optimized out>
        bdo_queue = {sqh_first = 0x0, sqh_last = 0x7fffd0d03aa0}
        __func__ = "main"
(gdb) 

#5  0x00005576867afabc in ehci_execute (action=0x557686ab38cc "process", p=0x5576883e2a10) at hw/usb/hcd-ehci.c:1363
1363	    ep = usb_ep_get(p->queue->dev, p->pid, endp);
(gdb) list
1358	        ehci_queue_stopped(p->queue); /* Mark the ep in the prev dir stopped */
1359	    }
1360	    p->pid = ehci_get_pid(&p->qtd);
1361	    p->queue->last_pid = p->pid;
1362	    endp = get_field(p->queue->qh.epchar, QH_EPCHAR_EP);
1363	    ep = usb_ep_get(p->queue->dev, p->pid, endp);
1364	
1365	    if (p->async == EHCI_ASYNC_NONE) {
1366	        if (ehci_init_transfer(p) != 0) {
1367	            return -1;
(gdb) p *p
$1 = {queue = 0x5576893e8520, next = {tqe_next = 0x0, tqe_circ = {tql_next = 0x0, tql_prev = 0x5576893e8598}}, qtd = {next = 1994236864, altnext = 1, 
    token = 298368, bufptr = {1995777152, 0, 0, 0, 0}}, qtdaddr = 1994236672, packet = {pid = 0, id = 0, ep = 0x0, stream = 0, iov = {
      iov = 0x5576882ab820, niov = 0, {{nalloc = 1, local_iov = {iov_base = 0x0, iov_len = 0}}, {__pad = "\001\000\000\000\000\000\000\000\000\000\000", 
          size = 0}}}, parameter = 0, short_not_ok = false, int_req = false, status = 0, actual_length = 0, state = USB_PACKET_UNDEFINED, combined = 0x0, 
    queue = {tqe_next = 0x0, tqe_circ = {tql_next = 0x0, tql_prev = 0x0}}, combined_entry = {tqe_next = 0x0, tqe_circ = {tql_next = 0x0, 
        tql_prev = 0x0}}}, sgl = {sg = 0x0, nsg = 0, nalloc = 0, size = 0, dev = 0x0, as = 0x0}, pid = 105, async = EHCI_ASYNC_NONE}
(gdb)

Comment 13 Dr. David Alan Gilbert 2019-09-04 15:48:48 UTC
ehci trace from destination:
39022:usb_ehci_port_detach detach port #1, owner ehci
39022:usb_ehci_irq level 1, frindex 0x0798, sts 0x4004, mask 0x37
39022:usb_ehci_port_attach attach port #1, owner ehci, device Keyboard/Mouse Function
39022:usb_ehci_irq level 1, frindex 0x0798, sts 0x4004, mask 0x37
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4004
39047:usb_ehci_opreg_write wr mmio 0x0024 [USBSTS] = 0x4
39047:usb_ehci_usbsts usbsts PCD 0
39047:usb_ehci_irq level 0, frindex 0x08cd, sts 0x4000, mask 0x37
39047:usb_ehci_opreg_change ch mmio 0x0024 [USBSTS] = 0x4000 (old: 0x4004)
39047:usb_ehci_opreg_read rd mmio 0x0020 [USBCMD] = 0x10011
39047:usb_ehci_portsc_read rd mmio 0x0058 [port 5] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x0054 [port 4] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x0050 [port 3] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x004c [port 2] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x0048 [port 1] = 0x1003
39047:usb_ehci_portsc_read rd mmio 0x0044 [port 0] = 0x601085
39047:usb_ehci_portsc_read rd mmio 0x0044 [port 0] = 0x601085
39047:usb_ehci_portsc_read rd mmio 0x0048 [port 1] = 0x1003
39047:usb_ehci_portsc_read rd mmio 0x004c [port 2] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x0050 [port 3] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x0054 [port 4] = 0x1000
39047:usb_ehci_portsc_read rd mmio 0x0058 [port 5] = 0x1000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_portsc_read rd mmio 0x0048 [port 1] = 0x1003
39047:usb_ehci_portsc_read rd mmio 0x0048 [port 1] = 0x1003
39047:usb_ehci_portsc_write wr mmio 0x0048 [port 1] = 0x1003
39047:usb_ehci_portsc_change ch mmio 0x0048 [port 1] = 0x1001 (old: 0x1003)
39047:usb_ehci_opreg_read rd mmio 0x0020 [USBCMD] = 0x10011
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x4000
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39047:usb_ehci_opreg_read rd mmio 0x0024 [USBSTS] = 0x0
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule ACTIVE
39022:usb_ehci_state periodic schedule FETCH ENTRY
39022:usb_ehci_state periodic schedule FETCH QH
39022:usb_ehci_queue_action q 0x556ea6a0cb40: alloc
39022:usb_ehci_qh_ptrs q 0x556ea6a0cb40 - QH @ 0xbb8001e0: next 0x00000001 qtds 0xbb8013c0,0xbb801180,0x00000001
39022:usb_ehci_qh_fields QH @ 0xbb8001e0 - rl 0, mplen 8, eps 2, ep 3, dev 3
39022:usb_ehci_qh_bits QH @ 0xbb8001e0 - c 0, h 0, dtc 0, i 0
39022:usb_ehci_queue_action q 0x556ea6a0cb40: reset
39022:usb_ehci_state periodic schedule FETCH QTD
39022:usb_ehci_qtd_ptrs q 0x556ea6a0cb40 - QTD @ 0xbb8013c0: next 0xbb801180 altnext 0x00000001
39022:usb_ehci_qtd_fields QTD @ 0xbb8013c0 - tbytes 4, cpage 0, cerr 3, pid 1
39022:usb_ehci_qtd_bits QTD @ 0xbb8013c0 - ioc 1, active 1, halt 0, babble 0, xacterr 0
39022:usb_ehci_packet_action q 0x556ea6a0cb40 p 0x556ea778c000: alloc
39022:usb_ehci_state periodic schedule EXECUTE
qemu-system-x86_64: /home/dgilbert/distro/virt-rhel8-qemu-kvm/hw/usb/core.c:719: usb_ep_get: Assertion `dev != NULL' failed.

Comment 14 Dr. David Alan Gilbert 2019-09-04 16:02:24 UTC
The commit Gerd suggests in comment 6 does fix it; but I'd just like to try and understand why.

Comment 15 Dr. David Alan Gilbert 2019-09-04 18:42:29 UTC
Hmm I added some debug around usb_ehci_guest_bug:
it's reliably:
48181:usb_ehci_guest_bug usb0:0.6:no device attached to queue

usb0 is the usb controller, bus 0 and port 6; I'm not quite sure how to match that port number up:

(qemu) info usb
  Device 0.2, Port 1, Speed 480 Mb/s, Product QEMU USB Tablet, ID: input0
  Device 0.3, Port 2, Speed 480 Mb/s, Product Keyboard/Mouse Function, ID: hostdev0
  Device 1.2, Port 1, Speed 12 Mb/s, Product QEMU USB Keyboard, ID: kdb0
  Device 2.2, Port 1, Speed 12 Mb/s, Product QEMU USB Mouse, ID: mouse0
  Device 3.1, Port 1, Speed 5000 Mb/s, Product QEMU USB MSD, ID: bot1
  Device 4.2, Port 1, Speed 480 Mb/s, Product QEMU USB MSD, ID: bot2
  Device 5.2, Port 1, Speed 12 Mb/s, Product QEMU USB MSD, ID: bot3
  Device 6.2, Port 1, Speed 12 Mb/s, Product QEMU USB MSD, ID: usb-0
  Device 7.2, Port 1, Speed 480 Mb/s, Product QEMU USB MSD, ID: usb-1

(qemu) info usbhost
  Bus 1, Addr 4, Port 1.6.1, Speed 480 Mb/s
    Class 00: USB device 0624:0249, Keyboard/Mouse Function

-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 \

still; I suspect it is the rest of the mouse/keyboard after migration that's confusing it - you do see the disconnect in the logs
on the destination.

Comment 16 Dr. David Alan Gilbert 2019-09-04 18:52:56 UTC
Please try:
   https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=23360549

It has the fix that Gerd suggested.

Comment 17 Dr. David Alan Gilbert 2019-09-04 18:58:03 UTC
(Migration to 3.1 seems OK)

Comment 19 Danilo de Paula 2019-09-05 13:25:10 UTC
QA_ACK, please?

Comment 25 errata-xmlrpc 2019-11-06 07:19:01 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, 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/RHBA-2019:3723


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