1825785 – NVME should be detached from vfio after VM destroyed at mirroring phase

Bug 1825785 - NVME should be detached from vfio after VM destroyed at mirroring phase

Summary: NVME should be detached from vfio after VM destroyed at mirroring phase

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux Advanced Virtualization
Classification:	Red Hat
Component:	libvirt
Sub Component:
Version:	8.2
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Target Release:	8.3
Assignee:	Michal Privoznik
QA Contact:	gaojianan
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2020-04-20 09:33 UTC by Han Han
Modified:	2020-11-17 17:48 UTC (History)
CC List:	7 users (show)
Fixed In Version:	libvirt-6.4.0-1.el8
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2020-11-17 17:48:27 UTC
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
vm xml, libvirtd log (54.35 KB, application/gzip) 2020-04-20 09:33 UTC, Han Han	no flags	Details
Libvirtd log (543.82 KB, text/plain) 2020-08-13 01:25 UTC, gaojianan	no flags	Details
View All

Description Han Han 2020-04-20 09:33:57 UTC

Created attachment 1680217 [details]
vm xml, libvirtd log

Description of problem:
As subject

Version-Release number of selected component (if applicable):
qemu-kvm-4.2.0-19.module+el8.2.0+6296+6b821950.x86_64
libvirt-6.2.0-1.el8.x86_64
kernel-4.18.0-193.el8.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Start an VM 
2. Blockcopy to a nvme dest
~ cat valid.xml 
<disk type="nvme" device="disk">
      <driver name="qemu" type="raw"/>
      <source type="pci" managed="yes" namespace="1" index="1">
        <address domain="0x0000" bus="0x44" slot="0x00" function="0x0"/>
      </source>
      <target dev="vda" bus="virtio"/>
    </disk>

~ virsh blockcopy pc vda --xml valid.xml --transient-job --wait --verbose
Block Copy: [100 %]
Now in mirroring phase

3. Destroy VM, check nvme by lsblk, then start it, do as step2
~ virsh destroy pc                                                       
Domain pc destroyed

~ virsh blockcopy pc vda --xml valid.xml --transient-job --wait --verbose
error: Requested operation is not valid: NVMe device 0000:44:00.0 already in use by driver QEMU domain pc

No nvme disk in lsblk

The vm disk xml is not changed:
~ virsh -r dumpxml pc | xmllint --xpath //disk -                                                                                                   
<disk type="file" device="disk">
      <driver name="qemu" type="qcow2"/>
      <source file="/var/lib/libvirt/images/pc-luks" index="1"/>
      <backingStore/>
      <target dev="vda" bus="virtio"/>
      <encryption format="luks">
        <secret type="passphrase" usage="luks"/>
      </encryption>
      <alias name="virtio-disk0"/>
      <address type="pci" domain="0x0000" bus="0x00" slot="0x09" function="0x0"/>
    </disk>

Actual results:
As above

Expected results:
Blockcopy in step3 pass

Additional info:

Comment 1 Michal Privoznik 2020-05-06 12:42:20 UTC

Patch proposed upstream:

https://www.redhat.com/archives/libvir-list/2020-May/msg00210.html

Comment 2 Michal Privoznik 2020-05-07 09:51:16 UTC

v2:

https://www.redhat.com/archives/libvir-list/2020-May/msg00264.html

Comment 3 Michal Privoznik 2020-05-18 13:22:10 UTC

Merged upstream as:

8fd2749b2d qemuProcessStop: Reattach NVMe disks a domain is mirroring into
0230e38384 qemuProcessStop: Use XATTRs to restore seclabels on disks a domain is mirroring into

v6.3.0-106-g8fd2749b2d

Comment 4 Michal Privoznik 2020-05-18 14:26:52 UTC

To POST per comment 3.

Comment 5 Han Han 2020-05-19 06:55:32 UTC

Passe on libvirt v6.3.0-107-gc0e04c2e62, qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64:

1. Blockcopy to a nvme dest:
➜  ~ cat /tmp/nvme.xml 
  <disk type='nvme' device='disk'>
    <driver name='qemu' type='raw'/>
    <source type='pci' managed='yes' namespace='1'>
      <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
    </source>
    <target dev='vde' bus='virtio'/>
  </disk>

➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait --verbose
Block Copy: [100 %]
Now in mirroring phase


2. Destory & start VM, blockcopy again
➜  ~ virsh destroy nvme
Domain nvme destroyed

➜  ~ virsh start nvme --console
Domain nvme started
Connected to domain nvme
Escape character is ^]

➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait --verbose
Block Copy: [100 %]
Now in mirroring phase

Comment 9 gaojianan 2020-06-11 01:46:41 UTC

Verified on :
libvirt-6.4.0-1.module+el8.3.0+6881+88468c00.x86_64
qemu-kvm-5.0.0-0.module+el8.3.0+6620+5d5e1420.x86_64

1. Blockcopy to a nvme dest:
➜  ~ lspci|grep non-v -i      
44:00.0 Non-Volatile memory controller: Intel Corporation PCIe Data Center SSD (rev 01)

➜  ~ cat /tmp/nvme.xml 
  <disk type='nvme' device='disk'>
    <driver name='qemu' type='raw'/>
    <source type='pci' managed='yes' namespace='1'>
      <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
    </source>
    <target dev='vde' bus='virtio'/>
  </disk>

➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait --verbose
Block Copy: [100 %]
Now in mirroring phase


2. Destory & start VM, blockcopy again
➜  ~ virsh destroy nvme
Domain nvme destroyed

➜  ~ virsh start nvme 
Domain nvme started

➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait --verbose
Block Copy: [100 %]
Now in mirroring phase

Work as expected,so verified.

Comment 10 gaojianan 2020-06-11 02:44:45 UTC

Since RHEL8.3 target rebase is 6.6 , so set bug status back to on_qa.

Comment 11 gaojianan 2020-08-12 09:05:59 UTC

Try to verified as nearest libvirt version:
# rpm -q libvirt qemu-kvm
libvirt-6.6.0-2.module+el8.3.0+7567+dc41c0a9.x86_64
qemu-kvm-5.0.0-2.module+el8.3.0+7379+0505d6ca.x86_64

But in step 1 :
1. Blockcopy to a nvme dest:
➜  ~ lspci|grep non-v -i      
44:00.0 Non-Volatile memory controller: Intel Corporation PCIe Data Center SSD (rev 01)

~ lsblk
NAME                                                                                   MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
sda                                                                                      8:0    0 447.1G  0 disk           
├─sda1                                                                                   8:1    0     1G  0 part  /boot    
└─sda2                                                                                   8:2    0 446.1G  0 part           
  ├─rhel_hp--dl385g10--15-root                                                         253:0    0   150G  0 lvm   /        
  └─rhel_hp--dl385g10--15-swap                                                         253:1    0  15.7G  0 lvm   [SWAP]   
nvme4n1                                                                                259:0    0 372.6G  0 disk           
├─nvme.8086-43564654373338343030513734303042474e-494e54454c205353445045444d443430304734-00000001                           
│                                                                                      253:2    0 372.6G  0 mpath          
├─nvme4n1p1                                                                            259:1    0     1G  0 part           
└─nvme4n1p2  

➜  ~ cat /tmp/nvme.xml 
  <disk type='nvme' device='disk'>
    <driver name='qemu' type='raw'/>
    <source type='pci' managed='yes' namespace='1'>
      <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
    </source>
    <target dev='vde' bus='virtio'/>
  </disk>

➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait --verbose
Copy failed

And can't find nvme disk from lsblk unless execute "vfio_adm --detach --device 0000:44:00.0" again.
lsblk
NAME                           MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
sda                              8:0    0 447.1G  0 disk 
├─sda1                           8:1    0     1G  0 part /boot
└─sda2                           8:2    0 446.1G  0 part 
  ├─rhel_hp--dl385g10--15-root 253:0    0   150G  0 lvm  /
  └─rhel_hp--dl385g10--15-swap 253:1    0  15.7G  0 lvm  [SWAP]


libvirtd log in attachment during blockcopy.
@Michal Privoznik can you help to check if this is a libvirt issue?

Comment 12 gaojianan 2020-08-13 01:25:30 UTC

Created attachment 1711228 [details]
Libvirtd log

Comment 13 Michal Privoznik 2020-08-19 16:29:48 UTC

(In reply to gaojianan from comment #11)
> Try to verified as nearest libvirt version:
> # rpm -q libvirt qemu-kvm
> libvirt-6.6.0-2.module+el8.3.0+7567+dc41c0a9.x86_64
> qemu-kvm-5.0.0-2.module+el8.3.0+7379+0505d6ca.x86_64
> 
> But in step 1 :
> 1. Blockcopy to a nvme dest:
> ➜  ~ lspci|grep non-v -i      
> 44:00.0 Non-Volatile memory controller: Intel Corporation PCIe Data Center
> SSD (rev 01)
> 
> ~ lsblk
> NAME                                                                        
> MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
> sda                                                                         
> 8:0    0 447.1G  0 disk           
> ├─sda1                                                                      
> 8:1    0     1G  0 part  /boot    
> └─sda2                                                                      
> 8:2    0 446.1G  0 part           
>   ├─rhel_hp--dl385g10--15-root                                              
> 253:0    0   150G  0 lvm   /        
>   └─rhel_hp--dl385g10--15-swap                                              
> 253:1    0  15.7G  0 lvm   [SWAP]   
> nvme4n1                                                                     
> 259:0    0 372.6G  0 disk           
> ├─nvme.8086-43564654373338343030513734303042474e-
> 494e54454c205353445045444d443430304734-00000001                           
> │                                                                           
> 253:2    0 372.6G  0 mpath          
> ├─nvme4n1p1                                                                 
> 259:1    0     1G  0 part           
> └─nvme4n1p2  
> 
> ➜  ~ cat /tmp/nvme.xml 
>   <disk type='nvme' device='disk'>
>     <driver name='qemu' type='raw'/>
>     <source type='pci' managed='yes' namespace='1'>
>       <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
>     </source>
>     <target dev='vde' bus='virtio'/>
>   </disk>
> 
> ➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait
> --verbose
> Copy failed
> 
> And can't find nvme disk from lsblk unless execute "vfio_adm --detach
> --device 0000:44:00.0" again.

After the blockcopy fails, is the nvme still bound to vfio? Because this is what I can see in the logs:

2020-08-12 09:03:59.691+0000: 18866: debug : qemuBlockJobProcessEventConcludedCopyAbort:1402 : copy job 'copy-vda-libvirt-1-format' on VM 'nvme' aborted
...
2020-08-12 09:04:00.616+0000: 18866: debug : qemuDomainStorageSourceAccessModify:7311 : src='<null>' readonly=0 force_ro=0 force_rw=0 revoke=1 chain=1

Job was aborted, now we are doing cleanup. Cgroups are cleaned up first:

2020-08-12 09:04:00.616+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.616+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.616+0000: 18866: debug : virPCIDeviceNew:1414 : 8086 0953 0000:44:00.0: initialized
2020-08-12 09:04:00.616+0000: 18866: debug : virPCIDeviceFree:1445 : 8086 0953 0000:44:00.0: freeing
2020-08-12 09:04:00.616+0000: 18866: debug : virCgroupSetValueRaw:454 : Set value '/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2d1\x2dnvme.scope/devices.deny' to 'c 10:196 rwm'
2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : qemuTeardownImageCgroup:212 : Disabling device mapper control
2020-08-12 09:04:00.617+0000: 18866: debug : virCgroupSetValueRaw:454 : Set value '/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2d1\x2dnvme.scope/devices.deny' to 'c 10:236 rwm'
2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : qemuTeardownImageCgroup:223 : Deny path /dev/vfio/51
2020-08-12 09:04:00.617+0000: 18866: debug : virCgroupSetValueRaw:454 : Set value '/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2d1\x2dnvme.scope/devices.deny' to 'c 237:0 rwm'

Followed by restoring seclabels:

2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceNew:1414 : 8086 0953 0000:44:00.0: initialized
2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceFree:1445 : 8086 0953 0000:44:00.0: freeing
2020-08-12 09:04:00.617+0000: 18866: info : virSecuritySELinuxRestoreFileLabel:1457 : Restoring SELinux context on '/dev/vfio/51'
2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceNew:1414 : 8086 0953 0000:44:00.0: initialized
2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceFree:1445 : 8086 0953 0000:44:00.0: freeing
2020-08-12 09:04:00.620+0000: 18866: debug : virFileClose:135 : Closed fd 36
2020-08-12 09:04:00.623+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.625+0000: 18866: debug : virFileClose:135 : Closed fd 36
2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34

Followed by reattaching NVMe back to the host:

2020-08-12 09:04:00.627+0000: 18866: debug : qemuDomainStorageSourceAccessModifyNVMe:7241 : Modifying access for a NVMe disk src=0x7f6b58407c50 revoke=1
2020-08-12 09:04:00.627+0000: 18866: debug : virProcessSetMaxMemLock:767 : Locked memory for process 18759 limited to 67108864 bytes
2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.627+0000: 18866: debug : virPCIDeviceNew:1414 : 8086 0953 0000:44:00.0: initialized
2020-08-12 09:04:00.627+0000: 18866: debug : virHostdevReAttachPCIDevicesImpl:1017 : Removing PCI device 0000:44:00.0 from active list
2020-08-12 09:04:00.627+0000: 18866: debug : virHostdevReAttachPCIDevicesImpl:1021 : Adding PCI device 0000:44:00.0 to inactive list
2020-08-12 09:04:00.627+0000: 18866: debug : virHostdevResetAllPCIDevices:633 : Resetting PCI device 0000:44:00.0
2020-08-12 09:04:00.627+0000: 18866: debug : virPCIDeviceConfigOpenInternal:298 : 8086 0953 0000:44:00.0: opened /sys/bus/pci/devices/0000:44:00.0/config
2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.627+0000: 18866: debug : virPCIDeviceReset:947 : Device 0000:44:00.0 is bound to vfio-pci - skip reset

Here we can see the NVMe bound to VFIO and being reattach back to the host:

2020-08-12 09:04:00.627+0000: 18866: debug : virHostdevReattachAllPCIDevices:662 : Reattaching managed PCI device 0000:44:00.0
2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34

It even triggers udev event to which libvirt reacts in a different thread:

2020-08-12 09:04:00.627+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1 opaque=0x55d50a159820
2020-08-12 09:04:00.627+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430 opaque=0x55d50a159820
2020-08-12 09:04:00.628+0000: 18634: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-12 09:04:00.628+0000: 18634: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-12 09:04:00.628+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
2020-08-12 09:04:00.628+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
2020-08-12 09:04:00.628+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.628+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
2020-08-12 09:04:00.628+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
2020-08-12 09:04:00.628+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.628+0000: 18702: debug : udevHandleOneDevice:1500 : udev action: 'remove'
2020-08-12 09:04:00.628+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.628+0000: 18702: debug : udevRemoveOneDeviceSysPath:1232 : Failed to find device to remove that has udev path '/sys/devices/virtual/vfio/51'
2020-08-12 09:04:00.639+0000: 18866: debug : virFileClose:135 : Closed fd 34

It sees vfio disappearing, which is good.

2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1 opaque=0x55d50a159820
2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430 opaque=0x55d50a159820
2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.639+0000: 18702: debug : udevHandleOneDevice:1500 : udev action: 'unbind'
2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1 opaque=0x55d50a159820
2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430 opaque=0x55d50a159820
2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-08-12 09:04:00.639+0000: 18702: debug : udevHandleOneDevice:1500 : udev action: 'add'
2020-08-12 09:04:00.639+0000: 18702: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'nvme5'
2020-08-12 09:04:00.639+0000: 18702: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'nvme' for device with sysname 'nvme5'
2020-08-12 09:04:00.639+0000: 18702: debug : udevGetDeviceType:1174 : Could not determine device type for device with sysfs name 'nvme5'
2020-08-12 09:04:00.639+0000: 18702: debug : udevAddOneDevice:1362 : Discarding device -1 0x7f6b5400aad0 /sys/devices/pci0000:40/0000:40:03.2/0000:44:00.0/nvme/nvme5

And then it sees the NVMe appearing again. But for some reason it doesn't have "nvme" driver, but NULL.

2020-08-12 09:04:00.644+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1 opaque=0x55d50a159820
2020-08-12 09:04:00.644+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430 opaque=0x55d50a159820
2020-08-12 09:04:00.644+0000: 18634: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-12 09:04:00.644+0000: 18634: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-12 09:04:00.644+0000: 18634: debug : virEventGLibHandleDispatch:114 : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
2020-08-12 09:04:00.644+0000: 18634: info : virEventGLibHandleDispatch:118 : EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
2020-08-12 09:04:00.644+0000: 18866: debug : virFileClose:135 : Closed fd 34
2020-08-12 09:04:00.644+0000: 18866: debug : virPCIDeviceReattach:1249 : Removing PCI device 0000:44:00.0 from inactive list
2020-08-12 09:04:00.644+0000: 18866: debug : virPCIDeviceFree:1445 : 8086 0953 0000:44:00.0: freeing

And here libvirt finished detaching the device.

Can you please:

1) see what driver is the NVMe bound to after virsh exits?

2) see whether this reproduces with hostdev attach & detach? I mean, if you hotplug the NVMe disk as PCI device and then hot unplug it back.

Comment 14 gaojianan 2020-08-21 02:48:42 UTC

(In reply to Michal Privoznik from comment #13)
> (In reply to gaojianan from comment #11)
> > Try to verified as nearest libvirt version:
> > # rpm -q libvirt qemu-kvm
> > libvirt-6.6.0-2.module+el8.3.0+7567+dc41c0a9.x86_64
> > qemu-kvm-5.0.0-2.module+el8.3.0+7379+0505d6ca.x86_64
> > 
> > But in step 1 :
> > 1. Blockcopy to a nvme dest:
> > ➜  ~ lspci|grep non-v -i      
> > 44:00.0 Non-Volatile memory controller: Intel Corporation PCIe Data Center
> > SSD (rev 01)
> > 
> > ~ lsblk
> > NAME                                                                        
> > MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
> > sda                                                                         
> > 8:0    0 447.1G  0 disk           
> > ├─sda1                                                                      
> > 8:1    0     1G  0 part  /boot    
> > └─sda2                                                                      
> > 8:2    0 446.1G  0 part           
> >   ├─rhel_hp--dl385g10--15-root                                              
> > 253:0    0   150G  0 lvm   /        
> >   └─rhel_hp--dl385g10--15-swap                                              
> > 253:1    0  15.7G  0 lvm   [SWAP]   
> > nvme4n1                                                                     
> > 259:0    0 372.6G  0 disk           
> > ├─nvme.8086-43564654373338343030513734303042474e-
> > 494e54454c205353445045444d443430304734-00000001                           
> > │                                                                           
> > 253:2    0 372.6G  0 mpath          
> > ├─nvme4n1p1                                                                 
> > 259:1    0     1G  0 part           
> > └─nvme4n1p2  
> > 
> > ➜  ~ cat /tmp/nvme.xml 
> >   <disk type='nvme' device='disk'>
> >     <driver name='qemu' type='raw'/>
> >     <source type='pci' managed='yes' namespace='1'>
> >       <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
> >     </source>
> >     <target dev='vde' bus='virtio'/>
> >   </disk>
> > 
> > ➜  ~ virsh blockcopy nvme vda --xml /tmp/nvme.xml --transient-job --wait
> > --verbose
> > Copy failed
> > 
> > And can't find nvme disk from lsblk unless execute "vfio_adm --detach
> > --device 0000:44:00.0" again.
> 
> After the blockcopy fails, is the nvme still bound to vfio? Because this is
> what I can see in the logs:
> 
> 2020-08-12 09:03:59.691+0000: 18866: debug :
> qemuBlockJobProcessEventConcludedCopyAbort:1402 : copy job
> 'copy-vda-libvirt-1-format' on VM 'nvme' aborted
> ...
> 2020-08-12 09:04:00.616+0000: 18866: debug :
> qemuDomainStorageSourceAccessModify:7311 : src='<null>' readonly=0
> force_ro=0 force_rw=0 revoke=1 chain=1
> 
> Job was aborted, now we are doing cleanup. Cgroups are cleaned up first:
> 
> 2020-08-12 09:04:00.616+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.616+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.616+0000: 18866: debug : virPCIDeviceNew:1414 : 8086
> 0953 0000:44:00.0: initialized
> 2020-08-12 09:04:00.616+0000: 18866: debug : virPCIDeviceFree:1445 : 8086
> 0953 0000:44:00.0: freeing
> 2020-08-12 09:04:00.616+0000: 18866: debug : virCgroupSetValueRaw:454 : Set
> value
> '/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2d1\x2dnvme.scope/
> devices.deny' to 'c 10:196 rwm'
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : qemuTeardownImageCgroup:212 :
> Disabling device mapper control
> 2020-08-12 09:04:00.617+0000: 18866: debug : virCgroupSetValueRaw:454 : Set
> value
> '/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2d1\x2dnvme.scope/
> devices.deny' to 'c 10:236 rwm'
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : qemuTeardownImageCgroup:223 :
> Deny path /dev/vfio/51
> 2020-08-12 09:04:00.617+0000: 18866: debug : virCgroupSetValueRaw:454 : Set
> value
> '/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2d1\x2dnvme.scope/
> devices.deny' to 'c 237:0 rwm'
> 
> Followed by restoring seclabels:
> 
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceNew:1414 : 8086
> 0953 0000:44:00.0: initialized
> 2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceFree:1445 : 8086
> 0953 0000:44:00.0: freeing
> 2020-08-12 09:04:00.617+0000: 18866: info :
> virSecuritySELinuxRestoreFileLabel:1457 : Restoring SELinux context on
> '/dev/vfio/51'
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceNew:1414 : 8086
> 0953 0000:44:00.0: initialized
> 2020-08-12 09:04:00.617+0000: 18866: debug : virPCIDeviceFree:1445 : 8086
> 0953 0000:44:00.0: freeing
> 2020-08-12 09:04:00.620+0000: 18866: debug : virFileClose:135 : Closed fd 36
> 2020-08-12 09:04:00.623+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.625+0000: 18866: debug : virFileClose:135 : Closed fd 36
> 2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 
> Followed by reattaching NVMe back to the host:
> 
> 2020-08-12 09:04:00.627+0000: 18866: debug :
> qemuDomainStorageSourceAccessModifyNVMe:7241 : Modifying access for a NVMe
> disk src=0x7f6b58407c50 revoke=1
> 2020-08-12 09:04:00.627+0000: 18866: debug : virProcessSetMaxMemLock:767 :
> Locked memory for process 18759 limited to 67108864 bytes
> 2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.627+0000: 18866: debug : virPCIDeviceNew:1414 : 8086
> 0953 0000:44:00.0: initialized
> 2020-08-12 09:04:00.627+0000: 18866: debug :
> virHostdevReAttachPCIDevicesImpl:1017 : Removing PCI device 0000:44:00.0
> from active list
> 2020-08-12 09:04:00.627+0000: 18866: debug :
> virHostdevReAttachPCIDevicesImpl:1021 : Adding PCI device 0000:44:00.0 to
> inactive list
> 2020-08-12 09:04:00.627+0000: 18866: debug :
> virHostdevResetAllPCIDevices:633 : Resetting PCI device 0000:44:00.0
> 2020-08-12 09:04:00.627+0000: 18866: debug :
> virPCIDeviceConfigOpenInternal:298 : 8086 0953 0000:44:00.0: opened
> /sys/bus/pci/devices/0000:44:00.0/config
> 2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.627+0000: 18866: debug : virPCIDeviceReset:947 : Device
> 0000:44:00.0 is bound to vfio-pci - skip reset
> 
> Here we can see the NVMe bound to VFIO and being reattach back to the host:
> 
> 2020-08-12 09:04:00.627+0000: 18866: debug :
> virHostdevReattachAllPCIDevices:662 : Reattaching managed PCI device
> 0000:44:00.0
> 2020-08-12 09:04:00.627+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 
> It even triggers udev event to which libvirt reacts in a different thread:
> 
> 2020-08-12 09:04:00.627+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.627+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.628+0000: 18634: debug : virNetlinkEventCallback:862 :
> dispatching to max 0 clients, called from event watch 6
> 2020-08-12 09:04:00.628+0000: 18634: debug : virNetlinkEventCallback:875 :
> event not handled.
> 2020-08-12 09:04:00.628+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
> 2020-08-12 09:04:00.628+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
> 2020-08-12 09:04:00.628+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.628+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
> 2020-08-12 09:04:00.628+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
> 2020-08-12 09:04:00.628+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.628+0000: 18702: debug : udevHandleOneDevice:1500 : udev
> action: 'remove'
> 2020-08-12 09:04:00.628+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.628+0000: 18702: debug : udevRemoveOneDeviceSysPath:1232
> : Failed to find device to remove that has udev path
> '/sys/devices/virtual/vfio/51'
> 2020-08-12 09:04:00.639+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 
> It sees vfio disappearing, which is good.
> 
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:862 :
> dispatching to max 0 clients, called from event watch 6
> 2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:875 :
> event not handled.
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
> 2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.639+0000: 18702: debug : udevHandleOneDevice:1500 : udev
> action: 'unbind'
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:862 :
> dispatching to max 0 clients, called from event watch 6
> 2020-08-12 09:04:00.639+0000: 18634: debug : virNetlinkEventCallback:875 :
> event not handled.
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
> 2020-08-12 09:04:00.639+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.639+0000: 18634: debug : virEventRunDefaultImpl:340 :
> running default event implementation
> 2020-08-12 09:04:00.639+0000: 18702: debug : udevHandleOneDevice:1500 : udev
> action: 'add'
> 2020-08-12 09:04:00.639+0000: 18702: debug : udevGetDeviceProperty:145 :
> Found property key 'DRIVER' value '<null>' for device with sysname 'nvme5'
> 2020-08-12 09:04:00.639+0000: 18702: debug : udevGetDeviceProperty:145 :
> Found property key 'SUBSYSTEM' value 'nvme' for device with sysname 'nvme5'
> 2020-08-12 09:04:00.639+0000: 18702: debug : udevGetDeviceType:1174 : Could
> not determine device type for device with sysfs name 'nvme5'
> 2020-08-12 09:04:00.639+0000: 18702: debug : udevAddOneDevice:1362 :
> Discarding device -1 0x7f6b5400aad0
> /sys/devices/pci0000:40/0000:40:03.2/0000:44:00.0/nvme/nvme5
> 
> And then it sees the NVMe appearing again. But for some reason it doesn't
> have "nvme" driver, but NULL.
> 
> 2020-08-12 09:04:00.644+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x55d50a14dd70 watch=6 fd=14 events=1
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.644+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=6 events=1 cb=0x7f6bcdaa6430
> opaque=0x55d50a159820
> 2020-08-12 09:04:00.644+0000: 18634: debug : virNetlinkEventCallback:862 :
> dispatching to max 0 clients, called from event watch 6
> 2020-08-12 09:04:00.644+0000: 18634: debug : virNetlinkEventCallback:875 :
> event not handled.
> 2020-08-12 09:04:00.644+0000: 18634: debug : virEventGLibHandleDispatch:114
> : Dispatch handler data=0x7f6b58104990 watch=9 fd=27 events=1 opaque=(nil)
> 2020-08-12 09:04:00.644+0000: 18634: info : virEventGLibHandleDispatch:118 :
> EVENT_GLIB_DISPATCH_HANDLE: watch=9 events=1 cb=0x7f6b77c36870 opaque=(nil)
> 2020-08-12 09:04:00.644+0000: 18866: debug : virFileClose:135 : Closed fd 34
> 2020-08-12 09:04:00.644+0000: 18866: debug : virPCIDeviceReattach:1249 :
> Removing PCI device 0000:44:00.0 from inactive list
> 2020-08-12 09:04:00.644+0000: 18866: debug : virPCIDeviceFree:1445 : 8086
> 0953 0000:44:00.0: freeing
> 
> And here libvirt finished detaching the device.
> 
> Can you please:
> 
> 1) see what driver is the NVMe bound to after virsh exits?
> 
> 2) see whether this reproduces with hostdev attach & detach? I mean, if you
> hotplug the NVMe disk as PCI device and then hot unplug it back.



Try again with "hotplug the NVMe disk as PCI device and then hot unplug it back",it also doesn't work well.
Step:
1.Before attach the nvme disk:
# lshw |grep nvme -A13
           *-nvme
                description: NVMe device
                product: INTEL SSDPEDMD400G4
                vendor: Intel Corporation
                physical id: 0
                bus info: pci@0000:44:00.0
                logical name: /dev/nvme2
                version: 8DV10171
                serial: CVFT738400Q7400BGN
                width: 64 bits
                clock: 33MHz
                capabilities: nvme pm msix pciexpress nvm_express bus_master cap_list rom
                configuration: driver=nvme latency=0 nqn=nqn.2014.08.org.nvmexpress:80868086CVFT738400Q7400BGN  INTEL SSDPEDMD400G4 state=live
                resources: irq:89 memory:d1400000-d1403fff memory:d1410000-d141ffff

2.Hot-plug the nvme disk:
➜  ~ virsh attach-device nvme nvme.xml        
Device attached successfully

➜  ~ virsh domblklist nvme
 Target   Source
----------------------------------------
 vda      /var/lib/libvirt/images/test
 vdb      nvme://0000:44:00.0/1

and then hot-unplug the nvme disk:
# virsh detach-device nvme nvme.xml
Device detached successfully

# virsh domblklist nvme            
 Target   Source
----------------------------------------
 vda      /var/lib/libvirt/images/test

lshw |grep nvme -A13
           *-nvme UNCLAIMED                                   -------------------->>>here become UNCLAIMED status
                description: Non-Volatile memory controller
                product: PCIe Data Center SSD
                vendor: Intel Corporation
                physical id: 0
                bus info: pci@0000:44:00.0
                version: 01
                width: 64 bits
                clock: 33MHz
                capabilities: nvme pm msix pciexpress nvm_express cap_list
                configuration: latency=0
                resources: memory:d1400000-d1403fff memory:d1410000-d141ffff

And i found the log during hot-unplug:
2020-08-21 02:33:58.781+0000: 451980: debug : qemuDomainStorageSourceAccessModifyNVMe:7241 : Modifying access for a NVMe disk src=0x7f12f01168d0 revoke=1
2020-08-21 02:33:58.781+0000: 451980: debug : virProcessSetMaxMemLock:767 : Locked memory for process 451876 limited to 67108864 bytes
2020-08-21 02:33:58.781+0000: 451980: debug : virFileClose:135 : Closed fd 29
2020-08-21 02:33:58.781+0000: 451980: debug : virFileClose:135 : Closed fd 29
2020-08-21 02:33:58.781+0000: 451980: debug : virPCIDeviceNew:1414 : 8086 0953 0000:44:00.0: initialized
2020-08-21 02:33:58.781+0000: 451980: debug : virHostdevReAttachPCIDevicesImpl:1017 : Removing PCI device 0000:44:00.0 from active list
2020-08-21 02:33:58.781+0000: 451980: debug : virHostdevReAttachPCIDevicesImpl:1021 : Adding PCI device 0000:44:00.0 to inactive list
2020-08-21 02:33:58.781+0000: 451980: debug : virHostdevResetAllPCIDevices:633 : Resetting PCI device 0000:44:00.0
2020-08-21 02:33:58.781+0000: 451980: debug : virPCIDeviceConfigOpenInternal:298 : 8086 0953 0000:44:00.0: opened /sys/bus/pci/devices/0000:44:00.0/config
2020-08-21 02:33:58.782+0000: 451980: debug : virFileClose:135 : Closed fd 29
2020-08-21 02:33:58.782+0000: 451980: debug : virPCIDeviceReset:947 : Device 0000:44:00.0 is bound to vfio-pci - skip reset
2020-08-21 02:33:58.782+0000: 451980: debug : virHostdevReattachAllPCIDevices:662 : Reattaching managed PCI device 0000:44:00.0
2020-08-21 02:33:58.782+0000: 451980: debug : virFileClose:135 : Closed fd 29
2020-08-21 02:33:58.782+0000: 450787: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-21 02:33:58.782+0000: 450787: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-21 02:33:58.782+0000: 450861: debug : udevHandleOneDevice:1500 : udev action: 'remove'
2020-08-21 02:33:58.783+0000: 450861: debug : udevRemoveOneDeviceSysPath:1232 : Failed to find device to remove that has udev path '/sys/devices/virtual/vfio/51'
2020-08-21 02:33:58.795+0000: 450787: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-21 02:33:58.795+0000: 450787: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-21 02:33:58.795+0000: 451980: debug : virFileClose:135 : Closed fd 29
2020-08-21 02:33:58.795+0000: 450861: debug : udevHandleOneDevice:1500 : udev action: 'unbind'
2020-08-21 02:33:58.796+0000: 450787: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-21 02:33:58.796+0000: 450787: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-21 02:33:58.796+0000: 450861: debug : udevHandleOneDevice:1500 : udev action: 'add'
2020-08-21 02:33:58.796+0000: 450861: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'nvme1'     ----->>>>>> still '<null>'
2020-08-21 02:33:58.796+0000: 450861: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'nvme' for device with sysname 'nvme1'
2020-08-21 02:33:58.796+0000: 450861: debug : udevGetDeviceType:1174 : Could not determine device type for device with sysfs name 'nvme1'
2020-08-21 02:33:58.796+0000: 450861: debug : udevAddOneDevice:1362 : Discarding device -1 0x7f12ec007c30 /sys/devices/pci0000:40/0000:40:03.2/0000:44:00.0/nvme/nvme1                 ---------------->>>>>>>>>>>and descarding the device here as before
2020-08-21 02:33:58.801+0000: 451980: debug : virFileClose:135 : Closed fd 29
2020-08-21 02:33:58.802+0000: 451980: debug : virPCIDeviceReattach:1249 : Removing PCI device 0000:44:00.0 from inactive list
2020-08-21 02:33:58.802+0000: 451980: debug : virPCIDeviceFree:1445 : 8086 0953 0000:44:00.0: freeing
2020-08-21 02:33:58.801+0000: 450787: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 6
2020-08-21 02:33:58.802+0000: 450787: debug : virNetlinkEventCallback:875 : event not handled.
2020-08-21 02:33:58.802+0000: 451980: debug : virPCIDeviceFree:1445 : 8086 0953 0000:44:00.0: freeing
2020-08-21 02:33:58.802+0000: 451980: debug : virDomainLockImageDetach:291 : plugin=0x7f12f0107310 dom=0x56541fad16a0 src=0x7f12f01168d0
2020-08-21 02:33:58.802+0000: 451980: debug : virDomainLockManagerNew:134 : plugin=0x7f12f0107310 dom=0x56541fad16a0 withResources=0
2020-08-21 02:33:58.802+0000: 451980: debug : virLockManagerPluginGetDriver:277 : plugin=0x7f12f0107310

Comment 15 Michal Privoznik 2020-08-21 16:59:59 UTC

(In reply to gaojianan from comment #14)

> 
> Try again with "hotplug the NVMe disk as PCI device and then hot unplug it
> back",it also doesn't work well.
> Step:
> 1.Before attach the nvme disk:
> # lshw |grep nvme -A13
>            *-nvme
>                 description: NVMe device
>                 product: INTEL SSDPEDMD400G4
>                 vendor: Intel Corporation
>                 physical id: 0
>                 bus info: pci@0000:44:00.0
>                 logical name: /dev/nvme2
>                 version: 8DV10171
>                 serial: CVFT738400Q7400BGN
>                 width: 64 bits
>                 clock: 33MHz
>                 capabilities: nvme pm msix pciexpress nvm_express bus_master
> cap_list rom
>                 configuration: driver=nvme latency=0
> nqn=nqn.2014.08.org.nvmexpress:80868086CVFT738400Q7400BGN  INTEL
> SSDPEDMD400G4 state=live
>                 resources: irq:89 memory:d1400000-d1403fff
> memory:d1410000-d141ffff
> 
> 2.Hot-plug the nvme disk:
> ➜  ~ virsh attach-device nvme nvme.xml        
> Device attached successfully
> 
> ➜  ~ virsh domblklist nvme
>  Target   Source
> ----------------------------------------
>  vda      /var/lib/libvirt/images/test
>  vdb      nvme://0000:44:00.0/1

This hotplugged the nvme disk as a virtio disk into the guest. What I meant was more like this:

     <hostdev mode='subsystem' type='pci' managed='yes'>
       <source>
         <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
       </source>
     </hostdev>

And if you detach it again, does the host register it as a nvme disk again? Because this smells like a kernel bug to me.

Comment 16 gaojianan 2020-08-26 02:54:33 UTC

(In reply to Michal Privoznik from comment #15)

> This hotplugged the nvme disk as a virtio disk into the guest. What I meant
> was more like this:
> 
>      <hostdev mode='subsystem' type='pci' managed='yes'>
>        <source>
>          <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
>        </source>
>      </hostdev>
> 
> And if you detach it again, does the host register it as a nvme disk again?
> Because this smells like a kernel bug to me.

Try again to hot-plug the nvme disk into disk as hostdev,
1.# cat nvme.xml 
 <hostdev mode='subsystem' type='pci' managed='yes'>
       <source>
         <address domain='0x0000' bus='0x44' slot='0x00' function='0x0'/>
       </source>
     </hostdev>

# virsh attach-device nvme nvme.xml
Device attached successfully

2.And then login to the guest and check disk:
➜  ~ virsh console nvme
Connected to domain nvme
Escape character is ^] (Ctrl + ])

[root@localhost ~]# lsblk
NAME          MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
vda           252:0    0  10G  0 disk 
├─vda1        252:1    0   1G  0 part /boot
└─vda2        252:2    0   9G  0 part 
  ├─rhel-root 253:0    0   8G  0 lvm  /
  └─rhel-swap 253:1    0   1G  0 lvm  [SWAP]
[root@localhost ~]# [  359.448052] nvme nvme0: Device not ready; aborting initialisation
[  359.449598] nvme nvme0: Removing after probe failure status: -19

Not find the new scsi disk and get remove failure.

3.Logout and detach the device
# virsh detach-device nvme nvme.xml
Device detached successfully

# lsblk
NAME                                                                                                MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
sda                                                                                                   8:0    0 447.1G  0 disk  
├─sda1                                                                                                8:1    0     1G  0 part  /boot
└─sda2                                                                                                8:2    0 446.1G  0 part  
  ├─rhel_hp--dl385g10--15-root                                                                      253:0    0   250G  0 lvm   /
  └─rhel_hp--dl385g10--15-swap                                                                      253:1    0  15.7G  0 lvm   [SWAP]
nvme4n1                                                                                             259:0    0 372.6G  0 disk  
├─nvme.8086-43564654373338343030513734303042474e-494e54454c205353445045444d443430304734-00000001    253:2    0 372.6G  0 mpath 
│ ├─nvme.8086-43564654373338343030513734303042474e-494e54454c205353445045444d443430304734-00000001p1
│ │                                                                                                 253:3    0     1G  0 part  
│ └─nvme.8086-43564654373338343030513734303042474e-494e54454c205353445045444d443430304734-00000001p2
│                                                                                                   253:4    0     9G  0 part  
├─nvme4n1p1                                                                                         259:1    0     1G  0 part  
└─nvme4n1p2   

nvme disk has back !

Comment 17 Michal Privoznik 2020-08-26 07:41:15 UTC

(In reply to gaojianan from comment #16)

> [root@localhost ~]# lsblk
> NAME          MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
> vda           252:0    0  10G  0 disk 
> ├─vda1        252:1    0   1G  0 part /boot
> └─vda2        252:2    0   9G  0 part 
>   ├─rhel-root 253:0    0   8G  0 lvm  /
>   └─rhel-swap 253:1    0   1G  0 lvm  [SWAP]
> [root@localhost ~]# [  359.448052] nvme nvme0: Device not ready; aborting
> initialisation
> [  359.449598] nvme nvme0: Removing after probe failure status: -19
> 
> Not find the new scsi disk and get remove failure.

This looks very suspicious. I guess there is something wrong with the host kernel. I don't think this is a libvirt bug.

Comment 18 gaojianan 2020-09-03 02:38:51 UTC

(In reply to Michal Privoznik from comment #17)
> (In reply to gaojianan from comment #16)
> 
> > [root@localhost ~]# lsblk
> > NAME          MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
> > vda           252:0    0  10G  0 disk 
> > ├─vda1        252:1    0   1G  0 part /boot
> > └─vda2        252:2    0   9G  0 part 
> >   ├─rhel-root 253:0    0   8G  0 lvm  /
> >   └─rhel-swap 253:1    0   1G  0 lvm  [SWAP]
> > [root@localhost ~]# [  359.448052] nvme nvme0: Device not ready; aborting
> > initialisation
> > [  359.449598] nvme nvme0: Removing after probe failure status: -19
> > 
> > Not find the new scsi disk and get remove failure.
> 
> This looks very suspicious. I guess there is something wrong with the host
> kernel. I don't think this is a libvirt bug.

Maybe yes,it works well as https://bugzilla.redhat.com/show_bug.cgi?id=1825785#c9 in new kernel version:
kernel-4.18.0-234.el8.x86_64.
So verified this bug at libvirt version:
libvirt-6.6.0-4.module+el8.3.0+7883+3d717aa8.x86_64

Comment 21 errata-xmlrpc 2020-11-17 17:48:27 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 (virt:8.3 bug fix and enhancement update), and where to find the updated
files, follow the link below.

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

https://access.redhat.com/errata/RHBA-2020:5137

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