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
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index 4e621e3..5cd9fc8 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -415,7 +415,13 @@
// 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 @@
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 @@
// 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
_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 @@
}
}
+ 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) {