Bug 1396596

Summary: "Internal error: pool_free asked to free pointer not in pool" when attempting conversion to raid4 from raid0_meta
Product: Red Hat Enterprise Linux 7 Reporter: Corey Marthaler <cmarthal>
Component: lvm2Assignee: Heinz Mauelshagen <heinzm>
lvm2 sub component: Mirroring and RAID QA Contact: cluster-qe <cluster-qe>
Status: CLOSED WORKSFORME Docs Contact:
Severity: urgent    
Priority: unspecified CC: agk, heinzm, jbrassow, msnitzer, prajnoha, prockai, 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: 2016-11-18 20:14:50 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-11-18 17:29:40 UTC
Description of problem:
This is an attempt to test the conversion scenarios mentioned in bugs 1386184/1395562 while running on different kernels/dmraid targets.


[root@host-090 ~]#  dmsetup targets|grep raid
raid             v1.9.1

3.10.0-516.el7.x86_64

lvm2-2.02.166-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
lvm2-libs-2.02.166-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
lvm2-cluster-2.02.166-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
device-mapper-1.02.135-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
device-mapper-libs-1.02.135-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
device-mapper-event-1.02.135-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
device-mapper-event-libs-1.02.135-1.el7_3.2    BUILT: Wed Nov 16 04:11:32 CST 2016
device-mapper-persistent-data-0.6.3-1.el7    BUILT: Fri Jul 22 05:29:13 CDT 2016


[root@host-090 ~]# pvscan --cache
[root@host-090 ~]# pvscan
  PV /dev/sda1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sdb1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sdc1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sdd1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sde1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sdf1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sdg1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/sdh1   VG vg              lvm2 [19.99 GiB / 19.99 GiB free]
  PV /dev/vda2   VG rhel_host-090   lvm2 [7.00 GiB / 0    free]
  Total: 9 [166.93 GiB] / in use: 9 [166.93 GiB] / in no VG: 0 [0   ]

[root@host-090 ~]# lvcreate -i2 --ty striped -L64 -nlv vg
  Using default stripesize 64.00 KiB.
  Logical volume "lv" created.

[root@host-090 ~]# lvconvert --ty raid0 vg/lv
  Using default stripesize 64.00 KiB.
  Logical volume vg/lv successfully converted.

[root@host-090 ~]# lvconvert --ty raid0_meta vg/lv
  Using default stripesize 64.00 KiB.
  Logical volume vg/lv successfully converted.

[root@host-090 ~]# lvconvert --ty raid4 vg/lv
  Using default stripesize 64.00 KiB.
  Internal error: pool_free asked to free pointer not in pool
*** Error in `lvconvert': corrupted double-linked list: 0x00007f4758da8100 ***
======= Backtrace: =========
/lib64/libc.so.6(+0x7ada4)[0x7f4755be5da4]
/lib64/libc.so.6(+0x7c595)[0x7f4755be7595]
lvconvert(+0x87f4d)[0x7f4756ed1f4d]
lvconvert(dev_read+0x45)[0x7f4756ed27c5]
lvconvert(+0x9977c)[0x7f4756ee377c]
lvconvert(raw_read_mda_header+0x33)[0x7f4756ee4593]
lvconvert(+0x9afac)[0x7f4756ee4fac]
lvconvert(vg_write+0x711)[0x7f4756f159f1]
lvconvert(+0xac9b3)[0x7f4756ef69b3]
lvconvert(+0xdd78b)[0x7f4756f2778b]
lvconvert(+0xe3d88)[0x7f4756f2dd88]
lvconvert(lv_raid_convert+0x2cf)[0x7f4756f2fa6f]
lvconvert(+0x33c39)[0x7f4756e7dc39]
lvconvert(+0x36af9)[0x7f4756e80af9]
lvconvert(process_each_lv_in_vg+0x7c6)[0x7f4756ea6d46]
lvconvert(process_each_lv+0xc89)[0x7f4756ea8049]
lvconvert(lvconvert+0x19d3)[0x7f4756e83933]
lvconvert(lvm_run_command+0x1208)[0x7f4756e91108]
lvconvert(lvm2_main+0x436)[0x7f4756e91f06]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f4755b8cb35]
lvconvert(+0x2a57e)[0x7f4756e7457e]
======= Memory map: ========
7f4748000000-7f4748021000 rw-p 00000000 00:00 0 
7f4748021000-7f474c000000 ---p 00000000 00:00 0 
7f474d509000-7f4753a32000 r--p 00000000 fd:00 12615927                   /usr/lib/locale/locale-archive
7f4753a32000-7f4753a92000 r-xp 00000000 fd:00 8623920                    /usr/lib64/libpcre.so.1.2.0
7f4753a92000-7f4753c91000 ---p 00060000 fd:00 8623920                    /usr/lib64/libpcre.so.1.2.0
7f4753c91000-7f4753c92000 r--p 0005f000 fd:00 8623920                    /usr/lib64/libpcre.so.1.2.0
7f4753c92000-7f4753c93000 rw-p 00060000 fd:00 8623920                    /usr/lib64/libpcre.so.1.2.0
7f4753c93000-7f4753ca2000 r-xp 00000000 fd:00 8632205                    /usr/lib64/libbz2.so.1.0.6
7f4753ca2000-7f4753ea1000 ---p 0000f000 fd:00 8632205                    /usr/lib64/libbz2.so.1.0.6
7f4753ea1000-7f4753ea2000 r--p 0000e000 fd:00 8632205                    /usr/lib64/libbz2.so.1.0.6
7f4753ea2000-7f4753ea3000 rw-p 0000f000 fd:00 8632205                    /usr/lib64/libbz2.so.1.0.6
7f4753ea3000-7f4753ec8000 r-xp 00000000 fd:00 8632207                    /usr/lib64/liblzma.so.5.2.2
7f4753ec8000-7f47540c7000 ---p 00025000 fd:00 8632207                    /usr/lib64/liblzma.so.5.2.2
7f47540c7000-7f47540c8000 r--p 00024000 fd:00 8632207                    /usr/lib64/liblzma.so.5.2.2
7f47540c8000-7f47540c9000 rw-p 00025000 fd:00 8632207                    /usr/lib64/liblzma.so.5.2.2
7f47540c9000-7f47540de000 r-xp 00000000 fd:00 8632195                    /usr/lib64/libz.so.1.2.7
7f47540de000-7f47542dd000 ---p 00015000 fd:00 8632195                    /usr/lib64/libz.so.1.2.7
7f47542dd000-7f47542de000 r--p 00014000 fd:00 8632195                    /usr/lib64/libz.so.1.2.7
7f47542de000-7f47542df000 rw-p 00015000 fd:00 8632195                    /usr/lib64/libz.so.1.2.7
7f47542df000-7f47542f6000 r-xp 00000000 fd:00 8632213                    /usr/lib64/libelf-0.166.so
7f47542f6000-7f47544f5000 ---p 00017000 fd:00 8632213                    /usr/lib64/libelf-0.166.so
7f47544f5000-7f47544f6000 r--p 00016000 fd:00 8632213                    /usr/lib64/libelf-0.166.so
7f47544f6000-7f47544f7000 rw-p 00017000 fd:00 8632213                    /usr/lib64/libelf-0.166.so
7f47544f7000-7f47544fb000 r-xp 00000000 fd:00 8647517                    /usr/lib64/libattr.so.1.1.0
7f47544fb000-7f47546fa000 ---p 00004000 fd:00 8647517                    /usr/lib64/libattr.so.1.1.0
7f47546fa000-7f47546fb000 r--p 00003000 fd:00 8647517                    /usr/lib64/libattr.so.1.1.0
7f47546fb000-7f47546fc000 rw-p 00004000 fd:00 8647517                    /usr/lib64/libattr.so.1.1.0
7f47546fc000-7f4754721000 r-xp 00000000 fd:00 8623897                    /usr/lib64/libtinfo.so.5.9
7f4754721000-7f4754921000 ---p 00025000 fd:00 8623897                    /usr/lib64/libtinfo.so.5.9
7f4754921000-7f4754925000 r--p 00025000 fd:00 8623897                    /usr/lib64/libtinfo.so.5.9
7f4754925000-7f4754926000 rw-p 00029000 fd:00 8623897                    /usr/lib64/libtinfo.so.5.9
7f4754926000-7f47549bb000 r-xp 00000000 fd:00 8623918                    /usr/lib64/libsepol.so.1
7f47549bb000-7f4754bbb000 ---p 00095000 fd:00 8623918                    /usr/lib64/libsepol.so.1
7f4754bbb000-7f4754bbc000 r--p 00095000 fd:00 8623918                    /usr/lib64/libsepol.so.1
7f4754bbc000-7f4754bbd000 rw-p 00096000 fd:00 8623918                    /usr/lib64/libsepol.so.1
7f4754bbd000-7f4754bbe000 rw-p 00000000 00:00 0 
7f4754bbe000-7f4754be2000 r-xp 00000000 fd:00 8632192                    /usr/lib64/libselinux.so.1
7f4754be2000-7f4754de1000 ---p 00024000 fd:00 8632192                    /usr/lib64/libselinux.so.1
7f4754de1000-7f4754de2000 r--p 00023000 fd:00 8632192                    /usr/lib64/libselinux.so.1
7f4754de2000-7f4754de3000 rw-p 00024000 fd:00 8632192                    /usr/lib64/libselinux.so.1
7f4754de3000-7f4754de5000 rw-p 00000000 00:00 0 
7f4754de5000-7f4754de9000 r-xp 00000000 fd:00 8632201                    /usr/lib64/libuuid.so.1.3.0
7f4754de9000-7f4754fe8000 ---p 00004000 fd:00 8632201                    /usr/lib64/libuuid.so.1.3.0
7f4754fe8000-7f4754fe9000 r--p 00003000 fd:00 8632201                    /usr/lib64/libuuid.so.1.3.0
7f4754fe9000-7f4754fea000 rw-p 00004000 fd:00 8632201                    /usr/lib64/libuuid.so.1.3.0
7f4754fea000-7f4755001000 r-xp 00000000 fd:00 8609405                    /usr/lib64/libpthread-2.17.so
7f4755001000-7f4755200000 ---p 00017000 fd:00 8609405                    /usr/lib64/libpthread-2.17.so
7f4755200000-7f4755201000 r--p 00016000 fd:00 8609405                    /usr/lib64/libpthread-2.17.so
7f4755201000-7f4755202000 rw-p 00017000 fd:00 8609405                    /usr/lib64/libpthread-2.17.so
7f4755202000-7f4755206000 rw-p 00000000 00:00 0 
7f4755206000-7f475521b000 r-xp 00000000 fd:00 8560521                    /usr/lib64/libgcc_s-4.8.5-20150702.so.1
7f475521b000-7f475541a000 ---p 00015000 fd:00 8560521                    /usr/lib64/libgcc_s-4.8.5-20150702.so.1
7f475541a000-7f475541b000 r--p 00014000 fd:00 8560521                    /usr/lib64/libgcc_s-4.8.5-20150702.so.1
7f475541b000-7f475541c000 rw-p 00015000 fd:00 8560521                    /usr/lib64/libgcc_s-4.8.5-20150702.so.1
7f475541c000-7f4755461000 r-xp 00000000 fd:00 8647503                    /usr/lib64/libdw-0.166.so
7f4755461000-7f4755661000 ---p 00045000 fd:00 8647503                    /usr/lib64/libdw-0.166.so
7f4755661000-7f4755663000 r--p 00045000 fd:00 8647503                    /usr/lib64/libdw-0.166.soAborted (core dumped)




Core was generated by `lvconvert --ty raid4 vg/lv'.
Program terminated with signal 6, Aborted.
#0  0x00007f4755ba01d7 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install bzip2-libs-1.0.6-13.el7.x86_64 elfutils-libelf-0.166-2.el7.x86_64 elfutils-libs-0.166-2.el7.x86_64 glibc-2.17-157.el7.x86_64 libattr-2.4.46-12.el7.x86_64 libblkid-2.23.2-33.el7.x86_64 libcap-2.22-8.el7.x86_64 libgcc-4.8.5-11.el7.x86_64 libselinux-2.5-6.el7.x86_64 libsepol-2.5-6.el7.x86_64 libuuid-2.23.2-33.el7.x86_64 ncurses-libs-5.9-13.20130511.el7.x86_64 pcre-8.32-15.el7_2.1.x86_64 readline-6.2-9.el7.x86_64 systemd-libs-219-30.el7.x86_64 xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-17.el7.x86_64
(gdb) bt
#0  0x00007f4755ba01d7 in raise () from /lib64/libc.so.6
#1  0x00007f4755ba18c8 in abort () from /lib64/libc.so.6
#2  0x00007f4755bdff07 in __libc_message () from /lib64/libc.so.6
#3  0x00007f4755be5da4 in malloc_printerr () from /lib64/libc.so.6
#4  0x00007f4755be7595 in _int_free () from /lib64/libc.so.6
#5  0x00007f4756ed1f4d in _aligned_io (where=where@entry=0x7fffa4b49510, buffer=buffer@entry=0x7f4755f257c0 <main_arena+96> "\255\070\341H LVM2 x[5A%r0N*>\001", should_write=should_write@entry=0)
    at device/dev-io.c:271
#6  0x00007f4756ed27c5 in dev_read (dev=0x7f4758e0b4e0, offset=<optimized out>, len=len@entry=512, buffer=buffer@entry=0x7f4755f257c0 <main_arena+96>) at device/dev-io.c:713
#7  0x00007f4756ee377c in _raw_read_mda_header (mdah=mdah@entry=0x7f4755f257c0 <main_arena+96>, dev_area=0x7f4758df7290, dev_area=0x7f4758df7290) at format_text/format-text.c:325
#8  0x00007f4756ee4593 in raw_read_mda_header (fmt=0x7f4758d84ff0, dev_area=0x7f4758df7290) at format_text/format-text.c:379
#9  0x00007f4756ee4fac in _vg_write_raw (fid=0x7f4758df71f0, vg=0x7f4758e195b0, mda=<optimized out>) at format_text/format-text.c:630
#10 0x00007f4756f159f1 in vg_write (vg=vg@entry=0x7f4758e195b0) at metadata/metadata.c:3507
#11 0x00007f4756ef69b3 in _lv_update_and_reload (lv=lv@entry=0x7f4758e1a3a8, origin_only=origin_only@entry=1) at metadata/lv_manip.c:6180
#12 0x00007f4756f01e8a in lv_update_and_reload_origin (lv=lv@entry=0x7f4758e1a3a8) at metadata/lv_manip.c:6214
#13 0x00007f4756f2778b in _lv_update_reload_fns_reset_eliminate_lvs (lv=lv@entry=0x7f4758e1a3a8, removal_lvs=removal_lvs@entry=0x0) at metadata/raid_manip.c:1976
#14 0x00007f4756f2dd88 in _striped_or_raid0_to_raid45610_wrapper (lv=<optimized out>, new_segtype=<optimized out>, new_image_count=<optimized out>, new_data_copies=<optimized out>, 
    new_region_size=1024, allocate_pvs=<optimized out>, new_stripe_size=<optimized out>, force=<optimized out>, yes=<optimized out>, new_stripes=0) at metadata/raid_manip.c:3218
#15 0x00007f4756f2fa6f in lv_raid_convert (lv=lv@entry=0x7f4758e1a3a8, new_segtype=0x7f4758d9c690, yes=0, force=0, new_stripes=0, new_stripe_size_supplied=<optimized out>, new_stripe_size=128, 
    new_region_size=1024, allocate_pvs=0x7f4758e19688) at metadata/raid_manip.c:3743
#16 0x00007f4756e7dc39 in _lvconvert_raid (lv=lv@entry=0x7f4758e1a3a8, lp=lp@entry=0x7fffa4b49d70) at lvconvert.c:1973
#17 0x00007f4756e80af9 in _convert_striped_raid (cmd=<optimized out>, lp=0x7fffa4b49d70, lv=0x7f4758e1a3a8) at lvconvert.c:4125
#18 _convert_striped (lp=<optimized out>, lv=<optimized out>, cmd=<optimized out>) at lvconvert.c:4408
#19 _lvconvert (lp=0x7fffa4b49d70, lv=0x7f4758e1a3a8, cmd=0x7f4758d5e020) at lvconvert.c:4570
#20 _lvconvert_and_add_to_poll_list (cmd=0x7f4758d5e020, lp=0x7fffa4b49d70, lv=0x7f4758e1a3a8) at lvconvert.c:4615
#21 0x00007f4756ea6d46 in process_each_lv_in_vg (cmd=cmd@entry=0x7f4758d5e020, vg=vg@entry=0x7f4758e195b0, arg_lvnames=arg_lvnames@entry=0x7fffa4b49bf0, tags_in=tags_in@entry=0x7fffa4b49ba0, 
    stop_on_error=stop_on_error@entry=0, handle=handle@entry=0x7f4758da7d48, process_single_lv=process_single_lv@entry=0x7f4756e81de0 <_lvconvert_single>) at toollib.c:2505
#22 0x00007f4756ea8049 in _process_lv_vgnameid_list (process_single_lv=0x7f4756e81de0 <_lvconvert_single>, handle=0x7f4758da7d48, arg_tags=0x7fffa4b49ba0, arg_lvnames=0x7fffa4b49bc0, 
    arg_vgnames=0x7fffa4b49bb0, vgnameids_to_process=0x7fffa4b49be0, read_flags=1048576, cmd=0x7f4758d5e020) at toollib.c:2830
#23 process_each_lv (cmd=cmd@entry=0x7f4758d5e020, argc=argc@entry=0, argv=argv@entry=0x0, one_vgname=<optimized out>, one_lvname=<optimized out>, read_flags=read_flags@entry=1048576, 
    handle=handle@entry=0x7f4758da7d48, process_single_lv=process_single_lv@entry=0x7f4756e81de0 <_lvconvert_single>) at toollib.c:2976
#24 0x00007f4756e83933 in lvconvert (cmd=0x7f4758d5e020, argc=1, argv=<optimized out>) at lvconvert.c:4705
#25 0x00007f4756e91108 in lvm_run_command (cmd=cmd@entry=0x7f4758d5e020, argc=1, argc@entry=4, argv=0x7fffa4b4a180, argv@entry=0x7fffa4b4a168) at lvmcmdline.c:1723
#26 0x00007f4756e91f06 in lvm2_main (argc=4, argv=0x7fffa4b4a168) at lvmcmdline.c:2249
#27 0x00007f4755b8cb35 in __libc_start_main () from /lib64/libc.so.6
#28 0x00007f4756e7457e in _start ()

Comment 1 Heinz Mauelshagen 2016-11-18 19:36:58 UTC
Corey told me he could not reproduce either.
I ran iterations of the command sequence under valgrind and did not see any incidence:
[root@work ~]# for i in {0..31};do for type in striped raid0 raid0_meta raid4; do echo "==== $type ===";valgrind lvconvert -y --ty $type iscsi/r 2>&1;done;done |egrep -i "in use at|total heap|error sum|striped|raid"|egrep -v "_lvconvert_raid|0 errors from 0|0 bytes in 0"
==== striped ===
==17858== Command: lvconvert -y --ty striped iscsi/r
  Operation not permitted on striped or linear LV iscsi/r.
  Operations permitted on a striped or linear LV are:
  --type raid*
==17858==   total heap usage: 13,570 allocs, 13,570 frees, 22,485,250 bytes allocated
==== raid0 ===
==17860== Command: lvconvert -y --ty raid0 iscsi/r
==17860==   total heap usage: 17,141 allocs, 17,141 frees, 30,816,258 bytes allocated
==== raid0_meta ===
==17893== Command: lvconvert -y --ty raid0_meta iscsi/r
==17893==   total heap usage: 19,787 allocs, 19,787 frees, 39,013,723 bytes allocated
==== raid4 ===
==17956== Command: lvconvert -y --ty raid4 iscsi/r
==17956==   total heap usage: 28,040 allocs, 28,040 frees, 64,557,298 bytes allocated
==== striped ===
==18175== Command: lvconvert -y --ty striped iscsi/r
==18175==   total heap usage: 19,925 allocs, 19,925 frees, 39,978,865 bytes allocated
==== raid0 ===
==18238== Command: lvconvert -y --ty raid0 iscsi/r
==18238==   total heap usage: 17,145 allocs, 17,145 frees, 30,804,209 bytes allocated
==== raid0_meta ===
==18270== Command: lvconvert -y --ty raid0_meta iscsi/r
==18270==   total heap usage: 19,791 allocs, 19,791 frees, 38,989,396 bytes allocated
==== raid4 ===
==18331== Command: lvconvert -y --ty raid4 iscsi/r
==18331==   total heap usage: 28,007 allocs, 28,007 frees, 64,446,361 bytes allocated
....

Comment 2 Heinz Mauelshagen 2016-11-18 19:54:34 UTC
Corey,
please close for the time being in case you can't reproduce.
We can reopen if we get a reliable reproducer.

Comment 3 Corey Marthaler 2016-11-18 20:14:50 UTC
Marking closed until reproduced again...