llvm dev - Feb 2016 - Buildling with/without AddressSanitizer causes divergent execution behaviour

Hi,

# TL;DR

I've been building an application with and without the address
sanitizer (with gcc 5.3 and clang 3.7.1) and I've observed that the
application's behaviour changes (assertion hit/ not hit). I'm
wondering if this could be a bug in address sanitizer or if the
application I'm running is just buggy (e.g. doing bad things like
relying on memory layout, etc.). I'm also observing ASan reporting a
heap-use-after-free which Valgrind is not reporting, which makes me
wonder if it is a false positive.

Any hints on how I might determine this? Building with UBSan doesn't
turn up anything.

# Longer version (if you are interested in the specific details)

The application of interest is the Z3 constraint solver [1].

Much of what I'm going to say is covered in [2] which is a bug report
I opened (including a heap-use-after-free AddressSanitizer finds, I'm
not sure if this a false positive or not) but here are the basics of
what I found.

Build Z3 as follows

```
git clone https://github.com/Z3Prover/z3.git
cd z3

# Now apply the attached patch.
# Basically this makes it so that in ``examples/c/test_capi.c``
# the main() function only calls two functions.
# Note if you build without the patch when running ``c_example``
program AddressSanitizer
# reports a heap-use-after-free. I'm not sure if this a false positive
or not. Valgrind doesn't
# seem to think there's a problem.

# Build with ASan, Assertion will be hit when running the example
CXX=clang++ CC=clang CXXFLAGS="-fno-omit-frame-pointer
-fsanitize=address" LDFLAGS="-fsanitize=address" python
scripts/mk_make.py --debug --noomp --build build_asan
cd build_asan
make
make c_examples
LD_LIBRARY_PATH=`pwd` ./c_example
...
ASSERTION VIOLATION
File: ../src/sat/sat_clause.h
Line: 59

# Now build without ASan
cd ../
CXX=clang++ CC=clang python scripts/mk_make.py --debug --noomp --build
build_noasan
cd build_noasan
make
make c_example
LD_LIBRARY_PATH=`pwd` ./c_example

# No assertion is hit
```

Any insights/suggestions on how I could debug what I'm seeing further
would be appreciated.

[1] https://github.com/z3prover/z3
[2] https://github.com/Z3Prover/z3/issues/436

Thanks,
Dan.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: patch_c_examples.patch
Type: text/x-patch
Size: 1218 bytes
Desc: not available
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20160209/d3ebf585/attachment.bin>

Hi Dan,

On Tue, Feb 9, 2016 at 10:57 AM, Dan Liew <dan at su-root.co.uk> wrote:
> Hi,
>
> # TL;DR
>
> I've been building an application with and without the address
> sanitizer (with gcc 5.3 and clang 3.7.1) and I've observed that the
> application's behaviour changes (assertion hit/ not hit). I'm
> wondering if this could be a bug in address sanitizer or if the
> application I'm running is just buggy (e.g. doing bad things like
> relying on memory layout, etc.). I'm also observing ASan reporting a
> heap-use-after-free which Valgrind is not reporting, which makes me
> wonder if it is a false positive.
>
Let us start from this heap-use-after-free report. The one in
https://github.com/Z3Prover/z3/issues/436 looks legitimate.
Unless the application does something extremely weird and tricky,
heap-use-after-free reports are usually true positives.

Can you somehow verify that this heap-use-after-free is happening?
E.g. print all the pointer values coming from memory::allocate, coming
into memory::deallocate, and coming into sat::clause::operator[]

If curious, check what size of quarantine is required to catch this bug
(ASAN_OPTIONS=quarantine_size_mb=N, default=256)
Valgrind may have smaller default quarantine and thus misses this bug.

>
> Any hints on how I might determine this? Building with UBSan doesn't
> turn up anything.
>
Does the application have threads? (If yes, did you run with TSan?)
Is it valgrind-clean?
Did you try msan?

>
> # Longer version (if you are interested in the specific details)
>
> The application of interest is the Z3 constraint solver [1].
>
Yay!

>
> Much of what I'm going to say is covered in [2] which is a bug report
> I opened (including a heap-use-after-free AddressSanitizer finds, I'm
> not sure if this a false positive or not) but here are the basics of
> what I found.
>
> Build Z3 as follows
>
> ```
> git clone https://github.com/Z3Prover/z3.git
> cd z3
>
> # Now apply the attached patch.
> # Basically this makes it so that in ``examples/c/test_capi.c``
> # the main() function only calls two functions.
> # Note if you build without the patch when running ``c_example``
> program AddressSanitizer
> # reports a heap-use-after-free. I'm not sure if this a false positive
> or not. Valgrind doesn't
> # seem to think there's a problem.
>
> # Build with ASan, Assertion will be hit when running the example
> CXX=clang++ CC=clang CXXFLAGS="-fno-omit-frame-pointer
> -fsanitize=address" LDFLAGS="-fsanitize=address" python
> scripts/mk_make.py --debug --noomp --build build_asan
> cd build_asan
> make
> make c_examples
> LD_LIBRARY_PATH=`pwd` ./c_example
> ...
> ASSERTION VIOLATION
> File: ../src/sat/sat_clause.h
> Line: 59
>
> # Now build without ASan
> cd ../
> CXX=clang++ CC=clang python scripts/mk_make.py --debug --noomp --build
> build_noasan
> cd build_noasan
> make
> make c_example
> LD_LIBRARY_PATH=`pwd` ./c_example
>
> # No assertion is hit
> ```
>
> Any insights/suggestions on how I could debug what I'm seeing further
> would be appreciated.
>
> [1] https://github.com/z3prover/z3
> [2] https://github.com/Z3Prover/z3/issues/436
>
> Thanks,
> Dan.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20160209/780cb470/attachment.html>

On 02/09/2016 09:57 PM, Dan Liew via cfe-dev wrote:
> Hi,
>
> # TL;DR
>
> I've been building an application with and without the address
> sanitizer (with gcc 5.3 and clang 3.7.1) and I've observed that the
> application's behaviour changes (assertion hit/ not hit). I'm
> wondering if this could be a bug in address sanitizer or if the
> application I'm running is just buggy (e.g. doing bad things like
> relying on memory layout, etc.).
We've experienced such situations as well. Usually this was caused by 
some wild memory write which was unnoticed before but started to corrupt 
something important due to changed stack/heap layout.

You can try to apply ASan selectively to parts of your program to 
isolate the problem.
> I'm also observing ASan reporting a
> heap-use-after-free which Valgrind is not reporting, which makes me
> wonder if it is a false positive.
>
> Any hints on how I might determine this? Building with UBSan doesn't
> turn up anything.
>
> # Longer version (if you are interested in the specific details)
>
> The application of interest is the Z3 constraint solver [1].
>
> Much of what I'm going to say is covered in [2] which is a bug report
> I opened (including a heap-use-after-free AddressSanitizer finds, I'm
> not sure if this a false positive or not) but here are the basics of
> what I found.
>
> Build Z3 as follows
>
> ```
> git clone https://github.com/Z3Prover/z3.git
> cd z3
>
> # Now apply the attached patch.
> # Basically this makes it so that in ``examples/c/test_capi.c``
> # the main() function only calls two functions.
> # Note if you build without the patch when running ``c_example``
> program AddressSanitizer
> # reports a heap-use-after-free. I'm not sure if this a false positive
> or not. Valgrind doesn't
> # seem to think there's a problem.
>
> # Build with ASan, Assertion will be hit when running the example
> CXX=clang++ CC=clang CXXFLAGS="-fno-omit-frame-pointer
> -fsanitize=address" LDFLAGS="-fsanitize=address" python
> scripts/mk_make.py --debug --noomp --build build_asan
> cd build_asan
> make
> make c_examples
> LD_LIBRARY_PATH=`pwd` ./c_example
> ...
> ASSERTION VIOLATION
> File: ../src/sat/sat_clause.h
> Line: 59
>
> # Now build without ASan
> cd ../
> CXX=clang++ CC=clang python scripts/mk_make.py --debug --noomp --build
> build_noasan
> cd build_noasan
> make
> make c_example
> LD_LIBRARY_PATH=`pwd` ./c_example
>
> # No assertion is hit
> ```
>
> Any insights/suggestions on how I could debug what I'm seeing further
> would be appreciated.
>
> [1] https://github.com/z3prover/z3
> [2] https://github.com/Z3Prover/z3/issues/436
>
> Thanks,
> Dan.
>
>
>
> _______________________________________________
> cfe-dev mailing list
> cfe-dev at lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-dev
>

Hi Kostya & Yury,

Thanks for the advice.

On 9 February 2016 at 22:48, Kostya Serebryany <kcc at google.com>
wrote:
> Hi Dan,
>
> On Tue, Feb 9, 2016 at 10:57 AM, Dan Liew <dan at su-root.co.uk>
wrote:
>>
>> Hi,
>>
>> # TL;DR
>>
>> I've been building an application with and without the address
>> sanitizer (with gcc 5.3 and clang 3.7.1) and I've observed that the
>> application's behaviour changes (assertion hit/ not hit). I'm
>> wondering if this could be a bug in address sanitizer or if the
>> application I'm running is just buggy (e.g. doing bad things like
>> relying on memory layout, etc.). I'm also observing ASan reporting
a
>> heap-use-after-free which Valgrind is not reporting, which makes me
>> wonder if it is a false positive.
>
>
> Let us start from this heap-use-after-free report. The one in
> https://github.com/Z3Prover/z3/issues/436 looks legitimate.
> Unless the application does something extremely weird and tricky,
> heap-use-after-free reports are usually true positives.
The developers tell me they are doing some unusual things and they
believe that this might the cause of the report.
> Can you somehow verify that this heap-use-after-free is happening?
> E.g. print all the pointer values coming from memory::allocate, coming into
> memory::deallocate, and coming into sat::clause::operator[]
>
> If curious, check what size of quarantine is required to catch this bug
> (ASAN_OPTIONS=quarantine_size_mb=N, default=256)
> Valgrind may have smaller default quarantine and thus misses this bug.
I was lazy and just told valgrind to execute the program (built by gcc
without ASan) with the largest quarantine it supported.

```
LD_LIBRARY_PATH=`pwd` valgrind --freelist-vol=10000000000 ./c_example
```

It didn't report any problems. This fills me with some confidence that
when the application is compiled without ASan that it probably doesn't
have a heap-use-after-free.

> Does the application have threads? (If yes, did you run with TSan?)
Not yet but I've stumbled across an issue that looks interesting. See below
> Did you try msan?
I just have and it immediately reported a problem. I took a closer
look and it looks like a false positive to me.

Here are the steps to reproduce

```
git clone https://github.com/Z3Prover/z3.git
cd z3
git checkout 9ed7dadc0251db992b44984edfa6c586aab20ecb
CC=clang CXX=clang++ CXXFLAGS="-fsanitize=memory -fPIE -pie
-fno-omit-frame-pointer -fsanitize-memory-track-origins"
LDFLAGS="-fsanitize=memory" python scripts/mk_make.py --build
build_msan_clang --noomp --debug
cd build_msan_clang
make
make c_example
LD_LIBRARY_PATH=`pwd` ./c_example
==26936==WARNING: MemorySanitizer: use-of-uninitialized-value
    #0 0x7fa7d906f3b0 in Z3_open_log
/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/../src/api/api_log.cpp:33:13
    #1 0x55c0c03107f5 in main
/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/../examples/c/test_capi.c:2794:5
    #2 0x7fa7d78f960f in __libc_start_main (/usr/lib/libc.so.6+0x2060f)
    #3 0x55c0c024d838 in _start
(/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/c_example+0x1c838)

  Uninitialized value was created by a heap allocation
    #0 0x55c0c0253ea0 in __interceptor_malloc
(/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/c_example+0x22ea0)
    #1 0x7fa7e2a6c120 in memory::allocate(unsigned long)
/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/../src/util/memory_manager.cpp:276:16
    #2 0x7fa7d906f125 in Z3_open_log
/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/../src/api/api_log.cpp:31:20
    #3 0x55c0c03107f5 in main
/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/../examples/c/test_capi.c:2794:5
    #4 0x7fa7d78f960f in __libc_start_main (/usr/lib/libc.so.6+0x2060f)

SUMMARY: MemorySanitizer: use-of-uninitialized-value
/home/dsl11/dev/klee/z3/z3_upstream/build_msan_clang/../src/api/api_log.cpp:33:13
in Z3_open_log
Exiting
```

Side note using ``MSAN_OPTIONS="halt_on_error=0`` doesn't seem to do
anything, the application always exits when it hits the reported bug.
I'd like a way to catch this in gdb but I'm not sure how to do it.

I took a look. MSan is complaining about this code

```
std::ostream * g_z3_log = 0;

...

    Z3_bool Z3_API Z3_open_log(Z3_string filename) {
        if (g_z3_log != 0)
            Z3_close_log();
        g_z3_log = alloc(std::ofstream, filename);
        g_z3_log_enabled = true;
        if (g_z3_log->bad() || g_z3_log->fail()) {
            dealloc(g_z3_log);
            g_z3_log = 0;
            return Z3_FALSE;
        }
        return Z3_TRUE;
    }
```

It seems to be complaining that ``g_z3_log`` is uninitialised when
doing ``g_z3_log->bad() || g_z3_log->fail()``. This seems incorrect
because ``alloc()`` appears to be this macro (see
``src/util/memory_manager.h``).

```
#define alloc(T,...) new (memory::allocate(sizeof(T))) T(__VA_ARGS__)
```
With the macro expanded it looks like this

```
g_z3_log = new (memory::allocate(sizeof(std::ofstream)))
std::ofstream(filename);
```

I think this is calling the "placement" version of ``operator new``
and so constructs a new object (in this case ``std::ofstream``)  using
the constructor but uses the memory allocated by
``memory::allocate(sizeof(T))``.

Therefore the memory in the pointer ``g_z3_log`` is initialised and
the "use-of-uninitialized-value" report is a false positive. Would you
agree with this assessment?

Thanks,
Dan.