From 31e4a02ff22c5eced2eeed8476978ccfdffd354a Mon Sep 17 00:00:00 2001 From: Thomas Moulard Date: Fri, 19 Apr 2019 02:11:11 -0700 Subject: [PATCH] Fix leak in test_logging_macros.cpp (#152) Call rcutils_logging_shutdown() in TearDown to avoid leaking logging internal objects. As any change to this file makes test_logging_named fail, this releaxes the EXACT_EQ call on g_last_log_event.location->line_number[1]. Instead of looking for a particular value, we test an invariant of the field (line numbers are positive). Finally, in test_logging_function, initialize g_counter and g_function_called values to make sure the test will not fail even if `--gtest_repeat=2` is passed. Other tests are still failing when this flag is passed: [ FAILED ] TestLoggingMacros.test_logging_once [ FAILED ] TestLoggingMacros.test_logging_skipfirst [ FAILED ] TestLoggingMacros.test_logging_skipfirst_throttle However, fixing those tests would require actually changing the logging implementation which is out of the scope of this change. Before: $ ./test_logging_macros Running main() from gmock_main.cc [==========] Running 8 tests from 1 test case. [----------] Global test environment set-up. [----------] 8 tests from TestLoggingMacros [ RUN ] TestLoggingMacros.test_logging_named [ OK ] TestLoggingMacros.test_logging_named (0 ms) [ RUN ] TestLoggingMacros.test_logging_once [ OK ] TestLoggingMacros.test_logging_once (0 ms) [ RUN ] TestLoggingMacros.test_logging_expression [ OK ] TestLoggingMacros.test_logging_expression (0 ms) [ RUN ] TestLoggingMacros.test_logging_function [ OK ] TestLoggingMacros.test_logging_function (0 ms) [ RUN ] TestLoggingMacros.test_logging_skipfirst [ OK ] TestLoggingMacros.test_logging_skipfirst (0 ms) [ RUN ] TestLoggingMacros.test_logging_throttle [ OK ] TestLoggingMacros.test_logging_throttle (302 ms) [ RUN ] TestLoggingMacros.test_logging_skipfirst_throttle [ OK ] TestLoggingMacros.test_logging_skipfirst_throttle (302 ms) [ RUN ] TestLoggingMacros.test_logger_hierarchy [ OK ] TestLoggingMacros.test_logger_hierarchy (0 ms) [----------] 8 tests from TestLoggingMacros (605 ms total) [----------] Global test environment tear-down [==========] 8 tests from 1 test case ran. (605 ms total) [ PASSED ] 8 tests. ================================================================= ==19903==ERROR: LeakSanitizer: detected memory leaks Direct leak of 504 byte(s) in 7 object(s) allocated from: #0 0x7fd640c1fb50 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xdeb50) #1 0x7fd64091cbb5 in __default_allocate (/home/.../ros2_ws/install-asan/rcutils/lib/librcutils.so+0x8bb5) #2 0x7fd64092f1b0 in rcutils_string_map_init (/home/.../ros2_ws/install-asan/rcutils/lib/librcutils.so+0x1b1b0) #3 0x7fd640926641 in rcutils_logging_initialize_with_allocator (/home/.../ros2_ws/install-asan/rcutils/lib/librcutils.so+0x12641) #4 0x7fd6409261ab in rcutils_logging_initialize (/home/.../ros2_ws/install-asan/rcutils/lib/librcutils.so+0x121ab) #5 0x564405fc6627 in TestLoggingMacros::SetUp() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x29627) #6 0x564406045999 in void testing::internal::HandleSehExceptionsInMethodIfSupported(testing::Test*, void (testing::Test::*)(), char const*) (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0xa8999) #7 0x564406037b7d in void testing::internal::HandleExceptionsInMethodIfSupported(testing::Test*, void (testing::Test::*)(), char const*) (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x9ab7d) #8 0x564405fe4503 in testing::Test::Run() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x47503) #9 0x564405fe59e4 in testing::TestInfo::Run() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x489e4) #10 0x564405fe6588 in testing::TestCase::Run() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x49588) #11 0x564406001699 in testing::internal::UnitTestImpl::RunAllTests() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x64699) #12 0x56440604844c in bool testing::internal::HandleSehExceptionsInMethodIfSupported(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0xab44c) #13 0x564406039e46 in bool testing::internal::HandleExceptionsInMethodIfSupported(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x9ce46) #14 0x564405ffe42d in testing::UnitTest::Run() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x6142d) #15 0x564405fd197d in RUN_ALL_TESTS() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x3497d) #16 0x564405fd18c3 in main (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x348c3) #17 0x7fd63fd84b96 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21b96) After: $ ./test_logging_macros Running main() from gmock_main.cc [==========] Running 9 tests from 1 test case. [----------] Global test environment set-up. [----------] 9 tests from TestLoggingMacros [ RUN ] TestLoggingMacros.test_empty [ OK ] TestLoggingMacros.test_empty (0 ms) [ RUN ] TestLoggingMacros.test_logging_named [ OK ] TestLoggingMacros.test_logging_named (0 ms) [ RUN ] TestLoggingMacros.test_logging_once [ OK ] TestLoggingMacros.test_logging_once (0 ms) [ RUN ] TestLoggingMacros.test_logging_expression [ OK ] TestLoggingMacros.test_logging_expression (0 ms) [ RUN ] TestLoggingMacros.test_logging_function [ OK ] TestLoggingMacros.test_logging_function (0 ms) [ RUN ] TestLoggingMacros.test_logging_skipfirst [ OK ] TestLoggingMacros.test_logging_skipfirst (0 ms) [ RUN ] TestLoggingMacros.test_logging_throttle [ OK ] TestLoggingMacros.test_logging_throttle (303 ms) [ RUN ] TestLoggingMacros.test_logging_skipfirst_throttle [ OK ] TestLoggingMacros.test_logging_skipfirst_throttle (302 ms) [ RUN ] TestLoggingMacros.test_logger_hierarchy [ OK ] TestLoggingMacros.test_logger_hierarchy (0 ms) [----------] 9 tests from TestLoggingMacros (605 ms total) [----------] Global test environment tear-down [==========] 9 tests from 1 test case ran. (606 ms total) [ PASSED ] 9 tests. [1] https://testing.googleblog.com/2015/01/testing-on-toilet-change-detector-tests.html Signed-off-by: Thomas Moulard --- test/test_logging_macros.cpp | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/test/test_logging_macros.cpp b/test/test_logging_macros.cpp index 7332c4e04..cfed6fd30 100644 --- a/test/test_logging_macros.cpp +++ b/test/test_logging_macros.cpp @@ -39,7 +39,6 @@ LogEvent g_last_log_event; class TestLoggingMacros : public ::testing::Test { public: - rcutils_logging_output_handler_t previous_output_handler; void SetUp() { g_log_calls = 0; @@ -63,16 +62,12 @@ class TestLoggingMacros : public ::testing::Test vsnprintf(buffer, sizeof(buffer), format, *args); g_last_log_event.message = buffer; }; - - this->previous_output_handler = rcutils_logging_get_output_handler(); rcutils_logging_set_output_handler(rcutils_logging_console_output_handler); } void TearDown() { - rcutils_logging_set_output_handler(this->previous_output_handler); - g_rcutils_logging_initialized = false; - EXPECT_FALSE(g_rcutils_logging_initialized); + EXPECT_EQ(RCUTILS_RET_OK, rcutils_logging_shutdown()); } }; @@ -85,7 +80,7 @@ TEST_F(TestLoggingMacros, test_logging_named) { if (g_last_log_event.location) { EXPECT_STREQ("TestBody", g_last_log_event.location->function_name); EXPECT_THAT(g_last_log_event.location->file_name, EndsWith("test_logging_macros.cpp")); - EXPECT_EQ(81u, g_last_log_event.location->line_number); + EXPECT_GT(g_last_log_event.location->line_number, 1u); } EXPECT_EQ(RCUTILS_LOG_SEVERITY_DEBUG, g_last_log_event.level); EXPECT_EQ("name", g_last_log_event.name); @@ -120,6 +115,9 @@ bool not_divisible_by_three() } TEST_F(TestLoggingMacros, test_logging_function) { + g_counter = 0; + g_function_called = false; + // check that evaluation of a specified function does not occur if the severity is not enabled g_rcutils_logging_default_logger_level = RCUTILS_LOG_SEVERITY_INFO; for (int i : {0, 1}) { // cover both true and false return values