Skip to content

Commit

Permalink
Fix leak in test_logging_macros.cpp (ros2#152)
Browse files Browse the repository at this point in the history 
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*, 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*, 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)
        ros2#10 0x564405fe6588 in testing::TestCase::Run() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x49588)
        ros2#11 0x564406001699 in testing::internal::UnitTestImpl::RunAllTests() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x64699)
        ros2#12 0x56440604844c in bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0xab44c)
        ros2#13 0x564406039e46 in bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x9ce46)
        ros2#14 0x564405ffe42d in testing::UnitTest::Run() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x6142d)
        ros2#15 0x564405fd197d in RUN_ALL_TESTS() (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x3497d)
        ros2#16 0x564405fd18c3 in main (/home/.../ros2_ws/build-asan/rcutils/test_logging_macros+0x348c3)
        ros2#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 <tmoulard@amazon.com>
  • Loading branch information
@thomas-moulard @wjwwood
thomas-moulard authored and wjwwood committed Apr 19, 2019
1 parent de45471 commit 31e4a02
Showing 1 changed file with 5 additions and 7 deletions.
12 changes: 5 additions & 7 deletions test/test_logging_macros.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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());
}
};

Expand All @@ -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);
Expand Down Expand Up @@ -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
Expand Down

0 comments on commit 31e4a02

Please sign in to comment.