Bug 886694

This is reproducible.

============================================================
Iteration 1 of 10 started at Wed Dec 12 18:18:17 CST 2012
============================================================
SCENARIO - [poolmetadatasizes]
Create pool volumes of varying pool metadata sizes (--poolmetadatasize)

Creating [4.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_4.00m --poolmetadatasize 4.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_4.00m -n origin_4.00m
lvcreate -s /dev/snapper_thinp/origin_4.00m -n snap_4.00m

Creating [16.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_16.00m --poolmetadatasize 16.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_16.00m -n origin_16.00m
lvcreate -s /dev/snapper_thinp/origin_16.00m -n snap_16.00m

Creating [32.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_32.00m --poolmetadatasize 32.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_32.00m -n origin_32.00m
lvcreate -s /dev/snapper_thinp/origin_32.00m -n snap_32.00m

Creating [64.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_64.00m --poolmetadatasize 64.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_64.00m -n origin_64.00m
lvcreate -s /dev/snapper_thinp/origin_64.00m -n snap_64.00m

Creating [128.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_128.00m --poolmetadatasize 128.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_128.00m -n origin_128.00m
lvcreate -s /dev/snapper_thinp/origin_128.00m -n snap_128.00m

Creating [256.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_256.00m --poolmetadatasize 256.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_256.00m -n origin_256.00m
lvcreate -s /dev/snapper_thinp/origin_256.00m -n snap_256.00m

Creating [512.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
lvcreate --thinpool POOL_512.00m --poolmetadatasize 512.00m -L 500M snapper_thinp
lvcreate --virtualsize 500M --thinpool snapper_thinp/POOL_512.00m -n origin_512.00m
lvcreate -s /dev/snapper_thinp/origin_512.00m -n snap_512.00m

Removing [4.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot
Removing volume snapper_thinp/snap_4.00m
Do you really want to remove active logical volume origin_4.00m? [y/n]: ^C




Dec 12 18:18:41 taft-01 qarshd[6387]: Running cmdline: lvremove /dev/snapper_thinp/origin_4.00m
device-mapper: thin: Data device (dm-4) discard unsupported: Disabling discard passdown.
Dec 12 18:18:41 taft-01 kernel: device-mapper: thin: Data device (dm-4) discard unsupported: Disabling discard passdown.
Dec 12 18:18:41 taft-01 lvm[3452]: Monitoring thin snapper_thinp-POOL_4.00m-tpool.
device-mapper: thin: Data device (dm-9) discard unsupported: Disabling discard passdown.
Dec 12 18:18:41 taft-01 kernel: device-mapper: thin: Data device (dm-9) discard unsupported: Disabling discard passdown.
Dec 12 18:18:41 taft-01 lvm[3452]: Monitoring thin snapper_thinp-POOL_16.00m-tpool.
device-mapper: thin: Data device (dm-15) discard unsupported: Disabling discard passdown.
Dec 12 18:18:41 taft-01 kernel: device-mapper: thin: Data device (dm-15) discard unsupported: Disabling discard passdown.
Dec 12 18:18:41 taft-01 lvm[3452]: Monitoring thin snapper_thinp-POOL_32.00m-tpool.
device-mapper: thin: Data device (dm-21) discard unsupported: Disabling discard passdown.
Dec 12 18:18:42 taft-01 kernel: device-mapper: thin: Data device (dm-21) discard unsupported: Disabling discard passdown.
Dec 12 18:18:42 taft-01 lvm[3452]: Monitoring thin snapper_thinp-POOL_64.00m-tpool.
device-mapper: thin: Data device (dm-27) discard unsupported: Disabling discard passdown.
Dec 12 18:18:42 taft-01 kernel: device-mapper: tdevice-mapper: table: 253:29: linear: dm-linear: Device lookup failed
hin: Data devicedevice-mapper: ioctl: error adding target to table
 (dm-27) discard unsupported: Disabling discard passdown.
Dec 12 18:18:42 taft-01 kernel: device-mapper: table: 253:29: linear: dm-linear: Device lookup failed
Dec 12 18:18:42 taft-01 kernel: device-mapper: ioctl: error adding target to table
device-mapper: thin: Data device (dm-27) discard unsupported: Disabling discard passdown.
Dec 12 18:18:42 device-mapper: table: 253:30: thin: Error opening pool device
taft-01 kernel: device-mapper: ioctl: error adding target to table
device-mapper: thin: Data device (dm-27) discard unsupported: Disabling discard passdown.
Dec 12 18:18:42 taft-01 kernel: device-mapper: table: 253:30: thin: Error opening pool device

> lvcreate -s /dev/snapper_thinp/origin_512.00m -n snap_512.00m
> 
> Removing [4.00m] MDA thinpool and corresponding thin virtual volume and thin
> snapshot
> Removing volume snapper_thinp/snap_4.00m
>   device-mapper: message ioctl on  failed: Device or resource busy
>   Unable to deactivate open snapper_thinp-POOL_4.00m_tdata (253:4)
>   Unable to deactivate open snapper_thinp-POOL_4.00m_tmeta (253:3)
>   Failed to deactivate snapper_thinp-POOL_4.00m-tpool
>   Failed to resume POOL_4.00m.
>   Failed to update thin pool POOL_4.00m.
> couldn't remove thin origin volume
> 
> 
> 
> Dec 12 14:56:30 hayes-01 qarshd[3277]: Running cmdline: lvremove
> /dev/snapper_thinp/origin_4.00m
> Dec 12 14:56:33 hayes-01 kernel: device-mapper: thin: Data device (dm-4)
> discard unsupported: Disabling discard passdown.
> Dec 12 14:56:33 hayes-01 lvm[2654]: Monitoring thin


Hmm I'm being a bit confused on the order of commands here,
since I'm not able to get close to your machine's behavior.

How did the remove of  snapper_thinp/snap_4.00m  triggered deactivation
of  snapper_thinp-POOL_4.00m_tdata ??

There is some 'chance'  your  snap_4.00m is being kept open by another process
(possibly overloaded udev) for a very very long time (>10s) - thus avoiding even retry operation for removal of LV.

But it still should not follow with any further operation.


We need to see 

dmsetup table
dmsetup ls --tree -o ascii
dmsetup status

before failing command
and possibly right after failure.

> Dec 12 14:56:33 hayes-01 udevd-work[3284]: setfilecon /dev/dm-13 failed: No
> such file or directory

Interesting - why udevd runs something over removed device ???


> Dec 12 14:56:34 hayes-01 kernel: device-mapper: table: 253:17: thin: Error
> opening pool device

Scary

Why we would active thin pool with missing device?
Something weird must be going on here.

Is this with lvmetad  or without?

It's with lvmetad, see the subject. Check out bug 886695 for more information on test cases that failed during removal. I think these two bugs are related.

(In reply to comment #3)

Corey, I am pretty sure this one was caused by Bug 889454 - looking at the test case, VG is deactivated, LV *snap* is removed, triggering udev action reactivating other LVs in the VG causing lvremove *origin* to fail:

> Removing [4.00m] MDA thinpool and corresponding thin virtual volume and thin snapshot

Here snap_4.00m is successfully removed:

> Removing volume snapper_thinp/snap_4.00m

And here removing origin_4.00m fails as it's active:

> Do you really want to remove active logical volume origin_4.00m? [y/n]: ^C


As for the original problem:

I have run lvm_single_thin_snapper (with lvmetad and with 889454 fixed) few dozen times and have not seen the issue - so either it's gone or the reproducibility is fairly low.

Corey, the latest build lvm2-2.02.98-7.el6 (which also resolves bug #889454) has the fix for autoactivation that intefered in this case too. Please, try it if you this is still reproducible. If not, we can close it as a dup of bug #889454.

This test case is no longer causing any issues with the latest rpms.

2.6.32-353.el6.x86_64

lvm2-2.02.98-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
lvm2-libs-2.02.98-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
lvm2-cluster-2.02.98-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
udev-147-2.43.el6    BUILT: Thu Oct 11 05:59:38 CDT 2012
device-mapper-1.02.77-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
device-mapper-libs-1.02.77-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
device-mapper-event-1.02.77-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
device-mapper-event-libs-1.02.77-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013
cmirror-2.02.98-7.el6    BUILT: Wed Jan  9 03:34:27 CST 2013

Just a note: the only change in latest rpms (not taking into account one lvm1 vs. lvmetad fix) are the fixes for autoactivation to not fire when it should not and addition of proper udev synchronization with "pvscan --cache -aay" that is called from within udev rules to autoactivate volumes.

Closing this bug as it can't be reproduced anymore with latest rpms which
include fixes for autoactivation (bug #889454).

If still seen, please, reopen this bug report.

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