Bug 1353993

Summary: When insufficient free space cache pool creation is aborted, left-over devices appear
Product: Red Hat Enterprise Linux 7 Reporter: Corey Marthaler <cmarthal>
Component: lvm2Assignee: Zdenek Kabelac <zkabelac>
lvm2 sub component: Cache Logical Volumes QA Contact: cluster-qe <cluster-qe>
Status: CLOSED DUPLICATE Docs Contact:
Severity: medium    
Priority: unspecified CC: agk, heinzm, jbrassow, msnitzer, prajnoha, zkabelac
Version: 7.3   
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-11-05 16:24:38 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Corey Marthaler 2016-07-08 16:07:48 UTC 
Description of problem:
This appears to be another version of bugs 1161347 and 1167431. This is also a regression from .156.

[root@host-084 ~]# pvcreate --setphysicalvolumesize 100M /dev/sdb1 /dev/sdc1 /dev/sdd1 /dev/sdh1
  Physical volume "/dev/sdb1" successfully created.
  Physical volume "/dev/sdc1" successfully created.
  Physical volume "/dev/sdd1" successfully created.
  Physical volume "/dev/sdh1" successfully created.

[root@host-084 ~]# vgcreate cache_sanity /dev/sdb1 /dev/sdc1 /dev/sdd1 /dev/sdh1
  Volume group "cache_sanity" successfully created

[root@host-084 ~]# lvcreate -vvvv  -L 2G --type cache-pool cache_sanity/over_size_pool > /tmp/lvcreate 2>&1 
[...]

#activate/fs.c:489         Syncing device names
#libdm-common.c:2273         Udev cookie 0xd4d0ae1 (semid 16416769) decremented to 1
#libdm-common.c:2559         Udev cookie 0xd4d0ae1 (semid 16416769) waiting for zero
#libdm-common.c:2288         Udev cookie 0xd4d0ae1 (semid 16416769) destroyed
#libdm-common.c:1427         cache_sanity-lvol0: Skipping NODE_ADD (253,2) 0:6 0660 [trust_udev]
#libdm-common.c:1437         cache_sanity-lvol0: Processing NODE_READ_AHEAD 8192 (flags=1)
#libdm-common.c:1191         cache_sanity-lvol0 (253:2): read ahead is 256
#libdm-common.c:1241         cache_sanity-lvol0 (253:2): Setting read ahead to 8192
#activate/dev_manager.c:755         Getting device info for cache_sanity-lvol0 [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6 [ noopencount flush ]   [16384] (*1)
#activate/activate.c:1487       cache_sanity/lvol0 is active locally
#device/dev-cache.c:356         /dev/cache_sanity/lvol0: Added to device cache (253:2)
#device/dev-cache.c:1402         Using /dev/cache_sanity/lvol0
#device/dev-io.c:570         Opened /dev/cache_sanity/lvol0 RW O_DIRECT
#metadata/lv_manip.c:6843     Initializing 4.00 KiB of logical volume "cache_sanity/lvol0" with value 0.
#device/dev-io.c:808         Wiping /dev/cache_sanity/lvol0 at sector 0 length 8 sectors
#device/dev-io.c:145         /dev/cache_sanity/lvol0: block size is 4096 bytes
#device/dev-io.c:156         /dev/cache_sanity/lvol0: physical block size is 512 bytes
#device/dev-io.c:625         Closed /dev/cache_sanity/lvol0
#metadata/lv_manip.c:7761     Temporary logical volume "lvol0" created.
#locking/file_locking.c:99       Locking LV 6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6 (NL)
#activate/activate.c:2216         Deactivating cache_sanity/lvol0.
#activate/dev_manager.c:755         Getting device info for cache_sanity-lvol0 [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6 [ noopencount flush ]   [16384] (*1)
#activate/dev_manager.c:755         Getting device info for cache_sanity-lvol0 [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6 [ opencount flush ]   [16384] (*1)
#mm/memlock.c:582         Entering critical section (deactivating).
#mm/memlock.c:551         Lock:   Memlock counters: locked:0 critical:1 daemon:0 suspended:0
#mm/memlock.c:475       Locking memory
#libdm-config.c:1036       Setting activation/use_mlockall to 0
#mm/memlock.c:259         mlock default filter 'locale/locale-archive' matches '7fa873c6d000-7fa87a194000 r--p 00000000 fd:00 17365023                   /usr/lib/locale/locale-archive': Skipping.
#mm/memlock.c:259         mlock default filter '/libpcre.so.' matches '7fa87a194000-7fa87a1f4000 r-xp 00000000 fd:00 16928966                   /usr/lib64/libpcre.so.1.2.0': Skipping.
#mm/memlock.c:241         mlock area unreadable 7fa87a1f4000-7fa87a3f3000 ---p 00060000 fd:00 16928966                   /usr/lib64/libpcre.so.1.2.0 : Skipping.
#mm/memlock.c:259         mlock default filter '/libpcre.so.' matches '7fa87a3f3000-7fa87a3f4000 r--p 0005f000 fd:00 16928966                   /usr/lib64/libpcre.so.1.2.0': Skipping.
#mm/memlock.c:259         mlock default filter '/libpcre.so.' matches '7fa87a3f4000-7fa87a3f5000 rw-p 00060000 fd:00 16928966                   /usr/lib64/libpcre.so.1.2.0': Skipping.
#mm/memlock.c:259         mlock default filter '/libz.so.' matches '7fa87a3f5000-7fa87a40a000 r-xp 00000000 fd:00 16928980                   /usr/lib64/libz.so.1.2.7': Skipping.
#mm/memlock.c:241         mlock area unreadable 7fa87a40a000-7fa87a609000 ---p 00015000 fd:00 16928980                   /usr/lib64/libz.so.1.2.7 : Skipping.

[...]

#mm/memlock.c:287         mlock        132KiB 7ffccc74c000 - 7ffccc76d000 rw-p 00000000 00:00 0                          [stack]
#mm/memlock.c:249         mlock ignore filter '[vdso]' matches '7ffccc7fc000-7ffccc7fe000 r-xp 00000000 00:00 0                          [vdso]': Skipping.
#mm/memlock.c:249         mlock ignore filter '[vsyscall]' matches 'ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]': Skipping.
#mm/memlock.c:373         Locked 13168640 bytes
#activate/dev_manager.c:3106         Creating DEACTIVATE tree for cache_sanity/lvol0.
#activate/dev_manager.c:1758         Getting device info for cache_sanity-lvol0 [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6 [ opencount flush ]   [16384] (*1)
#ioctl/libdm-iface.c:1838         dm deps   (253:2) [ opencount flush ]   [16384] (*1)
#activate/dev_manager.c:1758         Getting device info for cache_sanity-lvol0-real [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6-real]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6-real [ opencount flush ]   [16384] (*1)
#activate/dev_manager.c:1758         Getting device info for cache_sanity-lvol0-cow [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6-cow]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6-cow [ opencount flush ]   [16384] (*1)
#ioctl/libdm-iface.c:1838         dm info   (253:2) [ opencount flush ]   [16384] (*1)
#libdm-deptree.c:1026     Removing cache_sanity-lvol0 (253:2)
#libdm-common.c:2346         Udev cookie 0xd4dab0a (semid 16449537) created
#libdm-common.c:2366         Udev cookie 0xd4dab0a (semid 16449537) incremented to 1
#libdm-common.c:2238         Udev cookie 0xd4dab0a (semid 16449537) incremented to 2
#libdm-common.c:2488         Udev cookie 0xd4dab0a (semid 16449537) assigned to REMOVE task(2) with flags DISABLE_LIBRARY_FALLBACK         (0x20)
#ioctl/libdm-iface.c:1838         dm remove   (253:2) [ noopencount flush retryremove ]   [16384] (*1)
#libdm-common.c:1430         cache_sanity-lvol0: Stacking NODE_DEL [trust_udev]
#mm/memlock.c:592         Leaving critical section (deactivated).
#activate/dev_manager.c:755         Getting device info for cache_sanity-lvol0 [LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6]
#ioctl/libdm-iface.c:1838         dm info  LVM-6HRBVPk14m9ZeL0Nb3pcHONIcuxjCPKJmDXBbzJeSjbA9GAnkt6yf23dfiL8lGp6 [ noopencount flush ]   [16384] (*1)
#metadata/pool_manip.c:832     Renaming lvol0 as pool metadata spare volume lvol0_pmspare.
#metadata/lv_manip.c:5700         LV lvol0_pmspare in VG cache_sanity is now hidden.
#lvcreate.c:1516     Making pool over_size_pool in VG cache_sanity using segtype cache-pool
#metadata/lv_manip.c:7350   Volume group "cache_sanity" has insufficient free space (94 extents): 512 required.
#metadata/lv_manip.c:7758         <backtrace>
#lvcreate.c:1537         <backtrace>
#toollib.c:1965         <backtrace>
#cache/lvmetad.c:1224         Sending lvmetad updated VG cache_sanity (seqno 2)
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#cache/lvmetad.c:1651         Telling lvmetad to store PV /dev/sdb1 (D4QPgk-xLXQ-4rbS-bzbk-iolu-QD4y-sCXd6E)
#libdm-config.c:941       Setting response to OK


[root@host-084 ~]# lvs -a -o +devices
  LV              VG            Attr       LSize   Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert Devices       
  [lvol0_pmspare] cache_sanity  ewi-------   8.00m                                                     /dev/sdb1(0)  


[root@host-084 ~]# vgremove -f cache_sanity > /tmp/vgremove 2>&1

[...]

#metadata/vg.c:74         Allocated VG cache_sanity at 0x7f6818374b10.
#format_text/import_vsn1.c:572         Importing logical volume cache_sanity/lvol0_pmspare.
#format_text/import_vsn1.c:690         Logical volume cache_sanity/lvol0_pmspare is pool metadata spare.
#toollib.c:1960       Process single VG cache_sanity
#misc/lvm-flock.c:200       Locking /run/lock/lvm/P_orphans WB
#libdm-common.c:926         Preparing SELinux context for /run/lock/lvm/P_orphans to system_u:object_r:lvm_lock_t:s0.
#misc/lvm-flock.c:101         _do_flock /run/lock/lvm/P_orphans:aux WB
#misc/lvm-flock.c:101         _do_flock /run/lock/lvm/P_orphans WB
#misc/lvm-flock.c:48         _undo_flock /run/lock/lvm/P_orphans:aux
#libdm-common.c:929         Resetting SELinux context to default value.
#cache/lvmcache.c:522         lvmcache has no info for vgname "#orphans".
#cache/lvmetad.c:1288         Sending lvmetad pending remove VG cache_sanity
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#device/dev-io.c:625         Closed /dev/sdb1
#device/dev-io.c:570         Opened /dev/sdb1 RW O_DIRECT
#device/dev-io.c:145         /dev/sdb1: block size is 4096 bytes
#device/dev-io.c:156         /dev/sdb1: physical block size is 512 bytes
#device/dev-io.c:625         Closed /dev/sdc1
#device/dev-io.c:570         Opened /dev/sdc1 RW O_DIRECT
#device/dev-io.c:145         /dev/sdc1: block size is 4096 bytes
#device/dev-io.c:156         /dev/sdc1: physical block size is 512 bytes
#device/dev-io.c:625         Closed /dev/sdd1
#device/dev-io.c:570         Opened /dev/sdd1 RW O_DIRECT
#device/dev-io.c:145         /dev/sdd1: block size is 4096 bytes
#device/dev-io.c:156         /dev/sdd1: physical block size is 512 bytes
#device/dev-io.c:625         Closed /dev/sdh1
#device/dev-io.c:570         Opened /dev/sdh1 RW O_DIRECT
#device/dev-io.c:145         /dev/sdh1: block size is 4096 bytes
#device/dev-io.c:156         /dev/sdh1: physical block size is 512 bytes
#metadata/metadata.c:588     Removing physical volume "/dev/sdb1" from volume group "cache_sanity"
#device/dev-io.c:308       /dev/sdb1: using cached size 52420032 sectors
#metadata/metadata.c:5278   Assertion failed: can't _pv_write non-orphan PV (in VG )
#metadata/metadata.c:602   Failed to remove physical volume "/dev/sdb1" from volume group "cache_sanity"
#metadata/metadata.c:588     Removing physical volume "/dev/sdc1" from volume group "cache_sanity"
#device/dev-io.c:308       /dev/sdc1: using cached size 52420032 sectors
#cache/lvmcache.c:1873         lvmcache /dev/sdc1: now in VG #orphans_lvm2 (#orphans_lvm2) with 1 mda(s).
#format_text/format-text.c:1377         Creating metadata area on /dev/sdc1 at sector 8 size 2040 sectors
#format_text/text_label.c:184         /dev/sdc1: Preparing PV label header pVAczK-zwWf-V5vb-Gs00-sfEB-vl0Q-Lkd5M7 size 26839056384 with da1 (2048s, 0s) mda1 (8s, 2040s)
#label/label.c:338       /dev/sdc1: Writing label to sector 1 with stored offset 32.
#cache/lvmetad.c:1651         Telling lvmetad to store PV /dev/sdc1 (pVAczK-zwWf-V5vb-Gs00-sfEB-vl0Q-Lkd5M7)
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#metadata/metadata.c:588     Removing physical volume "/dev/sdd1" from volume group "cache_sanity"
#device/dev-io.c:308       /dev/sdd1: using cached size 52420032 sectors
#cache/lvmcache.c:1873         lvmcache /dev/sdd1: now in VG #orphans_lvm2 (#orphans_lvm2) with 1 mda(s).
#format_text/format-text.c:1377         Creating metadata area on /dev/sdd1 at sector 8 size 2040 sectors
#format_text/text_label.c:184         /dev/sdd1: Preparing PV label header TWz71g-Qf7S-5ePh-h1X9-idCg-YYfZ-24uxRO size 26839056384 with da1 (2048s, 0s) mda1 (8s, 2040s)
#label/label.c:338       /dev/sdd1: Writing label to sector 1 with stored offset 32.
#cache/lvmetad.c:1651         Telling lvmetad to store PV /dev/sdd1 (TWz71g-Qf7S-5ePh-h1X9-idCg-YYfZ-24uxRO)
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#libdm-config.c:941       Setting response to OK
#metadata/metadata.c:588     Removing physical volume "/dev/sdh1" from volume group "cache_sanity"
#device/dev-io.c:308       /dev/sdh1: using cached size 52420032 sectors
#cache/lvmcache.c:1873         lvmcache /dev/sdh1: now in VG #orphans_lvm2 (#orphans_lvm2) with 1 mda(s).
#format_text/format-text.c:1377         Creating metadata area on /dev/sdh1 at sector 8 size 2040 sectors
#format_text/text_label.c:184         /dev/sdh1: Preparing PV label header kZs2rs-3aE2-JcfG-oiQV-rTjs-leR3-x9NEZA size 26839056384 with da1 (2048s, 0s) mda1 (8s, 2040s)
#label/label.c:338       /dev/sdh1: Writing label to sector 1 with stored offset 32.
#cache/lvmetad.c:1651         Telling lvmetad to store PV /dev/sdh1 (kZs2rs-3aE2-JcfG-oiQV-rTjs-leR3-x9NEZA)
#libdm-config.c:941       Setting response to OK



Version-Release number of selected component (if applicable):
3.10.0-419.el7.x86_64
lvm2-2.02.160-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
lvm2-libs-2.02.160-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
lvm2-cluster-2.02.160-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
device-mapper-1.02.130-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
device-mapper-libs-1.02.130-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
device-mapper-event-1.02.130-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
device-mapper-event-libs-1.02.130-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
device-mapper-persistent-data-0.6.2-0.1.rc8.el7    BUILT: Wed May  4 02:56:34 CDT 2016
cmirror-2.02.160-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016
sanlock-3.3.0-1.el7    BUILT: Wed Feb 24 09:52:30 CST 2016
sanlock-lib-3.3.0-1.el7    BUILT: Wed Feb 24 09:52:30 CST 2016
lvm2-lockd-2.02.160-1.el7    BUILT: Wed Jul  6 11:16:47 CDT 2016