From 50af7f8b1d28d6efd1e61fa7aadaf963c7a2e3ff Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 10 Mar 2016 15:25:14 -0800 Subject: [PATCH 1/2] liblog: test: do not LOG in signal handler - We actually are logging in a signal handler, the title is bluster to remind developers. It is not a reliable path though as it can lock up. Our goal is to minimize the chances of a lockup regardless in the name of stability only. The test remains to catch regression in the name of code quality and reliability. Expected to be >99.999% reliable. - Add a new _correct_ duplicate test that uses signal to release a semaphore to a thread that performs the task. This path is expected to be 100% reliable. Bug: 27405083 Change-Id: Ibb7cf4b13e34ebfac2db2af8724b7db7a27f81a8 --- liblog/tests/liblog_test.cpp | 168 +++++++++++++++++++++++++++++++++-- 1 file changed, 163 insertions(+), 5 deletions(-) diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index 50ecd2dff..3b4d851aa 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -16,6 +16,7 @@ #include #include +#include #include #include #include @@ -531,9 +532,15 @@ TEST(liblog, __security_buffer) { } static unsigned signaled; -log_time signal_time; +static log_time signal_time; -static void caught_blocking(int /*signum*/) +/* + * Strictly, we are not allowed to log messages in a signal context, but we + * do make an effort to keep the failure surface minimized, and this in-effect + * should catch any regressions in that effort. The odds of a logged message + * in a signal handler causing a lockup problem should be _very_ small. + */ +static void caught_blocking_signal(int /*signum*/) { unsigned long long v = 0xDEADBEEFA55A0000ULL; @@ -583,7 +590,7 @@ static void get_ticks(unsigned long long *uticks, unsigned long long *sticks) } } -TEST(liblog, android_logger_list_read__cpu) { +TEST(liblog, android_logger_list_read__cpu_signal) { struct logger_list *logger_list; unsigned long long v = 0xDEADBEEFA55A0000ULL; @@ -606,7 +613,7 @@ TEST(liblog, android_logger_list_read__cpu) { memset(&signal_time, 0, sizeof(signal_time)); - signal(SIGALRM, caught_blocking); + signal(SIGALRM, caught_blocking_signal); alarm(alarm_time); signaled = 0; @@ -651,7 +658,158 @@ TEST(liblog, android_logger_list_read__cpu) { alarm(0); signal(SIGALRM, SIG_DFL); - EXPECT_LT(1, count); + EXPECT_LE(1, count); + + EXPECT_EQ(1, signals); + + android_logger_list_close(logger_list); + + unsigned long long uticks_end; + unsigned long long sticks_end; + get_ticks(&uticks_end, &sticks_end); + + // Less than 1% in either user or system time, or both + const unsigned long long one_percent_ticks = alarm_time; + unsigned long long user_ticks = uticks_end - uticks_start; + unsigned long long system_ticks = sticks_end - sticks_start; + EXPECT_GT(one_percent_ticks, user_ticks); + EXPECT_GT(one_percent_ticks, system_ticks); + EXPECT_GT(one_percent_ticks, user_ticks + system_ticks); +} + +/* + * Strictly, we are not allowed to log messages in a signal context, the + * correct way to handle this is to ensure the messages are constructed in + * a thread; the signal handler should only unblock the thread. + */ +static sem_t thread_trigger; + +static void caught_blocking_thread(int /*signum*/) +{ + sem_post(&thread_trigger); +} + +static void *running_thread(void *) { + unsigned long long v = 0xDEADBEAFA55A0000ULL; + + v += getpid() & 0xFFFF; + + struct timespec timeout; + clock_gettime(CLOCK_REALTIME, &timeout); + timeout.tv_sec += 55; + sem_timedwait(&thread_trigger, &timeout); + + ++signaled; + if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) { + signal_time = log_time(CLOCK_MONOTONIC); + signal_time.tv_sec += 2; + } + + LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); + + return NULL; +} + +int start_thread() +{ + sem_init(&thread_trigger, 0, 0); + + pthread_attr_t attr; + if (pthread_attr_init(&attr)) { + return -1; + } + + struct sched_param param; + + memset(¶m, 0, sizeof(param)); + pthread_attr_setschedparam(&attr, ¶m); + pthread_attr_setschedpolicy(&attr, SCHED_BATCH); + + if (pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED)) { + pthread_attr_destroy(&attr); + return -1; + } + + pthread_t thread; + if (pthread_create(&thread, &attr, running_thread, NULL)) { + pthread_attr_destroy(&attr); + return -1; + } + + pthread_attr_destroy(&attr); + return 0; +} + +TEST(liblog, android_logger_list_read__cpu_thread) { + struct logger_list *logger_list; + unsigned long long v = 0xDEADBEAFA55A0000ULL; + + pid_t pid = getpid(); + + v += pid & 0xFFFF; + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 1000, pid))); + + int count = 0; + + int signals = 0; + + unsigned long long uticks_start; + unsigned long long sticks_start; + get_ticks(&uticks_start, &sticks_start); + + const unsigned alarm_time = 10; + + memset(&signal_time, 0, sizeof(signal_time)); + + signaled = 0; + EXPECT_EQ(0, start_thread()); + + signal(SIGALRM, caught_blocking_thread); + alarm(alarm_time); + + do { + log_msg log_msg; + if (LOG_FAILURE_RETRY(android_logger_list_read(logger_list, &log_msg)) <= 0) { + break; + } + + alarm(alarm_time); + + ++count; + + ASSERT_EQ(log_msg.entry.pid, pid); + + if ((log_msg.entry.len != (4 + 1 + 8)) + || (log_msg.id() != LOG_ID_EVENTS)) { + continue; + } + + char *eventData = log_msg.msg(); + + if (eventData[4] != EVENT_TYPE_LONG) { + continue; + } + + unsigned long long l = eventData[4 + 1 + 0] & 0xFF; + l |= (unsigned long long) (eventData[4 + 1 + 1] & 0xFF) << 8; + l |= (unsigned long long) (eventData[4 + 1 + 2] & 0xFF) << 16; + l |= (unsigned long long) (eventData[4 + 1 + 3] & 0xFF) << 24; + l |= (unsigned long long) (eventData[4 + 1 + 4] & 0xFF) << 32; + l |= (unsigned long long) (eventData[4 + 1 + 5] & 0xFF) << 40; + l |= (unsigned long long) (eventData[4 + 1 + 6] & 0xFF) << 48; + l |= (unsigned long long) (eventData[4 + 1 + 7] & 0xFF) << 56; + + if (l == v) { + ++signals; + break; + } + } while (!signaled || (log_time(CLOCK_MONOTONIC) < signal_time)); + alarm(0); + signal(SIGALRM, SIG_DFL); + + EXPECT_LE(1, count); EXPECT_EQ(1, signals); From 29e70a98feee7eb4591fcfcca064e2ba60364a98 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 10 Mar 2016 15:25:14 -0800 Subject: [PATCH 2/2] liblog: test: security buffer is allowed to be denied Bug: 27405083 Change-Id: I7cbc8fda326a2aea3bef5dabee9d3290cc818b24 --- liblog/tests/liblog_test.cpp | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index 3b4d851aa..956b76c84 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -1136,11 +1136,20 @@ TEST(liblog, android_logger_get_) { struct logger * logger; EXPECT_TRUE(NULL != (logger = android_logger_open(logger_list, id))); EXPECT_EQ(id, android_logger_get_id(logger)); - EXPECT_LT(0, android_logger_get_log_size(logger)); - /* crash buffer is allowed to be empty, that is actually healthy! */ - if (android_logger_get_log_readable_size(logger) || - (strcmp("crash", name) && strcmp("security", name))) { - EXPECT_LT(0, android_logger_get_log_readable_size(logger)); + ssize_t get_log_size = android_logger_get_log_size(logger); + /* security buffer is allowed to be denied */ + if (strcmp("security", name)) { + EXPECT_LT(0, get_log_size); + /* crash buffer is allowed to be empty, that is actually healthy! */ + EXPECT_LE((strcmp("crash", name)) != 0, + android_logger_get_log_readable_size(logger)); + } else { + EXPECT_NE(0, get_log_size); + if (get_log_size < 0) { + EXPECT_GT(0, android_logger_get_log_readable_size(logger)); + } else { + EXPECT_LE(0, android_logger_get_log_readable_size(logger)); + } } EXPECT_LT(0, android_logger_get_log_version(logger)); }