Bug 1592582 - libvirtError: internal error: unable to execute QEMU command '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be initialized
Summary: libvirtError: internal error: unable to execute QEMU command '__com.redhat_dr...
Keywords:
Status: CLOSED DUPLICATE of bug 1547095
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: libvirt
Version: 7.5
Hardware: x86_64
OS: Linux
unspecified
urgent
Target Milestone: rc
: ---
Assignee: John Ferlan
QA Contact: Han Han
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-06-18 22:24 UTC by Siggy Sigwald
Modified: 2019-10-28 12:00 UTC (History)
16 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-08-30 11:43:43 UTC
Target Upstream Version:


Attachments (Terms of Use)
libvirtd.log (2.45 MB, text/plain)
2018-06-26 06:15 UTC, chhu
no flags Details

Description Siggy Sigwald 2018-06-18 22:24:55 UTC
Description of problem:
After updating to latest packages for RHEL 7.5 (RHOSP10) customer is not able to attach volumes to running instances. If the instance is shutdown the operation is successful.

Version-Release number of selected component (if applicable):
libvirt-daemon-kvm-3.9.0-14.el7_5.5.x86_64
qemu-kvm-common-rhev-2.10.0-21.el7_5.3.x86_64
qemu-kvm-rhev-2.10.0-21.el7_5.3.x86_64

How reproducible:
100%

Actual results:
2018-06-18 20:15:11.017 3454 ERROR nova.compute.manager [req-f03619b3-0049-41de-bdac-fa9ae677096f 5498725138c646c5bf2c71a9cf900352 a3ef19c843a34c2a95fde8e310f897bb - - -] [instance: 1a401f88-0883-4b3c-90e4-56a9d6a907bb] Failed to attach de920cd4-26d4-49b9-aba9-b0f1c26f68b5 at /dev/vdb
*******************************************************************************
2018-06-18 20:15:11.017 3454 ERROR nova.compute.manager [instance: 1a401f88-0883-4b3c-90e4-56a9d6a907bb] libvirtError: internal error: unable to execute QEMU command '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be initialized

Expected results:
Successfuly attaching the volume to the instance.

Additional info:
This is running RHOSP10z packages. The error seems to ocme from libvirt. I've found this bug that seems related: https://bugzilla.redhat.com/show_bug.cgi?id=1469235

Comment 3 jiyan 2018-06-19 09:16:15 UTC
Version:
kernel-3.10.0-862.el7.x86_64
qemu-kvm-rhev-2.10.0-21.el7_5.3.x86_64
libvirt-3.9.0-14.el7_5.5.x86_64
systemd-219-57.el7.x86_64

Steps:
# ll /dev/vg01/
total 0
lrwxrwxrwx. 1 root root 7 Jun 19 04:46 lv01 -> ../dm-4

# virsh domstate test1
shut off

# virsh start test1
Domain test1 started

# virsh attach-disk test1 /dev/vg01/lv01 vdb --targetbus virtio --driver qemu --subdriver raw
Disk attached successfully

# virsh detach-disk test1 vdb
Disk detached successfully

# lvchange -a n /dev/vg01/lv01
# lvchange -a n /dev/vg01/lv02
# lvchange -a n /dev/vg01/lv03
# lvchange -a y /dev/vg01/lv02
# lvchange -a y /dev/vg01/lv03
# lvchange -a y /dev/vg01/lv01

# ll /dev/vg01/lv01 
lrwxrwxrwx. 1 root root 7 Jun 19 05:08 /dev/vg01/lv01 -> ../dm-5

# virsh attach-disk test1 /dev/vg01/lv01 vdb --targetbus virtio --driver qemu --subdriver raw
Disk attached successfully

Hi, Siggy.
As the steps above, I can not hit the Bug 1528502 - Hotplug disk failing due to cgroups with same libvirt and qemu-kvm-rhev.

Could you provide the version of 'kernel' and 'systemd', more detailed operation steps and log? Thanks.

Comment 6 jiyan 2018-06-21 02:52:18 UTC
Hi, Siggy.

According to my colleague's analysis of RHOSP log, I still can not hit this issue in pure libvirt. We will try to reproduce in RHOSP ASAP.

1. VM in RHEL7.4 Host
libvirt-3.2.0-14.el7_4.11.x86_64
kernel-3.10.0-693.el7.x86_64
qemu-kvm-rhev-2.9.0-16.el7_4.17.x86_64

# virsh list --all
 Id    Name                           State
----------------------------------------------------
 4     bug1                           running

# virsh dumpxml bug1 |grep scsi
      <target dev='hda' bus='scsi'/>
      <alias name='scsi0-0-0-0'/>
    <controller type='scsi' index='0'>
      <alias name='scsi0'/>

# virsh dumpxml bug1 |grep cpupin
    <vcpupin vcpu='0' cpuset='1,3'/>

2. Upgrade Host to RHEL7.5
RHEL7.5
libvirt-3.9.0-14.el7_5.6.x86_64
kernel-3.10.0-862.el7.x86_64
qemu-kvm-rhev-2.10.0-21.el7_5.4.x86_64

3. Restart libvirtd and attach volume
# systemctl restart libvirtd

# virsh attach-disk bug1 /dev/sdb vdb --targetbus virtio --driver qemu --subdriver raw
Disk attached successfully

Comment 7 Xuesong Zhang 2018-06-21 03:01:40 UTC
Hi, Nathan,

We can not reproduce this BZ from pure libvirt steps, would you please help try to reproduce from RHOS env? Then we can have a analyse what's more info need libvirt QE to notice. Thx.

Comment 8 chhu 2018-06-26 06:11:02 UTC
As I found below error message in the "magui.json" as below:
-----------------------------------------------------------------
'Finds matches of error iscsid: Kernel reported iSCSI connection .*:.* error \\(1020 - ISCSI_ERR_TCP_CONN_CLOSE: TCP connection closed\\) state \\(.*\\).*"'
----------------------------------------------------------------

Then simulate the iscsi lun access issue, met similar error,
howerver, we need further check on the customer env to see if they are the same issue. 

More details as below:

Test on packages:
libvirt-3.9.0-14.el7_5.6.x86_64
qemu-kvm-rhev-2.10.0-21.el7_5.4.x86_64
kernel: kernel-3.10.0-862.6.3.el7.x86_64

Test steps:
1. Start a VM
# virsh list --all
 Id    Name                           State
----------------------------------------------------
 1     r7                             running

2. Try to attach iscsi lun to the VM before login, should met error as "No such file or directory".
# virsh attach-disk r7 /dev/disk/by-path/ip-10.66.4.104\:3260-iscsi-iqn.2017-06.com.redhat\:remotedisk2-lun-0 vdb
error: Failed to attach disk
error: Cannot access storage file '/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0': No such file or directory

3. Login to iscsi target
# iscsiadm -m node --targetname "iqn.2017-06.com.redhat:remotedisk2" --portal "10.66.4.104:3260" --login
Logging in to [iface: default, target: iqn.2017-06.com.redhat:remotedisk2, portal: 10.66.4.104,3260] (multiple)
Login to [iface: default, target: iqn.2017-06.com.redhat:remotedisk2, portal: 10.66.4.104,3260] successful.

4. Attach iscsi luns to the VM successfully
# virsh attach-disk r7 /dev/disk/by-path/ip-10.66.4.104\:3260-iscsi-iqn.2017-06.com.redhat\:remotedisk2-lun-0 vdb
Disk attached successfully

5. Login to the VM, check the disk

6. Reboot the iscsid server, no root to the iscsid server as 3260 port is no longer accessible.

7. Detach the disk in the VM
# virsh detach-disk  r7 vdb
Disk detached successfully

8. Try to attach the lun again, met error:
# virsh attach-disk r7 /dev/disk/by-path/ip-****\:3260-iscsi-iqn.2017-06.com.redhat\:remotedisk2-lun-0 vdb
error: Failed to attach disk
error: internal error: unable to execute QEMU command '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be initialized

Additional info:
libvirtd.log

Comment 9 chhu 2018-06-26 06:15:39 UTC
Created attachment 1454555 [details]
libvirtd.log

Comment 10 Marc Methot 2018-06-26 20:00:35 UTC
Hello,
Customer is not having the issue on shutdown guests, thus only on impacting live guests. Could it perhaps be the same thing that impacted https://bugzilla.redhat.com/show_bug.cgi?id=1469235 ? Which was only hotplug failures.

Their backend is NFS.
@chhu Let us know if you have any specific inquiries for our CU.

Cheers,
MM

Comment 11 chhu 2018-06-28 02:02:59 UTC
Hi, Marc

Thank you very much for above information!
Will you please help to confirm below items? Please correct them if I missing something important, thank you!

1. Reproduce steps:
Operate on rhos* with rhel7.4 libvirt/kernel/qemu-kvm-rhev
- Create image backed on nfs
  e.g. openstack image create r7_image --disk-format raw --container-format bare --file /nfs_mounted_patch/r.raw
- Create volume from the image
  e.g. openstack volume create r7-vol --size 8 --image r7_image
- Boot a VM r7 from image/volume

Upgrade to rhos12 with rhel7.5 libvirt/kernel/qemu-kvm-rhev
- Try to attach the vol:r7-vol to the VM: r7 failed
- Shutdown the VM: r7, try to attach the vol: r7_vol to VM: r7 successfully

2. On the compute node, which hit this bug, please help to run below command and upload the xmls in this bugzilla, thank you!
1) Before the attach volume operation:
- Run virsh list 
e.g.
# virsh list --all  
Id    Name                           State 
----------------------------------------------------  
11    instance-00000018              running
# virsh dumpxml instance-00000018 > instance-00000018.xml

2) After shutdown and attach the VM
- Shutdown the VM
- After attaching the volume to the VM, run virsh list 
# virsh dumpxml instance-00000018 > instance-00000018_with_volumn.xml
# virsh dumpxml instance-00000018 --inactive > instance-00000018_with_volumn_2.xml

And if you can collect the libvirtd log, and upload to this bugzilla, that would be wonderful.
1) Before doing the operations which reproduce this bug.
- Configure the libvirtd file: /etc/libvirt/libvirtd.conf
log_level = 1
log_filters = "1:qemu 1:libvirt 1:json 1:monitor 3:event 1:util 1:security"
log_outputs = "1:file:/var/log/libvirt/libvirtd.log"

- Restart the libvirtd service
- Restart nova related service

2) Do the operations, then upload the /var/log/libvirt/libvirtd.log.
 
3. In rhos, according to our former test, the VM with volume, the xml in libvirt side are as below, even if the volume is base on the image(backend local fs)
  
<disk type='block' device='disk'>       
  <driver name='qemu' type='raw' cache='none' io='native'/>       
  <source dev='/dev/disk/by-path/ip-address:3260-iscsi-iqn.2010-10.org.openstack:volume-1bb29c6a-7b4a-406b-ada7-04de824035a5-lun-0'/>
  <backingStore/>       
  <target dev='vda' bus='virtio'/>       
  <serial>1bb29c6a-7b4a-406b-ada7-04de824035a5</serial>       
  <alias name='virtio-disk0'/>       
  <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/> </disk>

And, actually in libvirt side, we can only attach volumn to a running VM, otherwise, we'll get error as below:

# virsh attach-disk r7 /dev/disk/by-path/ip-10.66.4.104\:3260-iscsi-iqn.2017-12.com.redhat\:smalldisk1-lun-0 vdb
error: Failed to attach disk
error: Requested operation is not valid: domain is not running

# cat disk2.xml
    <disk type='block' device='disk'>
      <driver name='qemu' type='raw' cache='none' io='native'/>
      <source dev='/dev/disk/by-path/ip-address:3260-iscsi-iqn.2017-12.com.redhat:smalldisk1-lun-0'/>
      <backingStore/>
      <target dev='vdc' bus='virtio'/>
      <alias name='virtio-disk2'/>
    </disk>
# virsh attach-device r7 disk2.xml
error: Failed to attach device from disk2.xml
error: Requested operation is not valid: domain is not running

Is it possible for us to access the customer env ?

Comment 13 Siggy Sigwald 2018-07-13 13:24:22 UTC
> Is it possible for us to access the customer env ?
Let me know when do you want to set up a remote session with the customer.

Comment 16 chhu 2018-07-20 07:51:14 UTC
Hi, Jarda

This bug is seems related to Bug 1469235(vdsm), Bug 1532183(libvirt),
however, QA haven't reproduced it yet, will you please help to involve one developer to have a look? You may have some advice from code analyzing, 
thank you very much!

Regards,
chhu

Comment 18 Jaroslav Suchanek 2018-07-20 12:10:56 UTC
John, can you please look into this? Thanks.

Comment 21 John Ferlan 2018-07-24 19:08:45 UTC
First impressions - a lot of data to sift through. I'll start with the initial report and provide some thoughts from the libvirtd.log

The error message "Device 'drive-virtio-disk1' could not be initialized" actually comes from QEMU - it is not a libvirt error message. So from a libvirt perspective the attempt to add the disk has passed a number of steps/challenges. Has there been any attempt to get QEMU logs?

Here's what I see from the attached libvirtd.log

... ATTEMPT #1

virDomainAttachDevice:8084 : dom=0x7fb5d40115b0, (VM: name=r7, uuid=38caa09c-6f8d-4a0d-9e38-7dd7373086a3), xml=<disk type='block'>
  <source dev='/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0'/>
  <target dev='vdb'/>
</disk>

... RESULT #1

 error : virStorageFileReportBrokenChain:427 : Cannot access storage file '/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0': No such file or directory

... ATTEMPT #2  (after what seems to be a libvirtd restart)

virDomainAttachDevice:8084 : dom=0x7fb5cc013f20, (VM: name=r7, uuid=38caa09c-6f8d-4a0d-9e38-7dd7373086a3), xml=<disk type='block'>
  <source dev='/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0'/>
  <target dev='vdb'/>
</disk>

... RESULT #2
qemuMonitorSend:1076 : QEMU_MONITOR_SEND_MSG: mon=0x7fb5cc0131c0 msg={"execute":"__com.redhat_drive_add","arguments":{"file":"/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0","format":"raw","id":"drive-virtio-disk1"},"id":"libvirt-16"}^M
qemuMonitorJSONIOProcessLine:193 : Line [{"return": {}, "id": "libvirt-16"}]
qemuMonitorJSONCommandWithFd:303 : Receive command reply ret=0 rxObject=0x563cd9b72940
qemuMonitorAddDeviceWithFd:3167 : device=virtio-blk-pci,scsi=off,bus=pci.0,addr=0x8,drive=drive-virtio-disk1,id=virtio-disk1 fd=-1 fdname=<null>
qemuMonitorJSONCommandWithFd:298 : Send command '{"execute":"device_add","arguments":{"driver":"virtio-blk-pci","scsi":"off","bus":"pci.0","addr":"0x8","drive":"drive-virtio-disk1","id":"virtio-disk1"},"id":"libvirt-17"}' for write with FD -1
qemuMonitorJSONIOProcessLine:193 : Line [{"return": {}, "id": "libvirt-17"}]
qemuMonitorJSONCommandWithFd:303 : Receive command reply ret=0 rxObject=0x563cd9b70220
 qemuMonitorJSONCommandWithFd:298 : Send command '{"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-18"}' for write with FD -1
virJSONValueFromString:1750 : string={"return": [{"name": "virtio-disk1", "type": "child<virtio-blk-pci>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "virtio-serial0", "type": "child<virtio-serial-pci>"}, {"name": "video0", "type": "child<cirrus-vga>"}, {"name": "serial0", "type": "child<isa-serial>"}, {"name": "balloon0", "type": "child<virtio-balloon-pci>"}, {"name": "channel0", "type": "child<virtserialport>"}, {"name": "net0", "type": "child<virtio-net-pci>"}, {"name": "input0", "type": "child<usb-tablet>"}, {"name": "usb", "type": "child<ich9-usb-ehci1>"}, {"name": "type", "type": "string"}], "id": "libvirt-18"}
qemuMonitorJSONCommandWithFd:303 : Receive command reply ret=0 rxObject=0x563cd9bbb560

Looks successful to me

... Followed by a DETACH: 

virDomainDetachDevice:8187 : dom=0x7fb5cc022310, (VM: name=r7, uuid=38caa09c-6f8d-4a0d-9e38-7dd7373086a3), xml=<disk type="block" device="disk">
      <driver name="qemu" type="raw"/>
      <source dev="/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0"/>
      <backingStore/>
      <target dev="vdb" bus="virtio"/>
      <alias name="virtio-disk1"/>
      <address type="pci" domain="0x0000" bus="0x00" slot="0x08" function="0x0"/>
    </disk>

... DETACH RESULT:

qemuMonitorSend:1076 : QEMU_MONITOR_SEND_MSG: mon=0x7fb5cc0131c0 msg={"execute":"device_del","arguments":{"id":"virtio-disk1"},"id":"libvirt-19"}^M
qemuMonitorJSONIOProcessLine:193 : Line [{"return": {}, "id": "libvirt-19"}]
qemuMonitorJSONCommandWithFd:303 : Receive command reply ret=0 rxObject=0x563cd9b733e0
qemuDomainRemoveDiskDevice:3641 : Removing disk virtio-disk1 from domain 0x7fb5d4016600 r7

Looks successful to me (both device and drive deleted)

... ATTEMPT #3

virDomainAttachDevice:8084 : dom=0x7fb5d80008c0, (VM: name=r7, uuid=38caa09c-6f8d-4a0d-9e38-7dd7373086a3), xml=<disk type='block'>
  <source dev='/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0'/>
  <target dev='vdb'/>
</disk>

... RESULT #3

 qemuMonitorAddDrive:3259 : drive=file=/dev/disk/by-path/ip-10.66.4.104:3260-iscsi-iqn.2017-06.com.redhat:remotedisk2-lun-0,format=raw,if=none,id=drive-virtio-disk1
qemuMonitorJSONIOProcessLine:213 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb5cc0131c0 reply={"id": "libvirt-22", "error": {"class": "GenericError", "desc": "Device 'drive-virtio-disk1' could not be initialized"}}

Obviously this fails, although it's not really clear why to me.  I don't recall any fixed issues after libvirt 3.9 where perhaps hotplug wasn't unplugging things properly (a possible reason why QEMU would fail).

----------------

So it seems there was success once Attaching the device, followed by a remove, followed by an Attach of the same device that fails.

It may be worth determining whether libvirtd restart followed by attach, detach, and attach for a block device using an iSCSI LUN is the consistent failure

I'll scan through other responses here to see what other thoughts have been provided.

Comment 22 John Ferlan 2018-07-24 19:29:56 UTC
well I see my comments would seem to be for the libvirtd.log from comment 8 - seemingly a wasted effort because it wasn't customer data. 

I have no idea where any other attachments exist - they aren't attached to this bz and clicking link supplied in comment 2 or comment 12 takes me nowhere. I don't have access to external bugs AFAIK.

Comment 10 mentions something about NFS.  That just throws another twist into the plot as NFS provides yet another layer of network/security type issues. It's been a while, but I know there has been far more effort in recent libvirt releases to be far more cautious about accessing NFS volumes properly under the right UID/GID. IIRC, definitely between RHEL 7.3 and 7.4. I think more in terms of libvirt releases.  Still as I noted in my last reply - the error comes from QEMU, so as far as libvirt is concerned things looked OK. I wouldn't be surprised at all if this turns out to be some interaction between SELinux, NFS, libvirt, and QEMU.

I'm not sure how to read all the data provided in comment 17, but it seems there was an unanswered needsinfo which got wiped out when I replied because bugzilla seems to like to wipe all needsinfo's by default.

I've restored the needsinfo, but it's for data from comment 17.

Tough to provide much more analysis without access to all the information.

Comment 23 chhu 2018-07-25 01:04:09 UTC
Hi, Nathan

We can not reproduce this BZ from pure libvirt steps, would you please help try to reproduce from RHOS env? Then we can have a analyse what's more info need libvirt QE to notice. Thank you very much!



Regards,
chhu

Comment 24 chhu 2018-07-25 03:15:53 UTC
(In reply to chhu from comment #17)
> Thanks Siggy provide the guest xmls!
> 
> Customer use cinder with nfs backend, the libvirtd log provided by customer
> don't have this error:
>  "libvirtError: internal error: unable to execute QEMU command
> '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be
> initialized".
> 
> But have below error:
> 2018-07-06 15:15:53.468+0000: 762998: error : qemuMonitorIO:719 : internal
> error: End of file from qemu monitor
> 2018-07-06 15:15:53.468+0000: 762998: debug : qemuMonitorIO:767 : Error on
> monitor internal error: End of file from qemu monitor
> 2018-07-06 15:15:53.468+0000: 762998: debug : qemuMonitorIO:788 : Triggering
> EOF callback
> 

Hi, Jonathan

1. I connected to the customer portal, and got some information, let me summarize the bug related information here, please correct them if they are not the case:

- Customer use rhos10 with rhel7.4 (libvirt 3.2.0)

- Start VM with ceph auth network disk(with OS) successfully
<disk type="network" device="disk">
<driver name="qemu" type="raw" cache="writeback" discard="unmap"/>
<auth username="openstack">
<secret type="ceph" uuid="7beff309-ed4f-46a5-b077-a1b9a35f9e21"/>
</auth>
<source protocol="rbd" name="vms/eaf1be35-4d81-4c91-aa31-ad6fecf1675d_disk">
<host name="10.214.14.20" port="6789"/>
<host name="10.214.14.21" port="6789"/>
<host name="10.214.14.22" port="6789"/>
</source>

- Customer upgarde rhos10 to rhos10.z with rhel7.5  
 (libvirt 3.9.0:libvirt-daemon-kvm-3.9.0-14.el7_5.5.x86_64, qemu-kvm-rhev-2.10.0-21.el7_5.3.x86_64), reboot the controller/compute node

- Try to attach a volume(nfs backend), but failed and hit error in this bug.

- Shutdown the VM, try to attach the volume to the VM succeed, but the VM failed to start.
<disk type="file" device="disk">
<driver name="qemu" type="raw" cache="none" io="native"/>
<source file="/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-7ec3a548-01d5-412d-95b2-0a5d741c8a21"/>
<target dev="vdb" bus="virtio"/>
<serial>7ec3a548-01d5-412d-95b2-0a5d741c8a21</serial>
<address type="pci" domain="0x0000" bus="0x00" slot="0x06" function="0x0"/>
</disk>

- the virt_use_nfs is set to "on" for both computes and controllers when the error happen.

My question is:
- the virt_use_nfs is set to "on" according to the customer reply

- Let us first rule out the problem of nfs configuration, please help to provide below information in this bugzilla:
  a. The content of nfs server export file
  b. # mount output in the nova controller and nova compute node
  c. Exactly nfs-utils/libvirt/qemu-kvm-rhev/Openstack package versions before and after upgrade.
  d. Use the nfs server in other env to make sure the nfs server is ok

2. We can't find the error message in this bug from the libvird log provided by customer, will you please help to collect the libvirtd log again ? Then we can provide to developer for further research, thank you!

1) Before doing the operations which can reproduced this bug.
- Configure the libvirtd file: /etc/libvirt/libvirtd.conf
log_level = 1
log_filters = "1:qemu 1:libvirt 1:json 1:monitor 3:event 1:util 1:security"
log_outputs = "1:file:/var/log/libvirt/libvirtd.log"

# echo "" >/var/log/libvirt/libvirtd.log

- Restart the libvirtd service
- Restart nova compute related service

2) Do the operations which reproduce this bug, then upload the /var/log/libvirt/libvirtd.log



Hi, John

Do you need some more logs for further research? Please help to list them here, thank you!



Regards,
chhu

Comment 25 John Ferlan 2018-07-25 11:35:51 UTC
BTW: A cold plug followed by a failure to start in this case is further points to QEMU or perhaps SELinux over libvirt or anything else up the stack. In the long run, QEMU will need to open the volume and I have to wonder if that's what is failing, but the more generic 'could not be initialized' message is returned.

My thoughts for other logs were along the lines of logs that bz1469235 describes. I'm not sure how to set up and get more details from QEMU. There's other elements in play here between NFS, QEMU, and SELinux. Again, the error comes from QEMU's attempt to use the volume, so "technically speaking" - I'm not sure what "up the stack" from QEMU/libvirt could provide that will get the detail needed in order to help resolve this issue. In the long run each of those would make the same API calls that something like 'virsh attach-device' would make. Another area of NFS that has caused issues is usage of the root_squash environment (/etc/exports and exportfs would provide those details).

Could be "interesting" to have some code that does an open/stat from root/root and then from qemu/qemu in the customers environment for the client volume that's being passed along to QEMU and causing the failure. The libvirt code does check if the volume exists, but if it's not creating it or managing via a storage pool, then there's not much more that's done. Continuing down that path, why not use libvirt and create an NFS storage pool (temporarily) and use virsh vol-* commands to list the pool members, the sizes, etc. That way we can "prove" (or disprove) that libvirt can open/view the volume.

Comment 26 chhu 2018-07-26 06:52:36 UTC
Hi, Jonathan

Thank you very much for the libvirtd log and mount output!

- Please help to also provide the nfs server export file:

1) On the nfs server(not the cinder): 
# cat /etc/exports
e.g. /home/images *(rw,no_root_squash,sync)

# exportfs
e.g. /home/images <world>

# ls -lah /home/images/
e.g....
-rw-rw-rw-. 1 root root 10G **** volume-ab89f710-***

2) On the cinder:
The nfs part in /etc/cinder/cinder.conf
e.g.
[nfs]
nfs_shares_config = /etc/cinder/nfs_share
volume_driver = cinder.volume.drivers.nfs.NfsDriver
volume_backend_name = nfsbackend
nfs_mount_options = "v4,soft"

3) On the nova compute:
The nfs part in /etc/nova/nova.conf
e.g.
nfs_mount_options=

- Please help to upload the VM qemu log: 
The VM which with the error happend.
e.g. # /var/log/libvirt/qemu/instance-0000d76c.log

- Prepare pool xml on compute node, and define/start a libvirt nfs pool,
use virsh vol-info to check if the libvirt can open/view the volume.

note: "/home/images" is the path in nfs server: /etc/exports

# cat nfs-pool.xml 
<pool type='netfs'>
<name>netfs</name>
<source>
<host name='nfs_server_ip'/>
<dir path='/home/images'/> 
<format type='nfs'/>
</source>
<target>
<path>/var/lib/nova/mnt</path>
</target>
</pool>

# virsh pool-define nfs-pool.xml
Pool netfs defined from nfs-pool.xml

# virsh pool-start netfs
Pool netfs started

# virsh vol-list --pool netfs
 Name                 Path                                    
------------------------------------------------------------------------------
 r7-5.qcow2           /var/lib/nova/mnt/r7-5.qcow2            
 systemd-private-17d72b9bc1574903987b80501e2bccac-systemd-machined.service-GvcZIN /var/lib/nova/mnt/systemd-private-17d72b9bc1574903987b80501e2bccac-systemd-machined.service-GvcZIN
 volume-15bac689-29d0-46cc-8efb-baebcc3371ac /var/lib/nova/mnt/volume-15bac689-29d0-46cc-8efb-baebcc3371ac
 volume-1617d737-3f8b-4764-bc40-7064999c5818 /var/lib/nova/mnt/volume-1617d737-3f8b-4764-bc40-7064999c5818
 volume-4b80b6bf-a216-4f68-849c-bd4ce82c20dc /var/lib/nova/mnt/volume-4b80b6bf-a216-4f68-849c-bd4ce82c20dc
...

If the volume is listed in above command, then try to get it's info.
e.g.
# virsh vol-info volume-1617d737-3f8b-4764-bc40-7064999c5818 --pool netfs
Name:           volume-1617d737-3f8b-4764-bc40-7064999c5818
Type:           file
Capacity:       10.00 GiB
Allocation:     1.31 GiB


Thank you!


Regards,
chhu

Comment 27 chhu 2018-07-26 07:07:48 UTC
> 
> If the volume is listed in above command, then try to get it's info.
> e.g.
> # virsh vol-info volume-1617d737-3f8b-4764-bc40-7064999c5818 --pool netfs
> Name:           volume-1617d737-3f8b-4764-bc40-7064999c5818
> Type:           file
> Capacity:       10.00 GiB
> Allocation:     1.31 GiB
> 

In order to get more information, if the volume is listed in virsh vol-list --pool netfs, please dumpxml and upload the file: error_volume.xml to this bug. Thank you!

# virsh vol-dumpxml volume-1617d737-3f8b-4764-bc40-7064999c5818 --pool netfs > error_volume.xml
 
 Regards,
 chhu

Comment 28 John Ferlan 2018-07-26 15:32:46 UTC
So, as far as libvirt is concerned, it can see the volume and get what appears to be correct sizing information for a sparse file from a storage pool. 

Whether the dumpxml output shows anything probably doesn't matter too much. It will though provide the <permissions> including mode, owner, group, and label which may be of value.

Curious - are any of the other volumes that are listed in that NFS pool used for domains? Without issue? (IOW: they can be seen/read by QEMU). Is there anything different between one of those volumes and the one failing (other than of course it's failing!).  IIRC, the volume cannot be cold plugged either. That is it cannot be listed in a domain and the domain start properly. Similar question of course then - what about other volumes in that NFS pool - can they be assigned to a guest and have it start?

Beyond that, from the output I see in the Jul25 logs chhu gave me access to on CASE 02123195...


'mount' output from "compute" (root@c2cwlkz19009)
...
/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173 type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.214.1.12,mountvers=3,mountport=20048,mountproto=udp,local_lock=none,addr=10.214.1.12)


'mount' output from "controller" (root@osc2ccntwlkz102):
...
/var/lib/cinder/mnt/f74055375761a044d3e09db0c605476d type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.214.1.12,mountvers=3,mountport=20048,mountproto=udp,local_lock=none,addr=10.214.1.12)
...

Wow, just had a strange deju vu moment related to a previous job and the rsize/wsize parameters. Wish I could recall what it was, but > 6 years is too long to recall... 

I also have a recollection something related to NFS coming up in more recent discussions, but I think that issue was related to locking problems. Not sure if that affects 7.5 or "more recent" adjustments though, but bz1547095 has a lot of information on the problem seen.

Something in the output below got me wondering... There's a call to virFileGetMountSubtreeImpl which is something in the path of namespaces support. Makes me wonder what is the value of "namespaces" is /etc/libvirt/qemu.conf? Is that related is an opaque way to bz1469235 as noted in an earlier response. IIRC, by default "mount" is in the namespaces list and one must set it to "[ ]" to disable mount being there. So if it's not set in qemu.conf, does changing to "[ ]" resolve the inability to hotplug.

As for the libvirtd.log data it seems as though things have been normally processed - the volume has cgroup adjustments, has security adjustments, and the attempt to add is done.  I've snipped out what should be the relevant parts:

...
2018-07-25 14:56:34.390+0000: 663087: info : hostname: osc2ccntwlkz105.localdomain


^^^^^^^^^^^^^^^ != osc2ccntwlkz102  ||   c2cwlkz19009

Can we assume mount output is the same on osc2ccntwlkz105 ??

...

ATTEMPT to hotplug device:

@2018-07-25 14:57:26.198+0000:
virDomainAttachDeviceFlags:8144 :
dom=0x7fa04c000bd0, (VM: name=instance-0000dab1, uuid=8d0a5442-b6ea-423c-b3b5-e1d12503c2af), xml=<disk type="file" device="disk">
  <driver name="qemu" type="raw" cache="none" io="native"/>
  <source file="/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb"/>
  <target bus="virtio" dev="vdb"/>
  <serial>ad9301d2-ba49-4774-bc6f-2154fc8c93eb</serial> 
</disk>
, flags=0x3

@2018-07-25 14:57:14.107+0000:
virDomainLockManagerAddImage:90 :
Add disk /var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb
virLockManagerAddResource:332 :
lock=0x7fa04c002550 type=0 name=/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb nparams=0 params=(nil) flags=0x0
virLockManagerAcquire:350 : 
lock=0x7fa04c002550 state='<null>' flags=0x0 action=0 fd=(nil)


@2018-07-25 14:57:14.107+0000:
virFileGetMountSubtreeImpl:1953 : prefix=/dev

Hmmm... I wonder if there's any namespace relationship...

@2018-07-25 14:57:14.116+0000: 
qemuSetupImagePathCgroup:76 : 
Allow path /var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb, perms: rw


@2018-07-25 14:57:14.117+0000:
qemuMonitorAddDrive:3259 : drive=file=/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb,format=raw,if=none,id=drive-virtio-disk1,serial=ad9301d2-ba49-4774-bc6f-2154fc8c93eb,cache=none,aio=native

qemuMonitorAddDrive:3261 : 
mon:0x7f9ffc000fc0 vm:0x7fa0082a2690 json:1 fd:23

...

qemuMonitorIOWrite:552 :
QEMU_MONITOR_IO_WRITE: mon=0x7f9ffc000fc0 msg={"execute":"__com.redhat_drive_add","arguments":{"file":"/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb","format":"raw","id":"drive-virtio-disk1","serial":"ad9301d2-ba49-4774-bc6f-2154fc8c93eb","cache":"none","aio":"native"},"id":"libvirt-22"}


FAILS:
@2018-07-25 14:57:26.195+0000
qemuMonitorIOProcess:447 : 
QEMU_MONITOR_IO_PROCESS: mon=0x7f9ffc000fc0 buf={"id": "libvirt-22", "error": {"class": "GenericError", "desc": "Device 'drive-virtio-disk1' could not be initialized"}}^M
 len=122
qemuMonitorJSONIOProcessLine:193 :
Line [{"id": "libvirt-22", "error": {"class": "GenericError", "desc": "Device 'drive-virtio-disk1' could not be initialized"}}]
...

qemuTeardownImageCgroup:160 : 
Deny path /var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb

virSecuritySELinuxRestoreFileLabel:1297 : 
Restoring SELinux context on '/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb'

virSecurityDACRestoreFileLabelInternal:664 : 
Restoring DAC user and group on '/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb'

Comment 29 chhu 2018-07-27 02:12:52 UTC
Hi, Jonathan

Please help to provide the information mentioned in comment26-28 in customer env, then developer can do further research, thank you!


Regards,
chhu

Comment 30 chhu 2018-07-28 23:41:43 UTC
Hi, Jonathan

Thank you and please help to provide this information to the customer:

>[root@c2cwlkz19009 heat-admin]# mount | grep -i nslb
>nslbwibox01nfs.fmr.com:/OpenStackCinderVolFS04 on >/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173 type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,>retrans=2,sec=sys,mountaddr=10.214.1.12,mountvers=3,mountport=20048,mountproto=>udp,local_lock=none,addr=10.214.1.12)
>nslbwibox01nfs.fmr.com:/OpenStackCinderVolFS01 on >/var/lib/nova/mnt/f74055375761a044d3e09db0c605476d type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,>retrans=2,sec=sys,mountaddr=10.214.1.12,mountvers=3,mountport=20048,mountproto=>udp,local_lock=none,addr=10.214.1.12)

>Sorry I am not understanding this "Prepare pool xml on compute node, and >define/start a libvirt nfs pool".  Based on the info above, would you be able >to send the commands? Not sure what the DIR path would be , (don't have login >access to NFS server). Is it the mount point?


You can do it like this: 

*Operations on Nova Compute*

- Touch a file as below xml file: nfs-pool.xml on the nova compute, when the volume attached to the shutoff VM, and you can see the mount output:

nslbwibox01nfs.fmr.com:/OpenStackCinderVolFS04 on /var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173 type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.214.1.12,mountvers=3,mountport=20048,mountproto=udp,local_lock=none,addr=10.214.1.12)

# cat nfs-pool.xml 
<pool type='netfs'>
<name>netfs</name>
<source>
<host name='nslbwibox01nfs.fmr.com'/>
<dir path='/OpenStackCinderVolFS04'/> 
<format type='nfs'/>
</source>
<target>
<path>/var/lib/nova/mnt</path>
</target>
</pool>

# virsh pool-define nfs-pool.xml
Pool netfs defined from nfs-pool.xml

# virsh pool-start netfs
Pool netfs started

# virsh vol-list --pool netfs

 Name                 Path                                    
------------------------------------------------------------------------------
volume-1617d737-3f8b-4764-bc40-7064999c5818 /var/lib/nova/mnt/volume-1617d737-3f8b-4764-bc40-7064999c5818
...
 
# virsh vol-dumpxml volume-1617d737-3f8b-4764-bc40-7064999c5818 --pool netfs > error_volume.xml

- Note:
1) After above operations, please help to provide the libvirtd log: /var/log/libvirt/libvirtd.log, and VM log in /var/log/libvirt/qemu/

2) The <host name='nslbwibox01nfs.fmr.com'/> you can change to ipaddr.
  e.g. 10.214.1.12 or  10.214.1.11, I'm not sure which one is correct, as from the mount output you provides these two times, the ip of the same nfs dir is changed from  10.214.1.11 to  10.214.1.12.
  Then, I wonder if you are using ceph to as the nfs server ? In that case, there should be some problem, as you set ceph with auth, it should fail to start VM with such disk by nfs xml.

-----Previous mount output-------------------------
nslbwibox01nfs.fmr.com:/OpenStackCinderVolFS04 on /var/lib/cinder/mnt/ab75b6068959d2760792fbc1e2a27173 type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.214.1.11,mountvers=3,mountport=20048,mountproto=udp,local_lock=none,addr=10.214.1.11)

3) Please set another nfs server, make sure use (rw,no_root_squash,sync), the export file like this, do related setting in cinder, and then try to attach a volume.

- nfs server
# cat /etc/exports
/home/images *(rw,no_root_squash,sync)

# systemctl restart nfs

- Do related cinder settings:
-------------------------------------------
Details similar to steps in doc: https://access.redhat.com/articles/1323213 

Make sure configured selinux
# setsebool -P virt_use_nfs on

Make sure restart openstack-cinder-volume service
# systemctl restart openstack-cinder-volume.service
 
# openstack volume service list
 Make sure the cinder-volume ***@nfs status:enabled,state:up

- Create cinder volume
------------------------------------------

- Restart nova-compute/libvirtd service
# systemctl stop openstack-nova-compute.service
# systemctl stop libvirtd
# systemctl start libvirtd
# systemctl start openstack-nova-compute.service

- Attach the volume to VM

Comment 32 John Ferlan 2018-07-31 12:57:20 UTC
I'm not sure any of those referenced cases are the same issue as this, but hopefully Fam can help (I've added a needinfo).

Fam - long story short, RHEL 7.5 (qemu-kvm-rhev-2.10.0-21.el7_5.3.x86_64) upgrade from RHEL 7.4, using NFS volume as target of a hotplug:

xml=<disk type="file" device="disk">
  <driver name="qemu" type="raw" cache="none" io="native"/>
  <source file="/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb"/>
  <target bus="virtio" dev="vdb"/>
  <serial>ad9301d2-ba49-4774-bc6f-2154fc8c93eb</serial> 
</disk>

w/ monitor command as follows 

{"execute":"__com.redhat_drive_add","arguments":{"file":"/var/lib/nova/mnt/ab75b6068959d2760792fbc1e2a27173/volume-ad9301d2-ba49-4774-bc6f-2154fc8c93eb","format":"raw","id":"drive-virtio-disk1","serial":"ad9301d2-ba49-4774-bc6f-2154fc8c93eb","cache":"none","aio":"native"},"id":"libvirt-22"}


is getting the "Device '%s' could not be initialized" error message and the guest log shows the "Failed to lock byte 100".

I recall hearing NFS and locking issues discussed at some recent block team meeting, but what the issue and/or resolution is I cannot recall. The only entrail from the meetings notes is to "Workaround: use nolock mount option".

So do you have any other thoughts or recollections in this space?

Comment 33 Fam Zheng 2018-08-01 07:12:13 UTC
If the customer configuration is with NFSv3, it's possible to hit a stale lock issue upon some serverside connection issue, e.g. when one client failed to notify the server about its release of a file lock. (BZ 1547095)

Comment 34 chhu 2018-08-02 01:39:37 UTC
Hi John

1. Customer defined the pool, and provide the # virsh vol-dumpxml output, as below: [more details in customer portal]
-------------------------------------------------------------------
<volume type="file">
<name>volume-7ec3a548-01d5-412d-95b2-0a5d741c8a21</name>
<key>
/var/lib/nova/mnt/volume-7ec3a548-01d5-412d-95b2-0a5d741c8a21
</key>
<source></source>
<capacity unit="bytes">16106127360</capacity>
<allocation unit="bytes">0</allocation>
<physical unit="bytes">16106127360</physical>
<target>
<path>
/var/lib/nova/mnt/volume-7ec3a548-01d5-412d-95b2-0a5d741c8a21
</path>
<format type="raw"/>
<permissions>
<mode>0666</mode>
<owner>0</owner>
<group>0</group>
<label>system_u:object_r:nfs_t:s0</label>
</permissions>
<timestamps>
<atime>1528832108.355732219</atime>
<mtime>1528832108.356448789</mtime>
<ctime>1533151611.664471139</ctime>
</timestamps>
</target>
</volume>

2. The guest qemu log still has the error:
"Failed to lock byte 100"

3. Customer said: "Note that we saw this issue already on each of the 3 NFS shares" and from the mount output, they used "nfs (rw,relatime,vers=3,hard...)"

4. Combined with Fam's reply, do you have some suggestion here ? Thank you!


Regards,
chhu

Comment 35 John Ferlan 2018-08-02 10:54:35 UTC
Do you mean a suggestion beyond what's provided in bz1547095? No.  Try the "o=nolock" or NFSv4.  Access to the volume is being prohibited to QEMU. There's lots of details in the referenced bz to read up on.

Comment 36 chhu 2018-08-03 01:47:37 UTC
Hi Jonathan

It seems this bug is related to BZ 1547095, will you please help to let the customer have a try with NFSv4 ? Thank you!


Regards,
chhu

Comment 37 chhu 2018-08-03 05:56:09 UTC
For the QEMU image locking bug1547095, it has been workarounded in RHV (NFSv3 mounts are using 'nolock') and in Cinder they're defaulting to NFSv4 or documenting the limitations (see Bug 1556957).

Comment 38 chhu 2018-08-07 04:21:42 UTC
(In reply to ***)
> Hello,
> 
> ****I also just found out from our *** storage vendor that currently NFS v3 is the only verison supported on the  storage array at this time.***
> 

Please help to have a try with (NFSv3 mounts are using 'nolock'), thank you !

E.g. Add 'nolock' to your nfs_mount_options for cinder.conf.

*From Cinder.conf*
[tripleo_nfs]
volume_driver=cinder.volume.drivers.nfs.NfsDriver
nfs_shares_config=/etc/cinder/shares-nfs.conf
nfs_mount_options="v3,rw,intr,nolock"
volume_backend_name=tripleo_nfs
nas_secure_file_permissions=False
nas_secure_file_operations=False

[tripleo_nfs2]
volume_backend_name=tripleo_nfs2
volume_driver=cinder.volume.drivers.nfs.NfsDriver
nfs_mount_options="v3,rw,intr,nolock"
nfs_shares_config=/etc/cinder/shares-nfs2.conf

*From Nova Compute* : /etc/nova/nova.conf
nfs_mount_options="v3,rw,intr,nolock"


Restart cinder, nova host: 
- Check the mount output: include "nolock"
From cinder: e.g.
***:/home/images on /var/lib/cinder/mnt/53836986a05977dce6c40a3a88f24802 type nfs (rw,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=***,mountvers=3,mountport=20048,mountproto=udp,local_lock=all,addr=***)


From nova-compute:
- Check the virt_use_nfs is on, otherwise, you'll hit this bug: failed to attach the volume and hit same error message
# getsebool virt_use_nfs
virt_use_nfs --> on

If it's off, please set it on, then reboot host(or stop nova-compute service, stop libvirtd service, start libvirtd service, start nova-compute service):  
#setsebool -P virt_use_nfs on


Then try to attach the volume to the VM, check the mount output in the nova-compute host. It should with "nolock", as below:
***:/home/images on /var/lib/nova/mnt/53836986a05977dce6c40a3a88f24802 type nfs (rw,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=***,mountvers=3,mountport=20048,mountproto=udp,local_lock=all,addr=***)

# nova volume-attach 5744ee05-254e-4ce0-b1c5-68df2a9a9c09 8b2e4c7f-9996-4e51-b700-aab62cb12e4a
+----------+--------------------------------------+
| Property | Value                                |
+----------+--------------------------------------+
| device   | /dev/vdb                             |
| id       | 8b2e4c7f-9996-4e51-b700-aab62cb12e4a |
| serverId | 5744ee05-254e-4ce0-b1c5-68df2a9a9c09 |
| volumeId | 8b2e4c7f-9996-4e51-b700-aab62cb12e4a |
+----------+--------------------------------------+
[root@hp-dl360g9-16 ~(keystone_admin)]# openstack volume list
+--------------------------------------+--------------+--------+------+--------------------------------------+
| ID                                   | Name         | Status | Size | Attached to                          |
+--------------------------------------+--------------+--------+------+---------
| 8b2e4c7f-9996-4e51-b700-aab62cb12e4a | r7-qcow2-vol | in-use |   10 | Attached to vm-r7-qcow2 on /dev/vdb  |
+--------------------------------------+--------------+--------+------+--------

Comment 39 chhu 2018-08-09 01:55:57 UTC
Thanks for John, Fam, Sigwald and customer!
I replied the first question of customer from libvirt side. For the cinder part, let me needinfo Nathan.

Below are the customer reply:
---------------------------------------------------------
>Thanks for the procedure. I have followed it and successfully attached volumes >to running and stopped VMs without issue!

Thank you! The using NFSv3 mounts with 'nolock' work here. The root cause of this bug is the same as:

Bug 1547095 - QEMU image locking on NFSv3 prevents VMs from getting restarted on different hosts upon an host crash, seen on RHEL 7.5

>I am asking our development team to confirm their automation runs fine now , and >will respond back .

>I have a number of follow up questions:

>1. Is this a temporary fix?

As the Bug 1547095 is CLOSED WONTFIX, using NFSv3 mounts with 'nolock' is a workaround. In Cinder they're defaulting to NFSv4 or documenting the limitations (see Bug 1556957)
 
Bug 1556957 - QEMU image locking on NFSv3 prevents VMs from getting restarted on different hosts upon an host crash, seen on RHEL 7.5

>2. Are we setting nolock because of a dependency issue between cinder, NFS, and >RHEL 7.5?

>3. I used the below to set the parameters via heat, but it only changed the >cinder.conf for the 1st NFS backend, instead of both. I had to manually update >for the 2nd backend. After the next stack update, this will get wiped.

Comment 41 John Ferlan 2018-08-30 11:43:43 UTC
Since this has been proven to be a duplicate, I'm closing it as such.

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

Comment 42 zhangjianwei 2018-12-12 08:55:01 UTC
Hi I have a similar problem,I cloudn't find the way to deal with it. please
ENV:
openstack version: ocata
libvirtd (libvirt): 2.5.0
ceph version: 10.2.9
qemu-img version: 2.8.0(Debian 1:2.8+dfsg-3ubuntu2.9~cloud1)
OS version: 
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 16.04.3 LTS
Release:	16.04
Codename:	xenial
-------------------------------------------------------------------------
setp1: create instance from the horizone and the instance is active
setp2: create volume and bind qos limit,like read_iops_sec=800, write_iops_sec=800
setp3:attach the volume to the instance, the result is success. virsh dumpxml instance-00000201 you will find 
<disk type='network' device='disk'>
      <driver name='qemu' type='raw' cache='writeback'/>
      <auth username='volumes'>
        <secret type='ceph' uuid='a5d0dd94-57c4-ae55-ffe0-7e3732a24455'/>
      </auth>
      <source protocol='rbd' name='volumes/volume-1aa48359-8d9d-4872-b2b6-e3d670e6a633'>
        <host name='172.19.16.3' port='6789'/>
        <host name='172.19.16.5' port='6789'/>
        <host name='172.19.16.6' port='6789'/>
      </source>
      <backingStore/>
      <target dev='vdc' bus='virtio'/>
      <iotune>
        <read_iops_sec>800</read_iops_sec>
        <write_iops_sec>800</write_iops_sec>
      </iotune>
      <serial>1aa48359-8d9d-4872-b2b6-e3d670e6a633</serial>
      <alias name='virtio-disk2'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x0d' function='0x0'/>
    </disk>
step4:detach the volume, the instance is OK
setp5: attach the volume again,the instance is shutdown. dmesg you will find this message:
   Dec 12 06:28:06 node-47.domain.tld libvirtd[699]: Unable to read from monitor: Connection reset by peer
   Dec 12 06:28:06 node-47.domain.tld libvirtd[699]:Unable to remove drive drive-virtio-disk2 (file=rbd:volumes/volume-1aa48359-8d9d-4872-b2b6-e3d670e6a633:id=volumes:auth_supported=cephx\;none:mon_host=172.19.16.3\:6789\;172.19.16.5\:6789\;172.19.16.6\:6789,file.password-secret=virtio-disk2-secret0,format=raw,if=none,id=drive-virtio-disk2,serial=1aa48359-8d9d-4872-b2b6-e3d67,cache=writeback,throttling.iops-read=800,throttling.iops-write=800)after failed qemuMonitorAddDevice
 File "/usr/lib/python2.7/dist-packages/libvirt.py", line 560, in attachDeviceFlags

2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [req-177f935e-b7fe-4a55-ac15-279f2e0f798e 114ecfaf0b5642aaacc7027574ac4d54 0adf527f68824bceb24278279b281d2d - - -] [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d] Failed to attach 1aa48359-8d9d-4872-b2b6-e3d670e6a633 at /dev/vdc
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d] Traceback (most recent call last):
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 4810, in _attach_volume
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     do_check_attach=False, do_driver_attach=True)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 48, in wrapped
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     ret_val = method(obj, context, *args, **kwargs)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 282, in attach
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     connector)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     self.force_reraise()
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     six.reraise(self.type_, self.value, self.tb)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 273, in attach
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     device_type=self['device_type'], encryption=encryption)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1263, in attach_volume
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     self._disconnect_volume(connection_info, disk_dev)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]     if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self)
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d] libvirtError: Unable to read from monitor: Connection reset by peer
2018-12-12 06:28:06.255 30081 ERROR nova.compute.manager [instance: 48fe54b1-abdc-4356-8ae3-ae60cdf21f1d]

but if you take out the QoS limit of volume, then attach and detach many times, the instance is not shutdown.
so I think the QoS cause this bug.


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