Bug 1346566

Can you please make an environment available to me in order to debug, test, and fix this...  I need to work through the mechanics of a fix with a real environment.

In scenario one, for some reason the delete path isn't removing the partition when it would seems it should be *and* it's not overwriting the error we got at create, so that says to me that perhaps the 'parted $src_path rm $part_num' isn't getting the right parameters. Also it seems something is "odd" in the results especially since setting part_separator='yes' is supposed to add the 'p' to the results, but it doesn't seem to be happening as seen with the the ll /dev/mapper/mpathc* showing a partition of "/dev/mapper/mpathc1". 

In scenario two, the create command actually looks right, but I assume the results were similar with creation of a "mpathc1" instead of "mpathcp1". The error message is also perplexing which leads me to believe the logic felt it created the partition with the correct name, but that name wasn't really set that way. There's no "ll /dev/mapper/mpathc*" on these results to confirm my suspicion. It seems the logic to force the usage of the "p" in the name isn't quite right as we think there should be one, but one doesn't exist and the parthelper logic doesn't pick up on that. It prints out using the name which allows the caller to think it's right, but in reality it's not.

Added a see also to bug 1265694 in order to help recall the genesis of this.

and naturally very shortly after sending comment 1 the lightbulb goes on inside my head...

The part_separator='yes' would be more useful when user_friendly_names=no.

The goal for part_separator wasn't meant to override multipath, but rather handle what devmapper would create if user_friendly_names wasn't set. If not set, then multipath would create devices with the "p" separator regardless of whether the path to the device ended with a letter, e.g. for the first partition using source path "/dev/mapper/mpatha" would be "/dev/mapper/mpathap1".

So in a way, the scenario two is expected results, although it's something I can document more clearly as a part of fixing the first issue.

Now whether it's possible to force a name to be something - well that's possible with certain caveats that would be difficult to support. It's possible to use 'parted name @partition @name' in order to set a partition name, but it only works for certain disklabels (Mac, PC98, and GPT currently).  Furthermore, how does one rationalize "/dev/mapper/nameone1" and "/dev/mapper/nametwo1" especially of the source path was "/dev/mapper/name"?  Mind boggling.

Since I don't normally work with mpath devices it's not clear from your response what you meant by generating the mpath device.

So here's what I did... Scouted around using 'lsscsi -tg' and 'dmsetup deps -o devname'... Then I found that a pool using 'bugtest' existed already using /dev/mapper/mpathb. So I figured I'd just use that since mpathb used 'sdc' and 'sde' which were both part of 'scsi_host1'.

Started the 'bugtest' pool and a vol-list found there were two partitions already:

# virsh vol-list bugtest --details
 Name     Path                 Type      Capacity   Allocation
---------------------------------------------------------------
 mpathb1  /dev/mapper/mpathb1  block    20.00 GiB    20.00 GiB
 mpathb2  /dev/mapper/mpathb2  block  1023.50 KiB  1023.50 KiB

#

Now that I had an environment "just before" trying to create a new partition, I created /etc/libvirt/libvirtd.conf.debug and /etc/libvirt/libvirtd.conf.clean from /etc/libvirtd.conf.  I then cp'd .debug into .conf and restarted libvirtd so that my results would be logged to /var/log/libvirt/libvirtd.log.

Attempting to create a 3rd failed due to lack of space:

# virsh vol-create-as bugtest badname 10M
error: Failed to create vol badname
error: internal error: no large enough free extent

#

So taking a chance, I removed mpathb2, then I ran:

# virsh vol-create-as bugtest badname 10M
error: Failed to create vol badname
error: internal error: no large enough free extent

# virsh vol-create-as bugtest badname 10K
error: Failed to create vol badname
error: invalid argument: invalid partition name 'badname', expected 'mpathb2'

# ll /dev/mapper/mpathb*
lrwxrwxrwx. 1 root root 7 Nov 17 03:12 /dev/mapper/mpathb -> ../dm-2
lrwxrwxrwx. 1 root root 7 Nov 17 03:12 /dev/mapper/mpathb1 -> ../dm-8

#

Hmmm... interesting - I'm not getting the same results. Digging into /var/log/libvirt/libvirtd.log shows that the deletion of the bad partition is happening as I'd expect. A snippet from the log file:

14319 2016-11-16 19:11:57.312+0000: 2685: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f8750734bc0
14320 2016-11-16 19:12:02.307+0000: 2704: error : virStorageBackendDiskMakeDataVol:97 : invalid argument: invalid partition name 'badname', expected 'mpathb2'
14321 2016-11-16 19:12:02.307+0000: 2704: debug : virProcessAbort:167 : aborting child process 5894
14322 2016-11-16 19:12:02.308+0000: 2704: debug : virProcessAbort:172 : process has ended: exit status 0
14323 2016-11-16 19:12:02.308+0000: 2704: debug : virStorageBackendDiskDeleteVol:868 : dev_name=mpathb2, srcname=mpathb
14324 2016-11-16 19:12:02.308+0000: 2704: debug : virCommandRunAsync:2429 : About to run /usr/sbin/parted /dev/mapper/mpathb rm --script 2
14325 2016-11-16 19:12:02.309+0000: 2704: debug : virFileClose:102 : Closed fd 24     
14326 2016-11-16 19:12:02.309+0000: 2704: debug : virFileClose:102 : Closed fd 26     
14327 2016-11-16 19:12:02.309+0000: 2704: debug : virFileClose:102 : Closed fd 28     
14328 2016-11-16 19:12:02.309+0000: 2704: debug : virCommandRunAsync:2432 : Command result 0, with PID 6485


You can see the 'invalid partition name' error followed closely by the running of the "parted /dev/mapper/mpathb rm --script 2" which was added by commit id '8cdff0b93' which was added in libvirt 1.3.5 and according to the bug report should include the fix, so I am a bit perplexed why it didn't work as I'd expect.

I copied /etc/libvirt/libvirtd.conf.clean to libvirtd.conf and restart libvirtd. So other than a (much) smaller second partition things are generally the same as I found them.

In any case, on the host now is libvirt 2.0.0 and I cannot reproduce the issue, so I'm inclined to say scenario one is resolved. I can still add some more text to the formatstorage.html.in to make it clearer that 'part_separator' should be used if 'user_friendly_names' is set to 'no'.

If you can reproduce, then I'll be happy to take a look.

Hi John, 
I can still reproduce this issue with a vHBA connected lun.
And I prepared a pool.xml in /root/ in the machine I mentioned
Exactly eproduce steps on that machine as follow:

# virsh nodedev-dumpxml scsi_host19

<device>
  <name>scsi_host19</name>
  <path>/sys/devices/pci0000:00/0000:00:01.0/0000:20:00.0/host1/vport-1:0-8/host19</path>
  <parent>scsi_host1</parent>
  <capability type='scsi_host'>
    <host>19</host>
    <unique_id>10</unique_id>
    <capability type='fc_host'>
      <wwnn>20000000c99e2b80</wwnn>
      <wwpn>1000000000000001</wwpn>
      <fabric_wwn>2001547feebe79c1</fabric_wwn>
    </capability>
  </capability>
</device>


# lsscsi | grep 19:
[19:0:0:0]   disk    IBM      2145             0000  /dev/sdj 
[19:0:0:1]   disk    IBM      2145             0000  /dev/sdk 
[19:0:1:0]   disk    IBM      2145             0000  /dev/sdl 
[19:0:1:1]   disk    IBM      2145             0000  /dev/sdm 




# multipath -ll | egrep "sdj|sdk|sdl|sdm" -a10 
<======== find out mpathg is connected lun of scsi_host19
...
mpathg (360050763008084e6e000000000000065) dm-7 IBM     ,2145            
size=10G features='1 queue_if_no_path' hwhandler='0' wp=rw
|-+- policy='service-time 0' prio=50 status=active
| `- 19:0:0:0 sdj 8:144 active ready running
`-+- policy='service-time 0' prio=10 status=enabled
  `- 19:0:1:0 sdl 8:176 active ready running
...

# cat ~/pool.xml 
<pool type='disk'>
<name>bugtest</name>
<uuid>c9145fe4-09dd-47df-ae4e-35ca9fd06d54</uuid>
<capacity unit='bytes'>0</capacity>
<allocation unit='bytes'>0</allocation>
<available unit='bytes'>0</available>
<source>
  <device path='/dev/mapper/mpathg' part_separator='yes'/>
  <format type='gpt'/>
</source>
<target>
<path>/dev/disk/by-path</path>
</target>
</pool>


# virsh pool-create pool.xml  --build --overwrite
Pool bugtest created from pool.xml


# virsh vol-list bugtest
 Name                 Path                                    
------------------------------------------------------------------------------

# ll /dev/mapper/mpathg*
lrwxrwxrwx. 1 root root 7 Nov 17 10:41 /dev/mapper/mpathg -> ../dm-7


# virsh vol-create-as bugtest badname 100M
error: Failed to create vol badname
error: invalid argument: invalid partition name 'badname', expected 'mpathgp1'

# virsh pool-refresh bugtest; virsh vol-list bugtest --details
error: Failed to refresh pool bugtest
error: Storage volume not found: no storage vol with matching path '/dev/mapper/mpathgp1'

error: failed to get pool 'bugtest'
error: Storage pool not found: no storage pool with matching name 'bugtest'

# virsh pool-list --all
 Name                 State      Autostart 
-------------------------------------------
 default              active     yes       
 images               active     yes       


# ll /dev/mapper/mpathg*
lrwxrwxrwx. 1 root root 7 Nov 17 10:42 /dev/mapper/mpathg -> ../dm-7
lrwxrwxrwx. 1 root root 8 Nov 17 10:41 /dev/mapper/mpathg1 -> ../dm-11


And now, I searched in the libvirtd.log, and there is no keyword as "rm --script 2", pls help to check. thx.

Your libvirtd.log has:

2016-11-17 02:48:02.580+0000: 18340: error : virStorageBackendDiskMakeDataVol:97 : invalid argument: invalid partition name 'badname', expected 'mpathgp1'
   10559 2016-11-17 02:48:02.580+0000: 18340: debug : virProcessAbort:167 : aborting child process 18608
   10560 2016-11-17 02:48:02.581+0000: 18340: debug : virProcessAbort:172 : process has ended: exit status 0
   10561 2016-11-17 02:48:02.582+0000: 18340: error : virStorageBackendDiskDeleteVol:862 : Couldn't read volume target path '/dev/mapper/mpathgp1': No such file or directory
   10562

and the output is 

# ll /dev/mapper/mpathg*
lrwxrwxrwx. 1 root root 7 Nov 17 10:42 /dev/mapper/mpathg -> ../dm-7
lrwxrwxrwx. 1 root root 8 Nov 17 10:41 /dev/mapper/mpathg1 -> ../dm-11

So here again, we're faced with this problem like scenario2 - told one thing (to add the separator in our generated name), but the reality is the separator isn't needed since user_friendly_names is set thus the name we've generated (mpathgp1) isn't correct since devmapper generated something else (mpathg1).

Compare your error to mine where the 'mpathb2' was used... Looking through my scrollback I see what the difference is/was - the 'bugtest' pool for mpathb was configured with "part_separator='no'" - my eyes must've wandered to the bugtest1 and bugtest2 output that I also dumped and saw 'yes' and well, just assumed (<sigh>).

In any case, I now have a better idea of the problem - let's see what I can do to fix it (it probably will be an ugly fix).

BTW: I tried to recreate the scenario since when I logged into that host it seems things had been cleaned up. That didn't go very well... Eventually I found that multipathd was stuck so I restarted it and it seems to have cleared some things up, but mpathg no longer existed - so I didn't want to do any more damage. Hopefully I didn't mess up some other test.

Looks like I neglected to note a patch was posted (in November):

http://www.redhat.com/archives/libvir-list/2016-November/msg00834.html

After a couple of pings, patch reviewed and pushed upstream:
$ git show
commit 0d157b3fed835e20385150af549cfdc107ff4304

    disk: Fixup error handling path for devmapper when part_separator='yes'
    
...    
    If libvirt_parthelper is erroneously told to append the partition
    separator 'p' onto the generated output for a disk pool using device
    mapper that has 'user_friendly_names' set to true, then the error
    recovery path will fail to find volume resulting in the pool being
    in an unusable state.
    
    So, augment the documentation to provide the better hint that the
    part_separator='yes' should be set when user_friendly_names are not
    being used. Additionally, once we're in the error path where the
    returned name doesn't match the expected partition name try to see
    if the reason is because the 'p' was erroneosly added. If so alter
    the about to be removed vol->target.path so that the DiskDeleteVol
    code can find the partition that was created and remove it.

$ git describe 0d157b3fed835e20385150af549cfdc107ff4304
v3.0.0-21-g0d157b3
$

test on libvirt-3.2.0-6.el7.x86_64

scenario 1:
## virsh pool-dumpxml bugtest
<pool type='disk'>
  <name>bugtest</name>
  <uuid>c9145fe4-09dd-47df-ae4e-35ca9fd06d54</uuid>
  <capacity unit='bytes'>21474819584</capacity>
  <allocation unit='bytes'>0</allocation>
  <available unit='bytes'>21474802176</available>
  <source>
    <device path='/dev/mapper/mpathc' part_separator='yes'>
      <freeExtent start='17408' end='21474819584'/>
    </device>
    <format type='gpt'/>
  </source>
  <target>
    <path>/dev/disk/by-path</path>
  </target>
</pool>


## virsh pool-build bugtest --overwrite
Pool bugtest built

## virsh pool-start bugtest
Pool bugtest started


## virsh vol-create-as bugtest badname 100M
error: Failed to create vol badname
error: invalid argument: invalid partition name 'badname', expected 'mpathcp1'


## virsh pool-refresh bugtest; virsh vol-list bugtest --details
Pool bugtest refreshed

 Name  Path  Type  Capacity  Allocation
----------------------------------------
<==== no error happened

## ll /dev/mapper/mpathc*
lrwxrwxrwx. 1 root root 7 May 27 15:29 /dev/mapper/mpathc -> ../dm-2
<==== no new partition created as expected

scenario 2 of comment 0:
Scenario two: libvirt expects vol_name = xxxxp1, parted expect xxxx1, we provide a xxxxp1, so it passes libvirt check, but fails parted check. 

Failed

steps:
## ll /dev/mapper/mpathc*                       
lrwxrwxrwx. 1 root root 7 May 27 15:44 /dev/mapper/mpathc -> ../dm-2
<=== mpathc has no partition

## virsh pool-dumpxml bugtest
<pool type='disk'>
  <name>bugtest</name>
  <uuid>c9145fe4-09dd-47df-ae4e-35ca9fd06d54</uuid>
  <capacity unit='bytes'>0</capacity>
  <allocation unit='bytes'>0</allocation>
  <available unit='bytes'>0</available>
  <source>
    <device path='/dev/mapper/mpathc' ** part_separator='yes'**/>
    <format type='gpt'/>
  </source>
  <target>
    <path>/dev/disk/by-path</path>
  </target>
</pool>
<=== xml has part_separator='yes', so libvirt will expect a mpathcp1 partition. 
but since mpathc is ending with 'c' which is not a digit, so parted will expect a mpathc1 partition.

## virsh pool-build bugtest --overwrite
Pool bugtest built

## virsh pool-start bugtest
Pool bugtest started

## virsh vol-create-as bugtest **mpathcp1** 100M
error: Failed to create vol mpathcp1
error: Storage volume not found: no storage vol with matching path '/dev/mapper/mpathcp1'
<=== error happened

** now, pool cannot be refreshed or started anymore
## virsh pool-refresh bugtest
error: Failed to refresh pool bugtest
error: Storage volume not found: no storage vol with matching path '/dev/mapper/mpathcp1'

## virsh pool-start bugtest
error: Failed to start pool bugtest
error: Storage volume not found: no storage vol with matching path '/dev/mapper/mpathcp1'

## ll /dev/mapper/mpathc*
lrwxrwxrwx. 1 root root 7 May 27 15:47 /dev/mapper/mpathc -> ../dm-2
lrwxrwxrwx. 1 root root 8 May 27 15:46 /dev/mapper/mpathc1 -> ../dm-13
<=== even if vol-create-as step failed, a new partition of mpathc1 still created. 

So failed_qa for now.

TBH - this is at the point I'm not sure whether what's being tested for scenario 2 is even fixable. IIRC there trying to fix both (or multiple) types of conditions caused issues for the other conditions.

To me it seems a refresh and start are doing the right thing - failing because they've been told to expect that the target device isn't using user_friendly_names. The code determines that there is a partition, but the name doesn't have the "expected" mpathcp1, so start/refresh fail.  The "answer" thus becomes to edit the pool definition to remove the "part_separator='yes'".

w/r/t the desire to properly delete if something was misconfigured...

What may help is to turn on logging for scenario 2 and see what libvirtd.log shows the code path to be for :

## virsh vol-create-as bugtest **mpathcp1** 100M
error: Failed to create vol mpathcp1
error: Storage volume not found: no storage vol with matching path '/dev/mapper/mpathcp1'
<=== error happened


Of course the real need is to see what's in a few fields in that code added to virStorageBackendDiskMakeDataVol which tries to remove the incorrectly named partition. IOW: What was miscoded in the code that tried to "hack" around the incorrectly named "target.path" compared to the "groups[0]" returned. There's perhaps something wrong in there, but I'm hesitant to even think about fixing it. It's too much of an edge condition.  I have to ask myself would customers fall into this trap of knowing they've set up their environment to use "user_friendly_names" *and* attempt to create/use a pool that would go against what they've set up for devmapper.

(In reply to John Ferlan from comment #11)
> TBH - this is at the point I'm not sure whether what's being tested for
> scenario 2 is even fixable. IIRC there trying to fix both (or multiple)
> types of conditions caused issues for the other conditions.
> 
> To me it seems a refresh and start are doing the right thing - failing
> because they've been told to expect that the target device isn't using
> user_friendly_names. The code determines that there is a partition, but the
> name doesn't have the "expected" mpathcp1, so start/refresh fail.  The
> "answer" thus becomes to edit the pool definition to remove the
> "part_separator='yes'".
> 
> w/r/t the desire to properly delete if something was misconfigured...
> 
> What may help is to turn on logging for scenario 2 and see what libvirtd.log
> shows the code path to be for :
> 
> ## virsh vol-create-as bugtest **mpathcp1** 100M
> error: Failed to create vol mpathcp1
> error: Storage volume not found: no storage vol with matching path
> '/dev/mapper/mpathcp1'
> <=== error happened
> 
> 
> Of course the real need is to see what's in a few fields in that code added
> to virStorageBackendDiskMakeDataVol which tries to remove the incorrectly
> named partition. IOW: What was miscoded in the code that tried to "hack"
> around the incorrectly named "target.path" compared to the "groups[0]"
> returned. There's perhaps something wrong in there, but I'm hesitant to even
> think about fixing it. It's too much of an edge condition.  I have to ask
> myself would customers fall into this trap of knowing they've set up their
> environment to use "user_friendly_names" *and* attempt to create/use a pool
> that would go against what they've set up for devmapper.
I have some problems when add a bugzilla attachment, so paste the log at:
http://pastebin.test.redhat.com/489252

it was 400 lines around "2017-05-31 01:16:11.872+0000: 32594: debug : virCommandRunAsync:2448 : About to run /usr/sbin/parted /dev/mapper/mpathc mkpart --script primary 17408B 104875007B", pls have a check.

Strange that text doesn't appear in the buffer you posted.  Again, I'll point out that unfortunately I don't think there's enough debugging in the code now in order to capture exactly what I want...

If you look at src/storage/storage_backend_disk.c

virStorageBackendDiskMakeDataVol()

start here:


    /* Enforce provided vol->name is the same as what parted created.
     * We do this after filling target.path so that we have a chance at
     * deleting the partition with this failure from CreateVol path
     */
    if (STRNEQ(vol->name, partname)) {
        virReportError(VIR_ERR_INVALID_ARG,
                       _("invalid partition name '%s', expected '%s'"),
                       vol->name, partname);


That next hunk is what "adjustment" I came up with that doesn't appear to do the right thing. But what I don't have in any output is what groups[0] and vol->target.path.  I don't even see that error message in the pastebin link, so I'm confused.

Still I really begin to wonder if it's worth the effort.  I'm under the assumption if you remove that "part_separator='yes'" from the pool, then things work.  It's this odd combination causing problems which some would consider a misconfiguration.

(In reply to John Ferlan from comment #13)
> Strange that text doesn't appear in the buffer you posted.  Again, I'll
> point out that unfortunately I don't think there's enough debugging in the
> code now in order to capture exactly what I want...
> 
> If you look at src/storage/storage_backend_disk.c
> 
> virStorageBackendDiskMakeDataVol()
> 
> start here:
> 
> 
>     /* Enforce provided vol->name is the same as what parted created.
>      * We do this after filling target.path so that we have a chance at
>      * deleting the partition with this failure from CreateVol path
>      */
>     if (STRNEQ(vol->name, partname)) {
>         virReportError(VIR_ERR_INVALID_ARG,
>                        _("invalid partition name '%s', expected '%s'"),
>                        vol->name, partname);
> 
> 
> That next hunk is what "adjustment" I came up with that doesn't appear to do
> the right thing. But what I don't have in any output is what groups[0] and
> vol->target.path.  I don't even see that error message in the pastebin link,
> so I'm confused.
> 
> Still I really begin to wonder if it's worth the effort.  I'm under the
> assumption if you remove that "part_separator='yes'" from the pool, then
> things work.  It's this odd combination causing problems which some would
> consider a misconfiguration.

Yes, pool-edit and change <device ...> to part_separator='no' will make the pool can be started. I am ok to set this bug to verified and consider it as a misconfiguration. 

So, VERIFIED as comment 9's steps, and comment 10 could be considered as misconfiguration.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

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

https://access.redhat.com/errata/RHEA-2017:1846

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

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

https://access.redhat.com/errata/RHEA-2017:1846