ASan detecting double-free when using JUnit & console reporters simultaneously

[jorgenpt]

Describe the bug
We recently upgraded to Catch3 to utilize the support for multiple reporters. We run all our tests with ASan on Linux, and this change has caused ASan to detect a double-free inside of MessageInfo::~MessageInfo. Here's the report:

=================================================================
==2304==ERROR: AddressSanitizer: attempting double-free on 0x60d0000a07c0 in thread T0:
    #0 0x520acd in operator delete(void*) (/home/ubuntu/jenkins/workspace/project/Binaries/Linux/TestsDevelopment+0x520acd)
    #1 0x556643 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/basic_string.h:672:9
    #2 0x556643 in Catch::MessageInfo::~MessageInfo() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.hpp:1289:12
    #3 0x556643 in Catch::ScopedMessage::~ScopedMessage() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:776:5
    #4 0x667352 in void std::_Destroy<Catch::ScopedMessage>(Catch::ScopedMessage*) /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_construct.h:151:19
    #5 0x667352 in void std::_Destroy_aux<false>::__destroy<Catch::ScopedMessage*>(Catch::ScopedMessage*, Catch::ScopedMessage*) /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_construct.h:163:6
    #6 0x667352 in void std::_Destroy<Catch::ScopedMessage*>(Catch::ScopedMessage*, Catch::ScopedMessage*) /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_construct.h:195:7
    #7 0x667352 in void std::_Destroy<Catch::ScopedMessage*, Catch::ScopedMessage>(Catch::ScopedMessage*, Catch::ScopedMessage*, std::allocator<Catch::ScopedMessage>&) /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/alloc_traits.h:848:7
    #8 0x667352 in std::vector<Catch::ScopedMessage, std::allocator<Catch::ScopedMessage> >::_M_erase_at_end(Catch::ScopedMessage*) /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_vector.h:1796:6
    #9 0x595824 in Catch::RunContext::assertionEnded(Catch::AssertionResult const&) /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:5252:29
    #10 0x59b46f in Catch::RunContext::reportExpr(Catch::AssertionInfo const&, Catch::ResultWas::OfType, Catch::ITransientExpression const*, bool) /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:5553:9
    #11 0x84d14e in OzyTest::CATCH2_INTERNAL_TEST_30() /home/ubuntu/jenkins/workspace/Server/Test/OzyTest.cpp:1352:3
    #12 0x59ac16 in Catch::RunContext::invokeActiveTestCase() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:5504:27
    #13 0x59465a in Catch::RunContext::runCurrentTest(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&) /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:5459:17
    #14 0x591bc3 in Catch::RunContext::runTest(Catch::TestCaseHandle const&) /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:5198:13
    #15 0x56e65d in Catch::(anonymous namespace)::TestGroup::execute() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:1022:45
    #16 0x56b2dc in Catch::Session::runInternal() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:1244:39
    #17 0x56aa9f in Catch::Session::run() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:1175:24
    #18 0x6bd4a7 in main /home/ubuntu/jenkins/workspace/Server/Test/TestMain.cpp:68:29
    #19 0x7fe3b1e86d8f in __libc_start_call_main csu/../sysdeps/nptl/libc_start_call_main.h:58:16
    #20 0x7fe3b1e86e3f in __libc_start_main csu/../csu/libc-start.c:392:3
    #21 0x4715c4 in _start (/home/ubuntu/jenkins/workspace/project/Binaries/Linux/TestsDevelopment+0x4715c4)

0x60d0000a07c0 is located 0 bytes inside of 135-byte region [0x60d0000a07c0,0x60d0000a0847)
freed by thread T0 here:
    #0 0x520acd in operator delete(void*) (/home/ubuntu/jenkins/workspace/project/Binaries/Linux/TestsDevelopment+0x520acd)
    #1 0x556643 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() /usr/bin/../lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/basic_string.h:672:9
    #2 0x556643 in Catch::MessageInfo::~MessageInfo() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.hpp:1289:12
    #3 0x556643 in Catch::ScopedMessage::~ScopedMessage() /home/ubuntu/jenkins/workspace/Server/Test/catch_amalgamated.cpp:776:5

previously allocated by thread T0 here:
    #0 0x52026d in operator new(unsigned long) (/home/ubuntu/jenkins/workspace/project/Binaries/Linux/TestsDevelopment+0x52026d)
    #1 0x7fe3b22d7f3d in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_mutate(unsigned long, unsigned long, char const*, unsigned long) (/lib/x86_64-linux-gnu/libstdc++.so.6+0x14bf3d)

SUMMARY: AddressSanitizer: double-free (/home/ubuntu/jenkins/workspace/project/Binaries/Linux/TestsDevelopment+0x520acd) in operator delete(void*)

Reproduction steps

We don't see the issue when running with -g -s -d yes --wait-for-keypress never -r junit -o test_report_main.xml, but we do see it when running with --reporter console::out=- -g -s -d yes --wait-for-keypress never --reporter JUnit::out=test_report_main.xml

We build with -O2 -fsanitize=undefined,address -fno-sanitize=enum -std=c++17 -DCATCH_CONFIG_ENABLE_BENCHMARKING=1 and we link with -fsanitize=undefined,address -fno-sanitize=enum

Platform information:

• OS: Ubuntu 22.04
• Compiler+version: Clang 13.0.1-2ubuntu2.1
• Catch version: v3.3.1

[horenmar]

I don't see how this is possible.

• MessageInfo is not a reference type, nor does it have custom destructor/move/copy ops, so it is all deferred to the std::string member. So for it to cause a double free, it has to be manually destructed twice, or std::string has to contain an interesting bug.
• The MessageInfo instance's destructor was triggered by a ScopedMessage's destructor. But that doesn't destruct the instance manually either. It defers to the usual erase-remove idiom, using the stdlib impls. Even destroying multiple instances of ScopedMessage shouldn't cause the same underlying MessageInfo to be destroyed multiple times, as all identical instances were destroyed previously.
• An alternate path to the double free would be the member MessageInfo in ScopedMessage being destructed multiple times. This would require ScopedMessage's destructor to be invoked multiple times, but the stack trace points to it being destroyed inside vector's destructor, so..

Basically you should try to compile the code with lesser optimization level to decrease the chance of miscompile and to get a more detailed stack trace.

[jorgenpt]

@horenmar I tracked this down to us calling UNSCOPED_INFO from a background thread. https://github.com/catchorg/Catch2/blob/devel/docs/limitations.md#thread-safe-assertions talks about assertions, but I'm assuming the same (lack of) thread safety guarantees apply to attaching info.

Seems like a way to solve this is:

• Have our background logging thread-safely push messages to a queue
• Add a custom reporter type
• Implement assertionStarting and have it thread-safely drain the queue and push it into UNSCOPED_INFO

That way we'll get the data associated with the foreground actions in a thread safely way.

[horenmar]

re MT: Yeah, just don't touch Catch2 from multiple threads.

re logging: if you are serializing logs into UNSCOPED_INFOs so that the standard reporters report it, prefer Event Listener to reporter. They are guaranteed to run before reporters, and are a bit simpler (because they do not have to handle output streams, are always active in the binary and so on).

[jorgenpt]

@horenmar Oh, thank you for the pointer! I will absolutely look into the event listeners.