1176772 – Hot-plug a virtual usb device to guest, and then restore/migrate guest failed.

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

Bug 1176772 - Hot-plug a virtual usb device to guest, and then restore/migrate guest failed.

Summary: Hot-plug a virtual usb device to guest, and then restore/migrate guest failed.

Keywords:
Status:	CLOSED DUPLICATE of bug 1215968
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	libvirt
Sub Component:
Version:	7.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	John Ferlan
QA Contact:	Virtualization Bugs
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2014-12-23 06:37 UTC by lcheng
Modified:	2016-07-25 18:09 UTC (History)
CC List:	9 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2016-07-25 18:09:10 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Bugzilla	1215968	0	high	CLOSED	Libvirt does not generate guest USB addresses	2021-02-22 00:41:40 UTC

Internal Links: 1215968

Description lcheng 2014-12-23 06:37:44 UTC

Description of problem:
Hot-plug a virtual usb device to guest, and then restore/migrate guest failed.

Version-Release number of selected component (if applicable):
qemu-kvm-rhev-2.1.2-17.el7.x86_64
libvirt-1.2.8-11.el7.x86_64

How reproducible:
100%

Steps to Reproduce:
Scenario 1: Hot-plug a virtual usb device to guest, and then save guest, restore guest failed.

1. Start a guest and attach a virtual usb disk to guest.

[root@localhost ~]# cat usb3.xml
<disk type='file' device='disk'>
<driver name='qemu' type='raw'/>
<source file='/var/lib/libvirt/images/usb.img' startupPolicy='optional'/>
<target dev='sdd' bus='usb'/>
</disk>

[root@localhost ~]# virsh start r7
Domain r7 started

[root@localhost ~]# virsh attach-device r7 usb3.xml
Device attached successfully

[root@localhost ~]# virsh dumpxml r7 | grep disk -A10
...
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/r7.qcow2'/>
      <backingStore/>
      <target dev='hda' bus='ide'/>
      <alias name='ide0-0-0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </disk>
    <disk type='file' device='disk'>
      <driver name='qemu' type='raw'/>
      <source file='/var/lib/libvirt/images/usb.img' startupPolicy='optional'/>
      <backingStore/>
      <target dev='sdd' bus='usb'/>
      <alias name='usb-disk3'/>
    </disk>
...

2. Save the guest.
[root@localhost ~]# virsh save r7 /tmp/r7.save

Domain r7 saved to /tmp/r7.save

3. Restore the guest failed.
[root@localhost ~]# virsh restore /tmp/r7.save
error: Failed to restore domain from /tmp/r7.save
error: internal error: early end of file from monitor: possible problem:
Unknown savevm section or instance '0000:00:01.2/1/usb-ptr' 0
2014-12-23T02:34:11.262949Z qemu-kvm: load of migration failed: Invalid argument


Scenario 2: Hot-plug a virtual usb device to guest, and then migrate guest failed.

1. Start a guest and attach a virtual usb disk to guest on hostA.

[root@localhost ~]# cat usb3.xml
<disk type='file' device='disk'>
<driver name='qemu' type='raw'/>
<source file='/var/lib/libvirt/images/usb.img' startupPolicy='optional'/>
<target dev='sdd' bus='usb'/>
</disk>

[root@localhost ~]# virsh start r7
Domain r7 started

[root@localhost ~]# virsh attach-device r7 usb3.xml
Device attached successfully


[root@localhost ~]# virsh dumpxml r7 | grep disk -A10
...
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2'/>
      <source file='/var/lib/libvirt/images/r7.qcow2'/>
      <backingStore/>
      <target dev='hda' bus='ide'/>
      <alias name='ide0-0-0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </disk>
    <disk type='file' device='disk'>
      <driver name='qemu' type='raw'/>
      <source file='/var/lib/libvirt/images/usb.img' startupPolicy='optional'/>
      <backingStore/>
      <target dev='sdd' bus='usb'/>
      <alias name='usb-disk3'/>
    </disk>
...
          
2. Migrate the guest from hostA to hostB.    
                                                 
[root@localhost ~]# virsh migrate --live --domain r7 qemu+ssh://10.66.82.123/system --verbose
root.82.123's password:
Migration: [ 88 %]error: internal error: early end of file from monitor: possible problem:
Unknown savevm section or instance '0000:00:01.2/1/usb-ptr' 0
2014-12-23T02:42:16.465958Z qemu-kvm: load of migration failed: Invalid argument
KVM: injection failed, MSI lost (Operation not permitted)


3. When migrate failed, the log on hostB as follows:

[root@intel-q9550-4-1 ~]# tail -f /var/log/libvirt/qemu/r7.log
LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin QEMU_AUDIO_DRV=spice /usr/libexec/qemu-kvm -name r7 -S -machine pc-i440fx-rhel7.1.0,accel=kvm,usb=off -cpu SandyBridge,-rdtscp,-avx,-aes,-tsc-deadline,-popcnt,-x2apic,-sse4.2,-pclmuldq -m 1024 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 5a56c9cd-0a1a-4fe9-ae65-f4027ff6d038 -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/r7.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=discard -no-hpet -no-shutdown -global PIIX4_PM.disable_s3=1 -global PIIX4_PM.disable_s4=1 -boot strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -drive file=/var/lib/libvirt/images/r7.qcow2,if=none,id=drive-ide0-0-0,format=qcow2 -device ide-hd,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0,bootindex=1 -drive file=/var/lib/libvirt/images/usb.img,if=none,id=drive-usb-disk3,format=raw -device usb-storage,drive=drive-usb-disk3,id=usb-disk3,removable=off -netdev tap,fd=23,id=hostnet0,vhost=on,vhostfd=26 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:db:0c:00,bus=pci.0,addr=0x3 -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 -device usb-tablet,id=input0 -spice port=5902,addr=127.0.0.1,disable-ticketing,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vgamem_mb=8,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x4 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -incoming tcp:[::]:49152 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -msg timestamp=on
char device redirected to /dev/pts/5 (label charserial0)
Unknown savevm section or instance '0000:00:01.2/1/usb-ptr' 0
2014-12-23T02:42:16.465958Z qemu-kvm: load of migration failed: Invalid argument
KVM: injection failed, MSI lost (Operation not permitted)
2014-12-23 02:42:16.667+0000: shutting down


Actual results:
As steps.


Expected results:
Restore/migrate guest successfully.


Additional info:

Comment 3 John Ferlan 2015-06-01 21:21:12 UTC

Looked into this a bit today - not sure it's a libvirt issue mostly because the error comes from qemu processing the saved file... Although my environment is slightly different, the result is the same (my guest name is f18 and I use /home/vm-images/ as a path to the usb.img and usbb.img files).

Note that the same issue is seen from the 'virsh managedsave' command which uses the same infrastructure as 'virsh save'...

Additionally, this only occurs for a hotplug'd USB device - if I add the same XML to the guest prior to starting using a different source file name of course, I can save/managedsave then restore/start the guest without issues. If I then do the hotplug, the issue happens again. Adding the device to the started guest adds "-drive file=/home/vm-images/usb.img,if=none,id=drive-usb-disk0,format=raw -device usb-storage,drive=drive-usb-disk0,id=usb-disk0,removable=off" to my command line.

Comparing things with respect to the "defined/started" device and the "hotplug" device doesn't show any obvious differences w/r/t file protections or selinux labels.  It's possible using the command :

  virsh qemu-monitor-command f18 '{"execute":"query-block"}'

to see both devices listed exactly the same except of course the filename.

Quite a bit more debug data...

Added logging to my libvirtd.log using:
< log_level = 1
< log_filters="3:remote 4:event 3:json 3:rpc"
< log_outputs="1:file:/var/log/libvirt/libvirtd.log"

Restarted libvirtd and ran through the scenario with a USB device defined at startup and one to be hotplug'd.  The following are some snippets from the libvirt debug log when adding the device and then doing the save/restore..

First the initial start:

2015-06-01 17:07:53.782+0000: 11749: debug : virCommandRunAsync:2428 : About to run LC_ALL=C LD_LIBRARY_PATH=/home/jferlan/git/libvirt.work/src/.libs PATH=/opt/cov-analysis-linux64-7.6.1/bin:/opt/cov-analysis-linux64-7.6.1/bin:/opt/cov-analysis-linux64-7.6.1/bin:/opt/cov-analysis-linux64-7.6.1/bin:/usr/lib64/ccache:/usr/local/bin:/usr/local/sbin:/usr/bin:/usr/sbin:/bin:/sbin:/home/jferlan/.local/bin:/home/jferlan/bin HOME=/root USER=jferlan LOGNAME=jferlan QEMU_AUDIO_DRV=spice /usr/bin/qemu-kvm -name f18 -S -machine pc-i440fx-1.4,accel=kvm,usb=off -m 1536 -realtime mlock=off -smp 2,sockets=2,cores=1,threads=1 -uuid abeb5797-df38-42c7-9265-c3359d409ab5 -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/f18.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=discard -no-hpet -no-shutdown -boot strict=on -device ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x5.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x5 -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x5.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x5.0x2 -device lsi,id=scsi0,bus=pci.0,addr=0xb -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -device usb-ccid,id=ccid0 -drive file=/home/vm-images/f18,if=none,id=drive-virtio-disk0,format=raw -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x7,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -drive file=/home/vm-images/usb.img,if=none,id=drive-usb-disk0,format=raw -device usb-storage,drive=drive-usb-disk0,id=usb-disk0,removable=off -netdev tap,fd=24,id=hostnet0,vhost=on,vhostfd=25 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:01:1d:d0,bus=pci.0,addr=0x3 -chardev pty,id=charconsole0 -device virtconsole,chardev=charconsole0,id=console0 -device usb-tablet,id=input0 -spice port=5900,addr=127.0.0.1,disable-ticketing,seamless-migration=on -device cirrus-vga,id=video0,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x4 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -msg timestamp=on

# touch /home/vm-images/usbb.img
# cat usb3b.xml
<disk type='file' device='disk'>
    <driver name='qemu' type='raw'/>
    <source file='/home/vm-images/usbb.img' startupPolicy='optional'/>
    <target dev='sdb' bus='usb'/>
</disk>

After 'virsh attach-device f18 usb3b.xml':

2015-06-01 17:08:07.470+0000: 11748: info : virSecuritySELinuxSetFileconHelper:890 : Setting SELinux context on '/home/vm-images/usbb.img' to 'unconfined_u:object_r:svirt_image_t:s0:c256,c286'
2015-06-01 17:08:07.470+0000: 11748: info : virSecurityDACSetOwnershipInternal:248 : Setting DAC user and group on '/home/vm-images/usbb.img' to '0:0'
2015-06-01 17:08:07.470+0000: 11748: debug : qemuSetImageCgroupInternal:85 : Allow path /home/vm-images/usbb.img, perms: rw
...
2015-06-01 17:08:07.471+0000: 11748: debug : qemuMonitorAddDrive:3015 : drive=file=/home/vm-images/usbb.img,if=none,id=drive-usb-disk1,format=raw
2015-06-01 17:08:07.471+0000: 11748: debug : qemuMonitorAddDrive:3017 : mon:0x7fffdc0094a0 vm:0x7fffac202780 json:1 fd:25
2015-06-01 17:08:07.471+0000: 11748: debug : qemuMonitorHMPCommandWithFd:1262 : mon:0x7fffdc0094a0 vm:0x7fffac202780 json:1 fd:25
2015-06-01 17:08:07.471+0000: 11748: info : qemuMonitorSend:1030 : QEMU_MONITOR_SEND_MSG: mon=0x7fffdc0094a0 msg={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/home/vm-images/usbb.img,if=none,id=drive-usb-disk1,format=raw"},"id":"libvirt-10"}^M
 fd=-1
2015-06-01 17:08:07.471+0000: 11743: info : qemuMonitorIOWrite:554 : QEMU_MONITOR_IO_WRITE: mon=0x7fffdc0094a0 buf={"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/home/vm-images/usbb.img,if=none,id=drive-usb-disk1,format=raw"},"id":"libvirt-10"}^M
 len=170 ret=170 errno=0
...
2015-06-01 17:08:07.473+0000: 11743: info : qemuMonitorIOProcess:449 : QEMU_MONITOR_IO_PROCESS: mon=0x7fffdc0094a0 buf={"return": "OK\r\n", "id": "libvirt-10"}^M
 len=42
...
2015-06-01 17:08:07.473+0000: 11748: info : qemuMonitorSend:1030 : QEMU_MONITOR_SEND_MSG: mon=0x7fffdc0094a0 msg={"execute":"device_add","arguments":{"driver":"usb-storage","drive":"drive-usb-disk1","id":"usb-disk1","removable":"off"},"id":"libvirt-11"}^M
 fd=-1
2015-06-01 17:08:07.473+0000: 11743: info : qemuMonitorIOWrite:554 : QEMU_MONITOR_IO_WRITE: mon=0x7fffdc0094a0 buf={"execute":"device_add","arguments":{"driver":"usb-storage","drive":"drive-usb-disk1","id":"usb-disk1","removable":"off"},"id":"libvirt-11"}^M
 len=142 ret=142 errno=11
...
2015-06-01 17:08:07.475+0000: 11743: info : qemuMonitorIOProcess:449 : QEMU_MONITOR_IO_PROCESS: mon=0x7fffdc0094a0 buf={"return": {}, "id": "libvirt-11"}^M
 len=36
...
2015-06-01 17:08:07.475+0000: 11748: info : qemuMonitorSend:1030 : QEMU_MONITOR_SEND_MSG: mon=0x7fffdc0094a0 msg={"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-12"}^M
 fd=-1
...
2015-06-01 17:08:07.477+0000: 11743: info : qemuMonitorIOProcess:449 : QEMU_MONITOR_IO_PROCESS: mon=0x7fffdc0094a0 buf={"return": [{"name": "usb-disk1", "type": "child<usb-storage>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "sound0-codec0", "type": "child<hda-duplex>"}, {"name": "sound0", "type": "child<intel-hda>"}, {"name": "video0", "type": "child<cirrus-vga>"}, {"name": "input0", "type": "child<usb-tablet>"}, {"name": "console0", "type": "child<virtconsole>"}, {"name": "net0", "type": "child<virtio-net-pci>"}, {"name": "usb-disk0", "type": "child<usb-storage>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "ccid0", "type": "child<usb-ccid>"}, {"name": "virtio-serial0", "type": "child<virtio-serial-pci>"}, {"name": "scsi0", "type": "child<lsi53c895a>"}, {"name": "usb", "type": "child<ich9-usb-ehci1>"}, {"name": "type", "type": "string"}], "id": "libvirt-12"}^M
 len=807
...

So it seems from libvirt's perspective that the disk was successfully attached and qom-list finds it...

Then for the save/managedsave (virsh managedsave f18):

2015-06-01 17:08:14.065+0000: 11750: info : qemuMonitorSend:1030 : QEMU_MONITOR_SEND_MSG: mon=0x7fffdc0094a0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-16"}^M
 fd=-1
015-06-01 17:08:14.065+0000: 11743: info : qemuMonitorIOWrite:554 : QEMU_MONITOR_IO_WRITE: mon=0x7fffdc0094a0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-16"}^M

after a few query-migrate's:

2015-06-01 17:08:14.066+0000: 11750: info : qemuMonitorSend:1030 : QEMU_MONITOR_SEND_MSG: mon=0x7fffdc0094a0 msg={"execute":"query-migrate","id":"libvirt-17"}^M
 fd=-1

successful save:
2015-06-01 17:08:14.429+0000: 11750: info : qemuMonitorSend:1030 : QEMU_MONITOR_SEND_MSG: mon=0x7fffdc0094a0 msg={"execute":"query-migrate","id":"libvirt-24"}^M
 fd=-1
...
2015-06-01 17:08:14.695+0000: 11743: info : qemuMonitorIOProcess:449 : QEMU_MONITOR_IO_PROCESS: mon=0x7fffdc0094a0 buf={"return": {"status": "completed", "setup-time": 7, "downtime": 315, "total-time": 629, "ram": {"total": 1619460096, "dirty-sync-count": 0, "remaining": 0, "mbps": 6053.383453, "transferred": 475843063, "duplicate": 280044, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 472399872, "normal": 115332}}, "id": "libvirt-24"}^M
 len=329
...
2015-06-01 17:08:20.841+0000: 11750: debug : virFileIsSharedFSType:2981 : Check if path /var/lib/libvirt/qemu/save/f18.save with FS magic 61267 is shared
...
2015-06-01 17:08:20.841+0000: 11750: debug : qemuProcessStop:5037 : Shutting down vm=0x7fffac202780 name=f18 id=2 pid=11822 flags=0



Followed by a restore/start (virsh start f18):

...
2015-06-01 17:08:25.738+0000: 11749: debug : virFileIsSharedFSType:2981 : Check if path /var/lib/libvirt/qemu/save/f18.save with FS magic 61267 is shared
...
2015-06-01 17:08:25.740+0000: 11749: debug : qemuProcessStart:4609 : Building emulator command line
...
2015-06-01 17:08:25.814+0000: 11749: debug : virCommandRunAsync:2428 : About to run LC_ALL=C LD_LIBRARY_PATH=/home/jferlan/git/libvirt.work/src/.libs PATH=/opt/cov-analysis-linux64-7.6.1/bin:/opt/cov-analysis-linux64-7.6.1/bin:/opt/cov-analysis-linux64-7.6.1/bin:/opt/cov-analysis-linux64-7.6.1/bin:/usr/lib64/ccache:/usr/local/bin:/usr/local/sbin:/usr/bin:/usr/sbin:/bin:/sbin:/home/jferlan/.local/bin:/home/jferlan/bin HOME=/root USER=jferlan LOGNAME=jferlan QEMU_AUDIO_DRV=spice /usr/bin/qemu-kvm -name f18 -S -machine pc-i440fx-1.4,accel=kvm,usb=off -m 1536 -realtime mlock=off -smp 2,sockets=2,cores=1,threads=1 -uuid abeb5797-df38-42c7-9265-c3359d409ab5 -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/f18.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=discard -no-hpet -no-shutdown -boot strict=on -device ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x5.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x5 -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x5.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x5.0x2 -device lsi,id=scsi0,bus=pci.0,addr=0xb -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -device usb-ccid,id=ccid0 -drive file=/home/vm-images/f18,if=none,id=drive-virtio-disk0,format=raw -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x7,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1 -drive file=/home/vm-images/usb.img,if=none,id=drive-usb-disk0,format=raw -device usb-storage,drive=drive-usb-disk0,id=usb-disk0,removable=off -drive file=/home/vm-images/usbb.img,if=none,id=drive-usb-disk1,format=raw -device usb-storage,drive=drive-usb-disk1,id=usb-disk1,removable=off -netdev tap,fd=25,id=hostnet0,vhost=on,vhostfd=26 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:01:1d:d0,bus=pci.0,addr=0x3 -chardev pty,id=charconsole0 -device virtconsole,chardev=charconsole0,id=console0 -device usb-tablet,id=input0 -spice port=5900,addr=127.0.0.1,disable-ticketing,seamless-migration=on -device cirrus-vga,id=video0,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x4 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -incoming fd:23 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -msg timestamp=on

...


2015-06-01 17:08:25.817+0000: 11749: debug : qemuProcessStart:4723 : QEMU vm=0x7fffac202780 name=f18 running with pid=12151
2015-06-01 17:08:25.817+0000: 11749: debug : qemuProcessStart:4729 : Writing early domain status to disk
2015-06-01 17:08:25.817+0000: 11749: debug : virFileMakePathHelper:2519 : path=/var/run/libvirt/qemu mode=0777
...
2015-06-01 17:08:25.831+0000: 11749: info : virSecuritySELinuxSetFileconHelper:890 : Setting SELinux context on '/home/vm-images/f18' to 'unconfined_u:object_r:svirt_image_t:s0:c317,c995'
2015-06-01 17:08:25.832+0000: 11749: info : virSecuritySELinuxSetFileconHelper:890 : Setting SELinux context on '/home/vm-images/usb.img' to 'unconfined_u:object_r:svirt_image_t:s0:c317,c995'
2015-06-01 17:08:25.832+0000: 11749: info : virSecuritySELinuxSetFileconHelper:890 : Setting SELinux context on '/home/vm-images/usbb.img' to 'unconfined_u:object_r:svirt_image_t:s0:c317,c995'
2015-06-01 17:08:25.832+0000: 11749: info : virSecuritySELinuxSetFileconHelper:890 : Setting SELinux context on '/var/lib/libvirt/qemu/save/f18.save' to 'system_u:object_r:virt_content_t:s0'
2015-06-01 17:08:25.832+0000: 11749: info : virSecurityDACSetOwnershipInternal:248 : Setting DAC user and group on '/home/vm-images/f18' to '0:0'
2015-06-01 17:08:25.832+0000: 11749: info : virSecurityDACSetOwnershipInternal:248 : Setting DAC user and group on '/home/vm-images/usb.img' to '0:0'
2015-06-01 17:08:25.832+0000: 11749: info : virSecurityDACSetOwnershipInternal:248 : Setting DAC user and group on '/home/vm-images/usbb.img' to '0:0'
...

Shortly thereafter followed by:

2015-06-01 17:08:26.752+0000: 11743: error : qemuMonitorIORead:606 : Unable to read from monitor: Connection reset by peer
2015-06-01 17:08:26.752+0000: 11743: error : qemuMonitorIO:750 : internal error: early end of file from monitor: possible problem:
Unknown savevm section or instance '0000:00:05.7/3/usb-ptr' 0
2015-06-01T17:08:26.717664Z qemu-system-x86_64: load of migration failed: Invalid argument
KVM: injection failed, MSI lost (Operation not permitted)

2015-06-01 17:08:26.752+0000: 11743: debug : qemuMonitorIO:770 : Error on monitor internal error: early end of file from monitor: possible problem:
Unknown savevm section or instance '0000:00:05.7/3/usb-ptr' 0
2015-06-01T17:08:26.717664Z qemu-system-x86_64: load of migration failed: Invalid argument
KVM: injection failed, MSI lost (Operation not permitted)

Searching the qemu sources for 'MSI lost' finds it in hw/i386/kvm/apic.c kvm_apic_mem_write(), but that's about the extent of my searching...

Searching the qemu sources finds the 'usb-ptr' as 'vmstate_usb_ptr' in hw/usb/dev-hid.c and scripts/vmstate-static-checker.py as a 'usb-mouse' or 'usb-tablet' (hmmm...)... My guest xml does have:

    <input type='tablet' bus='usb'/>
    <input type='mouse' bus='ps2'/>
    <input type='keyboard' bus='ps2'/>

but I seem to recall that being fairly standard from other guest xml.

In any case, I didn't see anything that jumped out as wrong with the libvirt code/processing. Attempting a similar process, but changing to use "<target... bus='scsi'"/> or <target... bus='virtio'>" with a different file name does work - that is a scsi or virtio device can be attached, saved, and restored.  So it's just usb that doesn't work.

NOTE: On a subsequent run, I captured the device in the guest which resulted in the same error message (I figured the process was the same so the guest view would be the same):

[root@localhost ~]# ls -alR /sys | grep sda
lrwxrwxrwx.  1 root root 0 Jun  1 15:31 sda -> ../devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda
lrwxrwxrwx.  1 root root 0 Jun  1 15:31 sda -> ../../devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda
lrwxrwxrwx. 1 root root 0 Jun  1 15:31 8:0 -> ../../devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda
drwxr-xr-x. 7 root root 0 Jun  1 15:31 sda
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda/holders:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda/power:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda/queue:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda/queue/iosched:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda/slaves:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-2/1-2:1.0/host3/target3:0:0/3:0:0:0/block/sda/trace:
[root@localhost ~]# ls -alR /sys | grep sdb
lrwxrwxrwx.  1 root root 0 Jun  1 16:45 sdb -> ../devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb
lrwxrwxrwx.  1 root root 0 Jun  1 16:45 sdb -> ../../devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb
lrwxrwxrwx. 1 root root 0 Jun  1 15:32 8:16 -> ../../devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb
drwxr-xr-x. 7 root root 0 Jun  1 15:32 sdb
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb/holders:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb/power:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb/queue:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb/queue/iosched:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb/slaves:
/sys/devices/pci0000:00/0000:00:05.7/usb1/1-4/1-4:1.0/host4/target4:0:0/4:0:0:0/block/sdb/trace:

Comment 4 John Ferlan 2015-06-04 19:38:52 UTC

With a bit of help from qemu... The "root cause" is because libvirt doesn't create addresses for usb devices, thus the restore or migration target doesn't have the correct "order" when processing the save file with the migrated/restarted domain.

In particular, my domain had a "<input type='tablet' bus='usb'/>".  When the domain starts up, there's no device address (eg usb bus & port) assigned. Thus it seems qemu chooses.  When adding the disk device it too doesn't get an address from libvirt.

When we go to restart/migrate, the disk is processed first which doesn't match the order of the save of "tablet, disk", thus the mismatch is triggered (the message is obtuse though) when a "disk" is the first expected device.

If I modify my domain to provide an address for the tablet (for example "<address type='usb' bus='0' port='4'/>") and then hot-plug the usb device I can save/restore the guest (and thus should be able to migrate as well). The same phenomena can be see with a 'usb' mouse as well.

Not sure historically why libvirt doesn't carve out usb address space like it does pci...

Comment 8 Han Han 2015-10-15 09:54:20 UTC

One more scenario to reproduce the error by usb hostdev:
1. Prepare two usb hostdev xml:
requisite.xml:
<hostdev mode='subsystem' type='usb' managed='yes'>
<source startupPolicy='requisite'>
<vendor id='0x058f'/>
<product id='0x6387'/>
</source>
</hostdev>
optional.xml: 
<hostdev mode='subsystem' type='usb' managed='yes'>
<source startupPolicy='optional'>
<vendor id='0x058f'/>
<product id='0x6387'/>
</source>
</hostdev>
2. Run following scripts:
#for i in requisite optional;do
#virsh attach-device u1 $i.xml
#virsh save u1 u1$i
#virsh list --all|grep u1
#sleep 18
#virsh restore u1$i
#virsh detach-device u1 $i.xml
#done
When restore from u1optional, get an error:
error: Failed to restore domain from u1optional
error: internal error: early end of file from monitor: possible problem:
libust[1933/1933]: Warning: HOME environment variable not set. Disabling LTTng-UST per-user tracing. (in setup_local_apps() at lttng-ust-comm.c:305)
libust[1933/1934]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:886)
libust[1933/1934]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:886)
red_dispatcher_loadvm_commands: 
2015-10-15T06:40:57.440622Z qemu-kvm: Unknown savevm section or instance '0000:00:06.7/4/usb-host' 0
2015-10-15T06:40:57.440674Z qemu-kvm: load of migration failed: Invalid argument

Comment 10 John Ferlan 2016-07-25 18:09:10 UTC

Looks like this is the same as bz 1215968, duping it.

*** This bug has been marked as a duplicate of bug 1215968 ***

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