[linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Hubert Kario]

[-- Attachment #1: Type: text/plain, Size: 4977 bytes --]

Hello everyone!

It seems that I'm using lvm2cmd library in quite specific way, as I call
lvm2_init() and lvm2_exit() multiple times during lifetime of a program,
or more specifically, my application calls lvm2_exit() as soon as it won't
need it for the next 10-15 minutes...

One specific proglem I noticed, that after calling lvm2_exit() valgrind
complains about invalid *writes* while doing printf() of *static* strings.

At first I thought that this was just a false positive, but my application
isn't stable, and when it crashes glibc reports:

	free(): invalid next size (fast)

gdb gives stacktrace pointing to freeing memory I'm completely sure is
allocated properly (it's strdup() of a const string, the same one that
previous 30000 allocations have and next 200000 allocations have).

So I've created a simple C program that also causes valgrind to complain as
soon as lvm2_exit() is called (attached below together with valgrind output).
In other words it looks to me like a bug in lvm2cmd library...

Please, keep me in CC as I'm not subscribed to this list

Regards,
Hubert Kario


Example application:

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <lvm2cmd.h>

int
main(int argc, char **argv)
{
    char *big_alloc = calloc(sizeof(char), 1024*1024*10);

    void *handle = lvm2_init();

    printf("Some text to output\n");

    char *string = strdup("Other text");

    printf("Variable before: \"%s\"\n", string);

    lvm2_exit(handle);

    printf("Variable after: \"%s\"\n", string);

    free(string);
    free(big_alloc);

    return 0;
}

Interesting part of valgrind output:

Variable before: "Other text"
==3565== Invalid write of size 1
==3565==    at 0x53BB944: _IO_file_xsputn@@GLIBC_2.2.5 (in /lib/libc-2.15.so)
==3565==    by 0x538B607: vfprintf (in /lib/libc-2.15.so)
==3565==    by 0x5395B98: printf (in /lib/libc-2.15.so)
==3565==    by 0x4007F6: main (test.c:21)
==3565==  Address 0x6b4c6a0 is 4,096 bytes inside a block of size 8,192 free'd
==3565==    at 0x4C29A9E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==3565==    by 0x4E48B11: destroy_toolcontext (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4EB5B02: lvm_fin (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4007E0: main (test.c:19)
==3565== 
==3565== Invalid write of size 1
==3565==    at 0x53BB944: _IO_file_xsputn@@GLIBC_2.2.5 (in /lib/libc-2.15.so)
==3565==    by 0x538E2F8: vfprintf (in /lib/libc-2.15.so)
==3565==    by 0x5395B98: printf (in /lib/libc-2.15.so)
==3565==    by 0x4007F6: main (test.c:21)
==3565==  Address 0x6b4c6b1 is 4,113 bytes inside a block of size 8,192 free'd
==3565==    at 0x4C29A9E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==3565==    by 0x4E48B11: destroy_toolcontext (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4EB5B02: lvm_fin (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4007E0: main (test.c:19)
==3565== 
==3565== Invalid write of size 1
==3565==    at 0x53BB944: _IO_file_xsputn@@GLIBC_2.2.5 (in /lib/libc-2.15.so)
==3565==    by 0x538C6C7: vfprintf (in /lib/libc-2.15.so)
==3565==    by 0x5395B98: printf (in /lib/libc-2.15.so)
==3565==    by 0x4007F6: main (test.c:21)
==3565==  Address 0x6b4c6bb is 4,123 bytes inside a block of size 8,192 free'd
==3565==    at 0x4C29A9E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==3565==    by 0x4E48B11: destroy_toolcontext (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4EB5B02: lvm_fin (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4007E0: main (test.c:19)
==3565== 
==3565== Syscall param write(buf) points to unaddressable byte(s)
==3565==    at 0x541F150: __write_nocancel (in /lib/libc-2.15.so)
==3565==    by 0x53BAFB2: _IO_file_write@@GLIBC_2.2.5 (in /lib/libc-2.15.so)
==3565==    by 0x53BAE91: new_do_write (in /lib/libc-2.15.so)
==3565==    by 0x53BBCB4: _IO_do_write@@GLIBC_2.2.5 (in /lib/libc-2.15.so)
==3565==    by 0x53BB9B1: _IO_file_xsputn@@GLIBC_2.2.5 (in /lib/libc-2.15.so)
==3565==    by 0x538C6C7: vfprintf (in /lib/libc-2.15.so)
==3565==    by 0x5395B98: printf (in /lib/libc-2.15.so)
==3565==    by 0x4007F6: main (test.c:21)
==3565==  Address 0x6b4c6a0 is 4,096 bytes inside a block of size 8,192 free'd
==3565==    at 0x4C29A9E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==3565==    by 0x4E48B11: destroy_toolcontext (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4EB5B02: lvm_fin (in /usr/lib/liblvm2cmd.so.2.02)
==3565==    by 0x4007E0: main (test.c:19)
==3565== 
Variable after: "Other text"
==3934== 
==3934== HEAP SUMMARY:
==3934==     in use at exit: 0 bytes in 0 blocks
==3934==   total heap usage: 2,575 allocs, 2,575 frees, 10,932,044 bytes allocated
==3934== 
==3934== All heap blocks were freed -- no leaks are possible
==3934== 
==3934== ERROR SUMMARY: 30 errors from 4 contexts (suppressed: 3 from 3)
-- 
Hubert Kario
hubert@kario.pl     kario@wit.edu.pl    https://hubert.kario.pl
PGP: 30D7 71F5 2F6F B157 872C  D811 A1D0 6BC9 8956 DCFE

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Alasdair G Kergon]

Your test program works for me:

$ valgrind ./a.out
==14092== Memcheck, a memory error detector
==14092== Copyright (C) 2002-2009, and GNU GPL'd, by Julian Seward et al.
==14092== Using Valgrind-3.5.0 and LibVEX; rerun with -h for copyright info
==14092== Command: ./a.out
==14092== 
Some text to output
Variable before: "Other text"
Variable after: "Other text"
==14092== 
==14092== HEAP SUMMARY:
==14092==     in use at exit: 0 bytes in 0 blocks
==14092==   total heap usage: 161 allocs, 161 frees, 10,620,400 bytes allocated
==14092== 
==14092== All heap blocks were freed -- no leaks are possible
==14092== 
==14092== For counts of detected and suppressed errors, rerun with: -v
==14092== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 6 from 6)

What version of lvm2 are you using?
Retest with upstream source?
What lvm configure options are you using?

Alasdair

Re: [linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Hubert Kario]

[-- Attachment #1: Type: text/plain, Size: 2043 bytes --]

On Wednesday 01 of August 2012 13:24:13 Alasdair G Kergon wrote:
> Your test program works for me:
> 
> $ valgrind ./a.out
> ==14092== Memcheck, a memory error detector
> ==14092== Copyright (C) 2002-2009, and GNU GPL'd, by Julian Seward et al.
> ==14092== Using Valgrind-3.5.0 and LibVEX; rerun with -h for copyright
> info ==14092== Command: ./a.out
> ==14092==
> Some text to output
> Variable before: "Other text"
> Variable after: "Other text"
> ==14092==
> ==14092== HEAP SUMMARY:
> ==14092==     in use at exit: 0 bytes in 0 blocks
> ==14092==   total heap usage: 161 allocs, 161 frees, 10,620,400 bytes allocated 
> ==14092==
> ==14092== All heap blocks were freed -- no leaks are possible
> ==14092==
> ==14092== For counts of detected and suppressed errors, rerun with: -v
> ==14092== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 6 from 6)

You've got 6 supressions, while I've got 3. Could be that errors I see are
hidden from You.

Try running with
valgrind -v ./a.out

I've re-worked the application to work with only one lvm2 handle and it's
been stable for the past 17h while with multiple lvm2_exit()'s called it would crash
after 2-3minutes...
 
> What version of lvm2 are you using?

lvm2 2.02.96-2
gcc-multilib 4.7.1-1
valgrind 3.7.0-2

> Retest with upstream source?
> What lvm configure options are you using?

It is vanilla upstream source, Archlinux package doesn't use any
distro-specific patches, it's compiled with

./configure --prefix=/ --sbindir=/sbin --sysconfdir=/etc --localstatedir=/var --datarootdir=/usr/share \
    --includedir=/usr/include --with-usrlibdir=/usr/lib  --libdir=/usr/lib --with-udev-prefix=/usr \
    --with-systemdsystemunitdir=/usr/lib/systemd/system --enable-pkgconfig --enable-readline \
    --enable-dmeventd --enable-cmdlib --enable-applib --enable-udev_sync --enable-udev_rules  \
    --with-default-locking-dir=/run/lock/lvm
make

Regards,
-- 
Hubert Kario
hubert@kario.pl     kario@wit.edu.pl    https://hubert.kario.pl
PGP: 30D7 71F5 2F6F B157 872C  D811 A1D0 6BC9 8956 DCFE

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Alasdair G Kergon]

On Wed, Aug 01, 2012 at 06:17:03PM +0200, Hubert Kario wrote:
> You've got 6 supressions, while I've got 3. Could be that errors I see are
> hidden from You.
 
I don't think those 6 matter.
  --11875-- used_suppression:      6 dl-hack3-cond-1

I'm not seeing messages like yours, even when I enable a similar set of config
options.

Alasdair

Re: [linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Alasdair G Kergon]

Another factor might be different contents in your lvm.conf file compared with
mine, or different devices present causing you to hit a problem code path
and me not to.

Or some other difference in the distribution/compiler/libraries etc.

Alasdair

Re: [linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Hubert Kario]

[-- Attachment #1.1: Type: text/plain, Size: 2167 bytes --]

On Thursday 02 of August 2012 02:50:17 Alasdair G Kergon wrote:
> Another factor might be different contents in your lvm.conf file compared
> with mine, or different devices present causing you to hit a problem code
> path and me not to.

As far as I know, I'm using standard lvm.conf (attached).

I'm having the same error (in valgrind) when I run the test app as a regular 
user, so actual LVM config shouldn't have any effect (?):

  /dev/mapper/control: open failed: Permission denied
  Failure to communicate with kernel device-mapper driver.

> 
> Or some other difference in the distribution/compiler/libraries etc.

I don't think so, I've got a test app that reliably crashes with normal 
execution while works fine under valgrind:

#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <lvm2cmd.h>
#include <unistd.h>
#include <assert.h>
#include <signal.h>
#include <string.h>

int keep_running = 1;

void
signal_handler(int dummy)
{
    keep_running = 0;
}

int
main(int argc, char **argv)
{
    signal(SIGTERM, signal_handler);
    signal(SIGINT, signal_handler);

    const char dev[] = "string";

    printf("Variable before: \"%s\"\n", dev);

    void *handle = lvm2_init();

    lvm2_exit(handle);

    while (keep_running) {

        int arr_len = (random()%320+1) * 1024;

        char **table = malloc(sizeof(char *) * arr_len);
        assert(table);
        for (size_t i=0; i<arr_len; i++) {
            table[i] = strdup(dev);
            assert(table[i]);
        }

        char *big_alloc = malloc(arr_len * 1024);
        big_alloc[0] = '\0';
        big_alloc[4095] = '\0';
        big_alloc[arr_len * 1024 - 4096] = '\0';

        printf("Some text to output\n");

        char *string = strdup("Other text");

        printf("Variable after: \"%s\"\n", table[arr_len/2]);

        free(string);
        free(big_alloc);

        for (size_t i=0; i<arr_len; i++) {
            free(table[i]);
        }
        free(table);

        //sleep(1);
    }

    return 0;
}
-- 
Hubert Kario
hubert@kario.pl     kario@wit.edu.pl    https://hubert.kario.pl
PGP: 30D7 71F5 2F6F B157 872C  D811 A1D0 6BC9 8956 DCFE

[-- Attachment #1.2: lvm.conf --]
[-- Type: text/plain, Size: 2393 bytes --]

devices {
    dir = "/dev"
    scan = [ "/dev" ]
    obtain_device_list_from_udev = 1
    preferred_names = [ ]
    filter = [ "a/.*/" ]
    cache_dir = "/etc/lvm/cache"
    cache_file_prefix = ""
    write_cache_state = 1
    sysfs_scan = 1
    multipath_component_detection = 1
    md_component_detection = 1
    md_chunk_alignment = 1
    data_alignment_detection = 1
    data_alignment = 0
    data_alignment_offset_detection = 1
    ignore_suspended_devices = 0
    disable_after_error_count = 0
    require_restorefile_with_uuid = 1
    pv_min_size = 2048
    issue_discards = 0
}
allocation {
 
    maximise_cling = 1
    mirror_logs_require_separate_pvs = 0
    thin_pool_metadata_require_separate_pvs = 0
}
log {
    verbose = 0
    syslog = 1
    overwrite = 0
    level = 0
    indent = 1
    command_names = 0
    prefix = "  "
}
backup {
    backup = 1
    backup_dir = "/etc/lvm/backup"
    archive = 1
    archive_dir = "/etc/lvm/archive"
    retain_min = 10
    retain_days = 30
}
shell {
    history_size = 100
}
global {
    umask = 077
    test = 0
    units = "h"
    si_unit_consistency = 1
    activation = 1
    proc = "/proc"
    locking_type = 1
    wait_for_locks = 1
    fallback_to_clustered_locking = 1
    fallback_to_local_locking = 1
    locking_dir = "/var/lock/lvm"
    prioritise_write_locks = 1
    abort_on_internal_errors = 0
    detect_internal_vg_cache_corruption = 0
    metadata_read_only = 0
    mirror_segtype_default = "mirror"
    use_lvmetad = 0
    thin_check_executable = ""
    thin_check_options = [ "-q" ]
}
activation {
    checks = 0
    udev_sync = 1
    udev_rules = 1
    verify_udev_operations = 0
    retry_deactivation = 1
    missing_stripe_filler = "error"
    use_linear_target = 1
    reserved_stack = 64
    reserved_memory = 8192
    process_priority = -18
    mirror_region_size = 512
    readahead = "auto"
    raid_fault_policy = "warn"
    mirror_log_fault_policy = "allocate"
    mirror_image_fault_policy = "remove"
    snapshot_autoextend_threshold = 100
    snapshot_autoextend_percent = 20
    thin_pool_autoextend_threshold = 100
    thin_pool_autoextend_percent = 20
    use_mlockall = 0
    monitoring = 1
    polling_interval = 15
}
dmeventd {
    mirror_library = "libdevmapper-event-lvm2mirror.so"
    snapshot_library = "libdevmapper-event-lvm2snapshot.so"
    thin_library = "libdevmapper-event-lvm2thin.so"
}

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [linux-lvm] [lvm2cmd] Heap destruction by lvm2_exit()?

[Hubert Kario]

[-- Attachment #1: Type: text/plain, Size: 704 bytes --]

On Thursday 02 of August 2012 02:50:17 Alasdair G Kergon wrote:
> Another factor might be different contents in your lvm.conf file compared
> with mine, or different devices present causing you to hit a problem code
> path and me not to.
> 
> Or some other difference in the distribution/compiler/libraries etc.

Interesting, I've tried to run the second test application on debian squeeze 
(stable) and it worked so this could be a regression...

It works with 
lvm2 2.02.66
gcc 4.4.5
glibc 2.13

While it doesn't with
lvm2 2.02.96-2
gcc 4.7.1-1
glibc 2.15

Regards,
-- 
Hubert Kario
hubert@kario.pl     kario@wit.edu.pl    https://hubert.kario.pl
PGP: 30D7 71F5 2F6F B157 872C  D811 A1D0 6BC9 8956 DCFE

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 836 bytes --]