logd: gtest: logd.timeout socket does not clean up properly

Until the socket ages out, it sticks around and gets reused in
subsequent tests affecting the outcome of those tests.  We opt
to run logd.timeout in a forked and isolated process to keep
these conditions from interfering.

Adjusted benchmark execute to only run the tests we are
interested in to improve the time it takes to run.

Commented some areas of code to make them easier to maintain.

Test: gTest logd-unit-tests success
Bug: 33962045
Change-Id: Ic1b98bc4a2d7e8927f1a87628e3bcc368c9cf8ce

1 files changed, 41 insertions, 10 deletions

diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index 4e621e382..5cd9fc8f2 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -415,7 +415,13 @@ TEST(logd, benchmark) {
 
     // Introduce some extreme spam for the worst UID filter
     ASSERT_TRUE(NULL != (fp = popen(
-        "/data/nativetest/liblog-benchmarks/liblog-benchmarks",
+        "/data/nativetest/liblog-benchmarks/liblog-benchmarks"
+            " BM_log_maximum_retry"
+            " BM_log_maximum"
+            " BM_clock_overhead"
+            " BM_log_overhead"
+            " BM_log_latency"
+            " BM_log_delay",
         "r")));
 
     char buffer[5120];
@@ -581,10 +587,12 @@ void timeout_negative(const char *command) {
             continue;
         }
 
+        // alarm triggers at 50% of the --wrap time out
         content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
 
         alarm_wrap = alarm(5);
 
+        // alarm triggers at 133% of the --wrap time out
         content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
         if (!content_timeout) { // make sure we hit dumpAndClose
             content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
@@ -629,11 +637,24 @@ TEST(logd, timeout_start_epoch) {
 
 // b/26447386 refined behavior
 TEST(logd, timeout) {
+    // b/33962045 This test interferes with other log reader tests that
+    // follow because of file descriptor socket persistence in the same
+    // process.  So let's fork it to isolate it from giving us pain.
+
+    pid_t pid = fork();
+
+    if (pid) {
+        siginfo_t info = {};
+        ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
+        ASSERT_EQ(0, info.si_status);
+        return;
+    }
+
     log_msg msg_wrap, msg_timeout;
     bool content_wrap = false, content_timeout = false, written = false;
     unsigned int alarm_wrap = 0, alarm_timeout = 0;
     // A few tries to get it right just in case wrap kicks in due to
-    // content providers being active during the test
+    // content providers being active during the test.
     int i = 5;
     log_time now(android_log_clockid());
     now.tv_sec -= 30; // reach back a moderate period of time
@@ -642,7 +663,8 @@ TEST(logd, timeout) {
         int fd = socket_local_client("logdr",
                                      ANDROID_SOCKET_NAMESPACE_RESERVED,
                                      SOCK_SEQPACKET);
-        ASSERT_LT(0, fd);
+        EXPECT_LT(0, fd);
+        if (fd < 0) _exit(fd);
 
         std::string ask = android::base::StringPrintf(
             "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%"
@@ -665,10 +687,12 @@ TEST(logd, timeout) {
             continue;
         }
 
+        // alarm triggers at 50% of the --wrap time out
         content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
 
         alarm_wrap = alarm(5);
 
+        // alarm triggers at 133% of the --wrap time out
         content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
         if (!content_timeout) { // make sure we hit dumpAndClose
             content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
@@ -692,6 +716,7 @@ TEST(logd, timeout) {
         if (content_timeout) {
             log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
             EXPECT_FALSE(msg < now);
+            if (msg < now) _exit(-1);
             if (msg > now) {
                 now = msg;
                 now.tv_sec += 30;
@@ -724,6 +749,8 @@ TEST(logd, timeout) {
     EXPECT_EQ(0U, alarm_wrap);
     EXPECT_TRUE(content_timeout);
     EXPECT_NE(0U, alarm_timeout);
+
+    _exit(!written + content_wrap + alarm_wrap + !content_timeout + !alarm_timeout);
 }
 
 // b/27242723 confirmed fixed
@@ -787,12 +814,11 @@ static inline int32_t get4LE(const char* src)
 void __android_log_btwrite_multiple__helper(int count) {
     log_time ts(CLOCK_MONOTONIC);
 
-    struct logger_list *logger_list;
-    ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
-        LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, 0)));
-
     log_time ts1(CLOCK_MONOTONIC);
 
+    // We fork to create a unique pid for the submitted log messages
+    // so that we do not collide with the other _multiple_ tests.
+
     pid_t pid = fork();
 
     if (pid == 0) {
@@ -807,8 +833,13 @@ void __android_log_btwrite_multiple__helper(int count) {
         _exit(0);
     }
 
-    siginfo_t info{};
+    siginfo_t info = {};
     ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
+    ASSERT_EQ(0, info.si_status);
+
+    struct logger_list *logger_list;
+    ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
+        LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, pid)));
 
     int expected_count = (count < 2) ? count : 2;
     int expected_chatty_count = (count <= 2) ? 0 : 1;
@@ -854,12 +885,12 @@ void __android_log_btwrite_multiple__helper(int count) {
         }
     }
 
+    android_logger_list_close(logger_list);
+
     EXPECT_EQ(expected_count, count);
     EXPECT_EQ(1, second_count);
     EXPECT_EQ(expected_chatty_count, chatty_count);
     EXPECT_EQ(expected_expire_count, expire_count);
-
-    android_logger_list_close(logger_list);
 }
 
 TEST(logd, multiple_test_1) {