[PATCH] libdm-iface: not output error message inside retry loops

[PATCH] libdm-iface: not output error message inside retry loops

[Liuhua Wang]

    To avoid noisy error message being output inside retry loops
    in case of remove failure because device busy.
---
 libdm/ioctl/libdm-iface.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/libdm/ioctl/libdm-iface.c b/libdm/ioctl/libdm-iface.c
index 73af12b..287e917 100644
--- a/libdm/ioctl/libdm-iface.c
+++ b/libdm/ioctl/libdm-iface.c
@@ -63,6 +63,8 @@
 #define MAPPER_CTRL_MINOR 236
 #define MISC_MAJOR 10
 
+#define DM_IOCTL_RETRIES 25
+
 /* dm major version no for running kernel */
 static unsigned _dm_version = DM_VERSION_MAJOR;
 static unsigned _dm_version_minor = 0;
@@ -1848,7 +1850,7 @@ static struct dm_ioctl *_do_dm_ioctl(struct dm_task *dmt, unsigned command,
 					    dmt->major > 0 && dmt->minor == 0 ? "0" : "",
 					    dmt->major > 0 ? ")" : "",
 					    strerror(dmt->ioctl_errno));
-			else
+			else if(dmt->ioctl_errno != EBUSY || retry_repeat_count == DM_IOCTL_RETRIES)
 				log_error("device-mapper: %s ioctl on %s%s%s%.0d%s%.0d%s%s "
 					  "failed: %s",
 					  _cmd_data_v4[dmt->type].name,
@@ -1901,7 +1903,6 @@ void dm_task_update_nodes(void)
 	update_devs();
 }
 
-#define DM_IOCTL_RETRIES 25
 #define DM_RETRY_USLEEP_DELAY 200000
 
 int dm_task_get_errno(struct dm_task *dmt)
-- 
1.8.4.5

[PATCH] libdm-iface: not output error message inside retry loops

[Zdenek Kabelac]

Dne 27.8.2015 v 10:30 Liuhua Wang napsal(a):
>      To avoid noisy error message being output inside retry loops
>      in case of remove failure because device busy.
> ---

Hi

It's in fact made 'noisy' intentionally - we normally should detect whether 
retry makes sense - so  what are the conditions when you experience this problem ?

Common scenario:

The major reason for retry is 'unpredictable'  udev event processing
i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed - 
retry fixes this problem.


Regards

Zdenek

[PATCH] libdm-iface: not output error message inside retry loops

[Liuhua Wang]

Hi Zdenek,

Thanks for your reply.

> It's in fact made 'noisy' intentionally - we normally should detect whether 
> retry makes sense - so  what are the conditions when you experience this 
> problem ?
> 
> Common scenario:
> 
> The major reason for retry is 'unpredictable'  udev event processing
> i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed - 
> retry fixes this problem.

 We first found this problem when we were testing lvcreate-usage.sh included in
 lvm2-2.02.120 package. The case always failed due to the following message:
  device-mapper: remove ioctl on (253:6) failed: Device or resource busy
 [ 0:01]   Node @TESTDIR@/dev/mapper/@PREFIX at vg-LV2-cow was not removed by udev. Falling back to direct node removal.

Then we tested more cases and found the problem occurs in the following cases:
   - lvremove/lvcreate a snap lv
   - lvremove/lvcreate a thin lv
   - lvremove/lvcreate a mirror lv
 
o Reproduce frequency:
   lvremove about 80%, lvcreate occurs occasionally 
  
With the patch I attached, the lvcreate-usage.sh will not fail due to the error message.

Regards,
Liuhua

[PATCH] libdm-iface: not output error message inside retry loops

[Zdenek Kabelac]

Dne 28.8.2015 v 04:58 Liuhua Wang napsal(a):
> Hi Zdenek,
>
> Thanks for your reply.
>
>> It's in fact made 'noisy' intentionally - we normally should detect whether
>> retry makes sense - so  what are the conditions when you experience this
>> problem ?
>>
>> Common scenario:
>>
>> The major reason for retry is 'unpredictable'  udev event processing
>> i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed -
>> retry fixes this problem.
>
>   We first found this problem when we were testing lvcreate-usage.sh included in
>   lvm2-2.02.120 package. The case always failed due to the following message:
>    device-mapper: remove ioctl on (253:6) failed: Device or resource busy
>   [ 0:01]   Node @TESTDIR@/dev/mapper/@PREFIX at vg-LV2-cow was not removed by udev. Falling back to direct node removal.

Looks like udev issue.


>
> Then we tested more cases and found the problem occurs in the following cases:
>     - lvremove/lvcreate a snap lv
>     - lvremove/lvcreate a thin lv
>     - lvremove/lvcreate a mirror lv
>
> o Reproduce frequency:
>     lvremove about 80%, lvcreate occurs occasionally
>
> With the patch I attached, the lvcreate-usage.sh will not fail due to the error message.

What is your system - is it Debian/Ubuntu?

These tests depend on properly working udev rules.


Zdenek

[PATCH] libdm-iface: not output error message inside retry loops

[Liuhua Wang]

Thanks for your reply.

>> Common scenario:
>>
>> The major reason for retry is 'unpredictable'  udev event processing
>> i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed -
>> retry fixes this problem.
>
>>   We first found this problem when we were testing lvcreate-usage.sh included in
>>   lvm2-2.02.120 package. The case always failed due to the following message:
>>    device-mapper: remove ioctl on (253:6) failed: Device or resource busy
>>   [ 0:01]   Node @TESTDIR@/dev/mapper/@PREFIX at vg-LV2-cow was not removed by udev. Falling >>back to direct node removal.

>Looks like udev issue.
You mean udev cookie related problem? Because I see udev cookie add and remove 
a little weird.

>
> >Then we tested more cases and found the problem occurs in the following cases:
>     >- lvremove/lvcreate a snap lv
>     >- lvremove/lvcreate a thin lv
>     >- lvremove/lvcreate a mirror lv
>
>> o Reproduce frequency:
>>     lvremove about 80%, lvcreate occurs occasionally
>
> >With the patch I attached, the lvcreate-usage.sh will not fail due to the error message.

>What is your system - is it Debian/Ubuntu?

>These tests depend on properly working udev rules.

We are using SuSE SLES12.
#udev version
 210

Regards,
Liuhua

[PATCH] libdm-iface: not output error message inside retry loops

[Zdenek Kabelac]

Dne 28.8.2015 v 13:24 Liuhua Wang napsal(a):
>
> Thanks for your reply.
>
>>> Common scenario:
>>>
>>> The major reason for retry is 'unpredictable'  udev event processing
>>> i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed -
>>> retry fixes this problem.
>>
>>>    We first found this problem when we were testing lvcreate-usage.sh included in
>>>    lvm2-2.02.120 package. The case always failed due to the following message:
>>>     device-mapper: remove ioctl on (253:6) failed: Device or resource busy
>>>    [ 0:01]   Node @TESTDIR@/dev/mapper/@PREFIX at vg-LV2-cow was not removed by udev. Falling >>back to direct node removal.
>
>> Looks like udev issue.
> You mean udev cookie related problem? Because I see udev cookie add and remove
> a little weird.
>

So the question #1 -  are you using upstream lvm2 udev rules ?
(matching with install package)

Are there any modification made to upsteam lvm2 udev rules?
(Debian is usually having problems with those)

The rules are quite complex and any 'touch 'to them should be consulted with 
upstream authors.

Could you create / remove snapshots without any problems.

I guess you should probably post failing logs for better diagnostic.

Zdenek

[PATCH] libdm-iface: not output error message inside retry loops

[Liuhua Wang]

Hi Zdenek,

>>> On 8/28/2015 at 07:52 PM, in message <55E04B67.3060003@redhat.com>, Zdenek
Kabelac <zkabelac@redhat.com> wrote: 
> Dne 28.8.2015 v 13:24 Liuhua Wang napsal(a):
> >
> > Thanks for your reply.
> >
> >>> Common scenario:
> >>>
> >>> The major reason for retry is 'unpredictable'  udev event processing
> >>> i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed -
> >>> retry fixes this problem.
> >>
> >>>    We first found this problem when we were testing lvcreate-usage.sh 
> included in
> >>>    lvm2-2.02.120 package. The case always failed due to the following 
> message:
> >>>     device-mapper: remove ioctl on (253:6) failed: Device or resource busy
> >>>    [ 0:01]   Node @TESTDIR@/dev/mapper/@PREFIX at vg-LV2-cow was not removed by 
> udev. Falling >>back to direct node removal.
> >
> >> Looks like udev issue.
> > You mean udev cookie related problem? Because I see udev cookie add and 
> remove
> > a little weird.
> >
> 
> So the question #1 -  are you using upstream lvm2 udev rules ?
> (matching with install package)
> 
> Are there any modification made to upsteam lvm2 udev rules?
> (Debian is usually having problems with those)
> 
> The rules are quite complex and any 'touch 'to them should be consulted with 
> 
> upstream authors.
Yes, udev rules have been modified a little, but even I replace them all with
upstream rules and reloaded, still has the issue.
 
> Could you create / remove snapshots without any problems.
> 
> I guess you should probably post failing logs for better diagnostic.

I attached my test log.

# lvcreate -s -L20M -nsnap vg/lv
  Logical volume "snap" created.

# lsblk 
NAME          MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
[...]
loop1           7:1    0   50M  0 loop 
??vg-lv-real  253:1    0   32M  0 lvm  
  ??vg-lv     253:0    0   32M  0 lvm  
  ??vg-snap   253:3    0   32M  0 lvm  
loop2           7:2    0   50M  0 loop 
??vg-snap-cow 253:2    0   20M  0 lvm  
  ??vg-snap   253:3    0   32M  0 lvm  

 # lvremove -ff vg/snap -vvvvv >lvremove-snap-failed.log 2>&1

Please see the detailed log attatched.
Thank you very much.

Regards,
Liuhua
-------------- next part --------------
A non-text attachment was scrubbed...
Name: lvremove-snap-failed.log
Type: application/octet-stream
Size: 61887 bytes
Desc: not available
URL: <http://listman.redhat.com/archives/lvm-devel/attachments/20150831/0af6c74f/attachment.obj>

[PATCH] libdm-iface: not output error message inside retry loops

[Zdenek Kabelac]

Dne 31.8.2015 v 10:39 Liuhua Wang napsal(a):
> Hi Zdenek,
>
>>>> On 8/28/2015 at 07:52 PM, in message <55E04B67.3060003@redhat.com>, Zdenek
> Kabelac <zkabelac@redhat.com> wrote:
>> Dne 28.8.2015 v 13:24 Liuhua Wang napsal(a):
>>>
>>> Thanks for your reply.
>>>
>>>>> Common scenario:
>>>>>
>>>>> The major reason for retry is 'unpredictable'  udev event processing
>>>>> i.e. you run  'umount' -> fires watch-rule -> lvremove  could have failed -
>>>>> retry fixes this problem.
>>>>
>>>>>     We first found this problem when we were testing lvcreate-usage.sh
>> included in
>>>>>     lvm2-2.02.120 package. The case always failed due to the following
>> message:
>>>>>      device-mapper: remove ioctl on (253:6) failed: Device or resource busy
>>>>>     [ 0:01]   Node @TESTDIR@/dev/mapper/@PREFIX at vg-LV2-cow was not removed by
>> udev. Falling >>back to direct node removal.
>>>
>>>> Looks like udev issue.
>>> You mean udev cookie related problem? Because I see udev cookie add and
>> remove
>>> a little weird.
>>>
>>
>> So the question #1 -  are you using upstream lvm2 udev rules ?
>> (matching with install package)
>>
>> Are there any modification made to upsteam lvm2 udev rules?
>> (Debian is usually having problems with those)
>>
>> The rules are quite complex and any 'touch 'to them should be consulted with
>>
>> upstream authors.
> Yes, udev rules have been modified a little, but even I replace them all with
> upstream rules and reloaded, still has the issue.

I'm afraid full audit of your udev rules is necessary then.

Upstream is developed on Fedora - so rules are checked there.

If your system has different rules - then more careful check is needed.
(and it's btw reason why we show those errors)

>
>   # lvremove -ff vg/snap -vvvvv >lvremove-snap-failed.log 2>&1
>

vg-snap-cow  is resumed with:

DISABLE_SUBSYSTEM_RULES DISABLE_DISK_RULES DISABLE_OTHER_RULES 
DISABLE_LIBRARY_FALLBACK

these rule flag's normally ensure  udev will not even try to look on these 
volumes - however you get:

device-mapper: remove ioctl on (253:2) failed: Device or resource busy


So clearly something holds this open.

To trace out this case - you need to run 'udevd' in 'debug/verbose' mode
and capture which rule is accessing DM device  (since normally upstream udev
actually skips anything  'dm' related and only we provide rules accessing dm 
devices)

Udev tracing however slows down processing of udev rules so it might be 
trickier to capture error - but anyway - you should find out which rule
cause read of -cow volume - such volume should never be scanned by udev.

As a side note - I do plan to rewrite snapshot deactivation code - but it will 
take a while - this could would eliminate resume of -cow completely.

Regards

Zdenek