search

MengRao / fmtlog

fmtlog is a performant fmtlib-style logging library with latency in nanoseconds.
MIT License
807 stars 124 forks source link

it leaks #100

Open Arniiiii opened 2 months ago

Arniiiii commented 2 months ago

It has a memory leak. I'm using updated (no) version of the lib with updated fmtlib. I believe it's fmtlog issue but I don't have time to investigate it After logd or any like macro.

image

Arniiiii commented 2 months ago

tests leak too.

UpdateCTestConfiguration  from :/home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/DartConfiguration.tcl
UpdateCTestConfiguration  from :/home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/DartConfiguration.tcl
Test project /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 1
    Start 1: enc_dec_test

1: Test command: /home/paxu/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test/enc_dec_test_Tests
1: Working Directory: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test
1: Test timeout computed to be: 10000000
1:
1: =================================================================
1: ==221008==ERROR: LeakSanitizer: detected memory leaks
1:
1: Direct leak of 79 byte(s) in 1 object(s) allocated from:
1:     #0 0x563c9483dd51 in operator new[](unsigned long) /var/tmp/portage/sys-libs/compiler-rt-sanitizers-20.0.0_pre20240917/work/compiler-rt/lib/asan/asan_new_delete.cpp:89:3
1:     #1 0x563c948da906 in fmt::v11::basic_string_view<char> fmtlogT<0>::unNameFormat<false, double, fmt::v11::detail::named_arg<char, int>, fmt::v11::detail::named_arg<char, char const (&) [4]>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>(fmt::v11::basic_string_view<char>, unsigned int*, double const&, fmt::v11::detail::named_arg<char, int> const&, fmt::v11::detail::named_arg<char, char const (&) [4]> const&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>> const&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>> const&) /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog.h:620:41
1:     #2 0x563c9484ba78 in void test<char [59], double, fmt::v11::detail::named_arg<char, int>, fmt::v11::detail::named_arg<char, char const (&) [4]>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>>(char const (&) [59], double&&, fmt::v11::detail::named_arg<char, int>&&, fmt::v11::detail::named_arg<char, char const (&) [4]>&&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>&&, fmt::v11::detail::named_arg<char, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>>&&) /home/paxu/code/experiments/fmtlog_cmake_fix/test/src/enc_dec_test.cc:59:25
1:     #3 0x563c94840b22 in main /home/paxu/code/experiments/fmtlog_cmake_fix/test/src/enc_dec_test.cc:96:3
1:     #4 0x7f7d0d82a44f in __libc_start_call_main /usr/src/debug/sys-libs/glibc-2.39-r6/glibc-2.39/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
1:
1: SUMMARY: AddressSanitizer: 79 byte(s) leaked in 1 allocation(s).
1/3 Test #1: enc_dec_test .....................***Failed    0.05 sec
test 2
    Start 2: log_test

2: Test command: /home/paxu/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test/log_test_Tests
2: Working Directory: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test
2: Test timeout computed to be: 10000000
2: 04:11:06.477170 log_test.cc:22   INF[221046] A string, pointer, number, and float: 'Hello World', 0x7ba3db6de020, 512, 3.14159
2: 04:11:06.477686 log_test.cc:27   INF[221046] void ptr: 0x7ba3db6de0b0, ptr: 7, sptr: 8, uptr: 6
2: 04:11:06.477689 log_test.cc:34   INF[221046] str: aaa, pstr: bbb, strarr: 111, pstrarr: 222, cstr: 111, pcstr: 222
2: 04:11:06.477694 log_test.cc:44   DBG[221046] Now debug msg is shown
2: 04:11:06.477798 log_test.cc:49   INF[main  ] log once: 0
2: 04:11:06.477803 log_test.cc:49   INF[main  ] log once: 1
2: 04:11:06.477805 log_test.cc:49   INF[main  ] log once: 2
2: 04:11:06.477807 log_test.cc:53   INF[main  ] Thread name changed
2: 2024-09-21 04:11:06.477856185 log_test.cc:58 INF[main] Header pattern is changed, full date time info is shown
2: 2024-09-21 04:11:06.477862890 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 0.
2: 2024-09-21 04:11:06.477863477 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 1.
2: 2024-09-21 04:11:06.477863571 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 2.
2: 2024-09-21 04:11:06.477863639 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 3.
2: 2024-09-21 04:11:06.477863717 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 4.
2: 2024-09-21 04:11:06.477863785 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 5.
2: 2024-09-21 04:11:06.477863855 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 6.
2: 2024-09-21 04:11:06.477863924 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 7.
2: 2024-09-21 04:11:06.477863987 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 8.
2: 2024-09-21 04:11:06.477864043 log_test.cc:63 INF[main] This msg will be logged at an interval of at least 10 ns: 9.
2:
2: =================================================================
2: ==221046==ERROR: LeakSanitizer: detected memory leaks
2:
2: Direct leak of 1048960 byte(s) in 1 object(s) allocated from:
2:     #0 0x555cbf718056 in operator new(unsigned long, std::align_val_t) /var/tmp/portage/sys-libs/compiler-rt-sanitizers-20.0.0_pre20240917/work/compiler-rt/lib/asan/asan_new_delete.cpp:98:3
2:     #1 0x555cbf71c25d in fmtlogDetailT<0>::preallocate() /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog-inl.h:290:28
2:     #2 0x555cbf71c0b7 in fmtlogT<0>::preallocate() /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog-inl.h:541:31
2:     #3 0x555cbf7248da in fmtlogT<0>::allocMsg(unsigned int, bool) /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog-inl.h:527:32
2:     #4 0x555cbf7257e7 in void fmtlogT<0>::log<char (&) [12], void*, int, double>(unsigned int&, long, char const*, fmtlogT<0>::LogLevel, fmt::v11::basic_format_string<char, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<char (&) [12]>::type>::type>::type>::type, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<void*>::type>::type>::type>::type, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<int>::type>::type>::type>::type, fmt::v11::type_identity<fmtlogdetail::UnrefPtr<std::remove_cv<std::remove_reference<double>::type>::type>::type>::type>, char (&) [12], void*&&, int&&, double&&) /home/paxu/code/experiments/fmtlog_cmake_fix/include/fmtlog/fmtlog.h:685:25
2:     #5 0x555cbf71aaef in main /home/paxu/code/experiments/fmtlog_cmake_fix/test/src/log_test.cc:21:3
2:     #6 0x7fa3dd02a44f in __libc_start_call_main /usr/src/debug/sys-libs/glibc-2.39-r6/glibc-2.39/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
2:
2: SUMMARY: AddressSanitizer: 1048960 byte(s) leaked in 1 allocation(s).
2/3 Test #2: log_test .........................***Failed    0.07 sec
test 3
    Start 3: multithread_test

3: Test command: /home/paxu/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test/multithread_test_Tests
3: Working Directory: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/test
3: Test timeout computed to be: 10000000
3: total msg_cnt: 196570, cb_size: 13715460, throughput: 12.8 MB/second, 184057.2113596684 msg/sec
3/3 Test #3: multithread_test .................   Passed    1.10 sec

33% tests passed, 2 tests failed out of 3

Total Test time (real) =   1.22 sec

The following tests FAILED:
          1 - enc_dec_test (Failed)
          2 - log_test (Failed)
Errors while running CTest
Output from these tests are in: /home/paxu/data/code/experiments/fmtlog_cmake_fix/build/Clang_20.0.0gitfd7d7882_x86_64-pc-linux-gnu/Debug/Testing/Temporary/LastTest.log
Use "--rerun-failed --output-on-failure" to re-run the failed cases verbosely.
Arniiiii commented 2 months ago

it fails with fmtlib 11.0.2 , 10.2.1 and 9.1.0 . It seems to be definitely fmtlog's problem.

Arniiiii commented 2 months ago

It seems that in unNameFormat there's strange problem:

  1. Creating a char* unnamed_str at heap via std::unique_ptr
  2. Using it somehow to calc char* out
  3. Getting raw char* ptr via releasing from unique_ptr
  4. Return string_view(ptr, out - ptr)
  5. Leaked memory between out and end of ptr

So, at least here's two no-no:

  1. Returning std::string_view that expected to have own lifetime (but it's not, since it's std::string_view)
  2. pointer arithmetic

I'll try change the std::string_view to std::string.

Arniiiii commented 2 months ago

Just fucking nice: one place fixed, got one test fixed and other tests leak in some other places. I'm loving it (no)

Arniiiii commented 2 months ago

just... why ... why it's in C's char pointer and not it std::string or any like

Arniiiii commented 2 months ago

Just amazing: solved another leak via converting a lot of dangling fmt::string_view to std::string... And got another one...

Creating thread buffer in heap and then saving pointer in std::vector<type *> ...... clear does not work if the type don't have appropriate destructor...

MengRao commented 2 months ago

Memory management in fmtlog is a little bit tricky, which may trigger false alarm by sanitizers, so don't care too much about it.

Arniiiii commented 2 months ago

Memory management in fmtlog is a little bit tricky, which may trigger false alarm by sanitizers, so don't care too much about it.

IDK , I solved them somehow, but now fmtlog requires fmtlog::poll() in any case. I believe it's because I've done something wrong with 3rd fix: there was a thread that wasn't destructed though it had state "ShouldBeDestroyed == true` or something like that