heap-use-after-free with BatchLogRecordProcessor

[sjinks]

Describe your environment
OpenTelemetry v1.17.0

Steps to reproduce
Sample code: https://github.com/sjinks/otel-heap-use-after-free
Sample run: https://github.com/sjinks/otel-heap-use-after-free/actions/runs/11758831588/job/32757617053

What is the expected behavior?
There should be no errors.

What is the actual behavior?
The application crashed because of the heap-use-after-free-error

=5853==ERROR: AddressSanitizer: heap-use-after-free on address 0x6030000005c8 at pc 0x55707b183c86 bp 0x7f82e12fe770 sp 0x7f82e12fdf38
READ of size 6 at 0x6030000005c8 thread T1
    #0 0x55707b183c85 in __interceptor_strlen (/home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/build/bug-repro+0x46c85) (BuildId: 3dbd37ecfe9134972fe6a448909a1b651fdd1e62)
    #1 0x7f82e3b3ceac in std::basic_ostream<char, std::char_traits<char> >& std::operator<<<std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*) (/lib/x86_64-linux-gnu/libstdc++.so.6+0x13ceac) (BuildId: e37fe1a879783838de78cbc8c80621fa685d58a2)
    #2 0x55707b247a33 in void opentelemetry::v1::exporter::ostream_common::print_value<char const*>(char const* const&, std::ostream&) /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/exporters/ostream/include/opentelemetry/exporters/ostream/common_utils.h:25:8
    #3 0x55707b2435cb in auto opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&, std::ostream&)::'lambda'(auto&&)::operator()<char const* const&>(auto&&) const /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.
    #4 0x55707b24ab4d in auto std::__invoke_impl<void, opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&, std::ostream&)::'lambda'(auto&&), char const* const&>(std::__invoke_other, opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, doub
    #5 0x55707b248277 in std::__invoke_result<auto, char const* const&>::type std::__invoke<opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&, std::ostream&)::'lambda'(auto&&), char const* const&>(auto&&, char const* const&) /usr/include/c++/11/bits/invoke.h:96:40
    #6 0x55707b243a33 in std::__detail::__variant::__gen_vtable_impl<std::__detail::__variant::_Multi_array<std::__detail::__variant::__deduce_visit_result<void> (*)(opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&, std::ostream&)::'lambda'(auto&&)&&, std::variant<bool, int, long, uns
    #7 0x55707b243f3a in decltype(auto) std::__do_visit<std::__detail::__variant::__deduce_visit_result<void>, opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&, std::ostream&)::'lambda'(auto&&), std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd:
    #8 0x55707b243fa1 in std::invoke_result<auto, std::conditional<is_lvalue_reference_v<std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&>, std::variant_alternative<0ul, std::remove_reference<decltype(__as(declval<std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd
    #9 0x55707b23f9a8 in opentelemetry::v1::exporter::ostream_common::print_value(std::variant<bool, int, long, unsigned int, double, char const*, opentelemetry::v1::nostd::string_view, opentelemetry::v1::nostd::span<bool const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned int const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<double const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<opentelemetry::v1::nostd::string_view const, 18446744073709551615ul>, unsigned long, opentelemetry::v1::nostd::span<unsigned long const, 18446744073709551615ul>, opentelemetry::v1::nostd::span<unsigned char const, 18446744073709551615ul> > const&, std::ostream&) /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/exporters/ostream/include/opentelemetry/exporters/ostream/commo
    #10 0x55707b23e5a4 in opentelemetry::v1::exporter::logs::OStreamLogRecordExporter::Export(opentelemetry::v1::nostd::span<std::unique_ptr<opentelemetry::v1::sdk::logs::Recordable, std::default_delete<opentelemetry::v1::sdk::logs::Recordable> >, 18446744073709551615ul> const&) /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/exporters/ostream/src/log_record_exporter.cc:111:57
    #11 0x55707b276fe7 in opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::Export() /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/sdk/src/logs/batch_log_record_processor.cc:223:22
    #12 0x55707b276cc6 in opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::DoBackgroundWork() /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/sdk/src/logs/batch_log_record_processor.cc:178:11
    #13 0x55707b27c429 in void std::__invoke_impl<void, void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*>(std::__invoke_memfun_deref, void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*&&)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*&&) /usr/include/c++/11/bits/invoke.h:74:46
    #14 0x55707b27c37c in std::__invoke_result<void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*>::type std::__invoke<void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*>(void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*&&)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*&&) /usr/include/c++/11/bits/invoke.h:96:40
    #15 0x55707b27c2dc in void std::thread::_Invoker<std::tuple<void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*> >::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) /usr/include/c++/11/bits/std_thread.h:259:26
    #16 0x55707b27c22b in std::thread::_Invoker<std::tuple<void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*> >::operator()() /usr/include/c++/11/bits/std_thread.h:266:20
    #17 0x55707b27c1c3 in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::*)(), opentelemetry::v1::sdk::logs::BatchLogRecordProcessor*> > >::_M_run() /usr/include/c++/11/bits/std_thread.h:211:20
    #18 0x7f82e3adc252  (/lib/x86_64-linux-gnu/libstdc++.so.6+0xdc252) (BuildId: e37fe1a879783838de78cbc8c80621fa685d58a2)
    #19 0x7f82e3694ac2  (/lib/x86_64-linux-gnu/libc.so.6+0x94ac2) (BuildId: 490fef8403240c91833978d494d39e537409b92e)
    #20 0x7f82e372684f  (/lib/x86_64-linux-gnu/libc.so.6+0x12684f) (BuildId: 490fef8403240c91833978d494d39e537409b92e)
0x6030000005c8 is located 24 bytes inside of 30-byte region [0x6030000005b0,0x6030000005ce)
freed by thread T0 here:
    #0 0x55707b22bfbd in operator delete(void*) (/home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/build/bug-repro+0xeefbd) (BuildId: 3dbd37ecfe9134972fe6a448909a1b651fdd1e62)
    #1 0x7f82e3ac46f2 in std::runtime_error::~runtime_error() (/lib/x86_64-linux-gnu/libstdc++.so.6+0xc46f2) (BuildId: e37fe1a879783838de78cbc8c80621fa685d58a2)
    #2 0x7f82e3629d8f  (/lib/x86_64-linux-gnu/libc.so.6+0x29d8f) (BuildId: 490fef8403240c91833978d494d39e537409b92e)
previously allocated by thread T0 here:
    #0 0x55707b22b75d in operator new(unsigned long) (/home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/build/bug-repro+0xee75d) (BuildId: 3dbd37ecfe9134972fe6a448909a1b651fdd1e62)
    #1 0x7f82e3af4978 in std::string::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&) (/lib/x86_64-linux-gnu/libstdc++.so.6+0xf4978) (BuildId: e37fe1a879783838de78cbc8c80621fa685d58a2)
Thread T1 created by T0 here:
    #0 0x55707b1d9e0c in __interceptor_pthread_create (/home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/build/bug-repro+0x9ce0c) (BuildId: 3dbd37ecfe9134972fe6a448909a1b651fdd1e62)
    #1 0x7f82e3adc328 in std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)()) (/lib/x86_64-linux-gnu/libstdc++.so.6+0xdc328) (BuildId: e37fe1a879783838de78cbc8c80621fa685d58a2)
    #2 0x55707b2764d0 in opentelemetry::v1::sdk::logs::BatchLogRecordProcessor::BatchLogRecordProcessor(std::unique_ptr<opentelemetry::v1::sdk::logs::LogRecordExporter, std::default_delete<opentelemetry::v1::sdk::logs::LogRecordExporter> >&&, opentelemetry::v1::sdk::logs::BatchLogRecordProcessorOptions const&) /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/sdk/src/logs/batch_log_record_processor.cc:58:7
    #3 0x55707b26c501 in opentelemetry::v1::sdk::logs::BatchLogRecordProcessorFactory::Create(std::unique_ptr<opentelemetry::v1::sdk::logs::LogRecordExporter, std::default_delete<opentelemetry::v1::sdk::logs::LogRecordExporter> >&&, opentelemetry::v1::sdk::logs::BatchLogRecordProcessorOptions const&) /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/vcpkg/buildtrees/opentelemetry-cpp/src/v1.17.0-b9ea5cab17.clean/sdk/src/logs/batch_log_record_processor_factory.cc:25:63
    #4 0x55707b22e18b in main /home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/repro.cpp:19:22
    #5 0x7f82e3629d8f  (/lib/x86_64-linux-gnu/libc.so.6+0x29d8f) (BuildId: 490fef8403240c91833978d494d39e537409b92e)
SUMMARY: AddressSanitizer: heap-use-after-free (/home/runner/work/otel-heap-use-after-free/otel-heap-use-after-free/build/bug-repro+0x46c85) (BuildId: 3dbd37ecfe9134972fe6a448909a1b651fdd1e62) in __interceptor_strlen
Shadow bytes around the buggy address:
  0x0c067fff8060: fa fa fd fd fd fa fa fa fd fd fd fa fa fa fd fd
  0x0c067fff8070: fd fa fa fa fd fd fd fa fa fa fd fd fd fa fa fa
  0x0c067fff8080: fd fd fd fa fa fa 00 00 06 fa fa fa 00 00 03 fa
  0x0c067fff8090: fa fa 00 00 07 fa fa fa 00 00 00 00 fa fa 00 00
  0x0c067fff80a0: 00 fa fa fa 00 00 00 fa fa fa fd fd fd fa fa fa
=>0x0c067fff80b0: fd fd fd fa fa fa fd fd fd[fd]fa fa 00 00 00 fa
  0x0c067fff80c0: fa fa fd fd fd fa fa fa fd fd fd fa fa fa fd fd
  0x0c067fff80d0: fd fd fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c067fff80e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c067fff80f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c067fff8100: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==5853==ABORTING

Additional context

    opentelemetry::sdk::logs::BatchLogRecordProcessorOptions options{2048, std::chrono::milliseconds(5000), 512};
    auto processor = opentelemetry::sdk::logs::BatchLogRecordProcessorFactory::Create(std::move(exporter), options);

//...

    try {
        throw std::runtime_error("error");
    }
    catch (const std::exception &e) {
        auto logger = opentelemetry::logs::Provider::GetLoggerProvider()->GetLogger("example");
        logger->Error(e.what());
    }

The bug happens when the catch block is left before the BatchLogRecordProcessor processes the data.

My understanding is that the log message is stored ReadWriteLogRecord::body_ which is opentelemetry::common::AttributeValue, a nostd::variant holding a const char* value. When e goes out of the scope and gets destructed, the memory pointed to by e.what() is also freed. However, because AttributeValue does not own the data, it is left with a dangling pointer.

The fix will probably be to replace AttributeValue with OwnedAttributeValue (this will affect body_ and attributes_map_).

Refs:

• https://github.com/open-telemetry/opentelemetry-cpp/blob/v1.17.0/sdk/include/opentelemetry/sdk/logs/read_write_log_record.h#L191
• https://github.com/open-telemetry/opentelemetry-cpp/blob/v1.17.0/sdk/include/opentelemetry/sdk/logs/read_write_log_record.h#L190

[ThomsonTan]

Looks the same issue as #2651.

The ostream exporter is for testing purpose and is not meant to be used with BatchLogExporter. It uses ReadWriteRecordable which doesn't make a copy the parameter in type char *.

[sjinks]

Confirmed, it works fine with OtlpHttpLogRecordExporter.

[marcalff]

Thanks for the confirmation.

I forgot to say, impressive steps to reproduce, with a dedicated git repository and all.

Feel free to close this report, we will keep #2651 opened to fix the ostream exporter.