TEST(libc, __libc_android_log_event_int) { struct logger_list *logger_list; pid_t pid = getpid(); ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); int value = ts.tv_nsec; __libc_android_log_event_int(0, value); usleep(1000000); int count = 0; for (;;) { log_msg log_msg; if (android_logger_list_read(logger_list, &log_msg) <= 0) { break; } ASSERT_EQ(log_msg.entry.pid, pid); if ((log_msg.entry.len != (4 + 1 + 4)) || ((int)log_msg.id() != LOG_ID_EVENTS)) { continue; } char *eventData = log_msg.msg(); int incoming = (eventData[0] & 0xFF) | ((eventData[1] & 0xFF) << 8) | ((eventData[2] & 0xFF) << 16) | ((eventData[3] & 0xFF) << 24); if (incoming != 0) { continue; } if (eventData[4] != EVENT_TYPE_INT) { continue; } incoming = (eventData[4 + 1 + 0] & 0xFF) | ((eventData[4 + 1 + 1] & 0xFF) << 8) | ((eventData[4 + 1 + 2] & 0xFF) << 16) | ((eventData[4 + 1 + 3] & 0xFF) << 24); if (incoming == value) { ++count; } } EXPECT_EQ(1, count); android_logger_list_close(logger_list); }
TEST(liblog, dual_reader) { struct logger_list *logger_list1; // >25 messages due to liblog.__android_log_buf_print__concurrentXX above. ASSERT_TRUE(NULL != (logger_list1 = android_logger_list_open( LOG_ID_MAIN, O_RDONLY | O_NDELAY, 25, 0))); struct logger_list *logger_list2; if (NULL == (logger_list2 = android_logger_list_open( LOG_ID_MAIN, O_RDONLY | O_NDELAY, 15, 0))) { android_logger_list_close(logger_list1); ASSERT_TRUE(NULL != logger_list2); } int count1 = 0; bool done1 = false; int count2 = 0; bool done2 = false; do { log_msg log_msg; if (!done1) { if (android_logger_list_read(logger_list1, &log_msg) <= 0) { done1 = true; } else { ++count1; } } if (!done2) { if (android_logger_list_read(logger_list2, &log_msg) <= 0) { done2 = true; } else { ++count2; } } } while ((!done1) || (!done2)); android_logger_list_close(logger_list1); android_logger_list_close(logger_list2); EXPECT_EQ(25, count1); EXPECT_EQ(15, count2); }
/* * Measure the time it takes for the logd posting call to make it into * the logs. Expect this to be less than double the process wakeup time (2ms). */ static void BM_log_delay(benchmark::State& state) { pid_t pid = getpid(); struct logger_list* logger_list = android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid); if (!logger_list) { fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); exit(EXIT_FAILURE); } signal(SIGALRM, caught_delay); alarm(alarm_time); while (state.KeepRunning()) { log_time ts(CLOCK_REALTIME); LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); for (;;) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); alarm(alarm_time); if (ret <= 0) { state.SkipWithError("android_logger_list_read"); break; } if ((log_msg.entry.len != (4 + 1 + 8)) || (log_msg.id() != LOG_ID_EVENTS)) { continue; } char* eventData = log_msg.msg(); if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { continue; } log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { state.SkipWithError("signal"); break; } continue; } break; } } state.PauseTiming(); signal(SIGALRM, SIG_DFL); alarm(0); android_logger_list_free(logger_list); }
TEST(liblog, too_big_payload) { pid_t pid = getpid(); static const char big_payload_tag[] = "TEST_big_payload_XXXX"; char tag[sizeof(big_payload_tag)]; memcpy(tag, big_payload_tag, sizeof(tag)); snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF); std::string longString(3266519, 'x'); ssize_t ret = LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO, tag, longString.c_str())); struct logger_list *logger_list; ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( LOG_ID_SYSTEM, O_RDONLY | O_NDELAY, 100, 0))); ssize_t max_len = 0; for(;;) { log_msg log_msg; if (android_logger_list_read(logger_list, &log_msg) <= 0) { break; } if ((log_msg.entry.pid != pid) || (log_msg.id() != LOG_ID_SYSTEM)) { continue; } char *data = log_msg.msg() + 1; if (strcmp(data, tag)) { continue; } data += strlen(data) + 1; const char *left = data; const char *right = longString.c_str(); while (*left && *right && (*left == *right)) { ++left; ++right; } if (max_len <= (left - data)) { max_len = left - data + 1; } } android_logger_list_close(logger_list); EXPECT_LE(LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag), static_cast<size_t>(max_len)); EXPECT_EQ(ret, max_len + sizeof(big_payload_tag)); }
TEST(liblog, __android_log_write__android_logger_list_read) { #ifdef __ANDROID__ pid_t pid = getpid(); struct logger_list* logger_list; ASSERT_TRUE( NULL != (logger_list = android_logger_list_open( LOG_ID_MAIN, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); std::string buf = android::base::StringPrintf("pid=%u ts=%ld.%09ld", pid, ts.tv_sec, ts.tv_nsec); static const char tag[] = "liblog.__android_log_write__android_logger_list_read"; static const char prio = ANDROID_LOG_DEBUG; ASSERT_LT(0, __android_log_write(prio, tag, buf.c_str())); usleep(1000000); buf = std::string(&prio, sizeof(prio)) + tag + std::string("", 1) + buf + std::string("", 1); int count = 0; for (;;) { log_msg log_msg; if (android_logger_list_read(logger_list, &log_msg) <= 0) break; EXPECT_EQ(log_msg.entry.pid, pid); // There may be a future where we leak "liblog" tagged LOG_ID_EVENT // binary messages through so that logger losses can be correlated? EXPECT_EQ(log_msg.id(), LOG_ID_MAIN); if (log_msg.entry.len != buf.length()) continue; if (buf != std::string(log_msg.msg(), log_msg.entry.len)) continue; ++count; } android_logger_list_close(logger_list); EXPECT_EQ(1, count); #else GTEST_LOG_(INFO) << "This test does nothing.\n"; #endif }
TEST(liblog, __android_log_btwrite__android_logger_list_read) { struct logger_list *logger_list; pid_t pid = getpid(); ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open( LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); log_time ts(CLOCK_MONOTONIC); ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); usleep(1000000); int count = 0; for (;;) { log_msg log_msg; if (android_logger_list_read(logger_list, &log_msg) <= 0) { break; } 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; } log_time tx(eventData + 4 + 1); if (ts == tx) { ++count; } } ASSERT_EQ(1, count); android_logger_list_close(logger_list); }
TEST(libc, __libc_fatal_no_abort) { struct logger_list *logger_list; pid_t pid = getpid(); ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( (log_id_t)LOG_ID_MAIN, O_RDONLY | O_NDELAY, 1000, pid))); char b[80]; struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); __libc_fatal_no_abort("%u.%09u", (unsigned)ts.tv_sec, (unsigned)ts.tv_nsec); snprintf(b, sizeof(b),"%u.%09u", (unsigned)ts.tv_sec, (unsigned)ts.tv_nsec); usleep(1000000); int count = 0; for (;;) { log_msg log_msg; if (android_logger_list_read(logger_list, &log_msg) <= 0) { break; } ASSERT_EQ(log_msg.entry.pid, pid); if ((int)log_msg.id() != LOG_ID_MAIN) { continue; } char *data = log_msg.msg(); if ((*data == ANDROID_LOG_FATAL) && !strcmp(data + 1, "libc") && !strcmp(data + 1 + strlen(data + 1) + 1, b)) { ++count; } } EXPECT_EQ(1, count); android_logger_list_close(logger_list); }
/* * Measure the time it takes for the logd posting call to make it into * the logs. Expect this to be less than double the process wakeup time (2ms). */ static void BM_log_delay(int iters) { pid_t pid = getpid(); struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS, O_RDONLY, 0, pid); if (!logger_list) { fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); exit(EXIT_FAILURE); } signal(SIGALRM, caught_delay); alarm(alarm_time); StartBenchmarkTiming(); for (int i = 0; i < iters; ++i) { log_time ts(CLOCK_REALTIME); LOG_FAILURE_RETRY( android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); for (;;) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); alarm(alarm_time); if (ret <= 0) { iters = i; break; } 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; } log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { iters = i; break; } continue; } break; } } signal(SIGALRM, SIG_DFL); alarm(0); StopBenchmarkTiming(); android_logger_list_free(logger_list); }
TEST(liblog, android_logger_list_read__cpu) { struct logger_list *logger_list; unsigned long long v = 0xDEADBEEFA55A0000ULL; pid_t pid = getpid(); v += pid & 0xFFFF; ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open( LOG_ID_EVENTS, O_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)); signal(SIGALRM, caught_blocking); alarm(alarm_time); signaled = 0; do { log_msg log_msg; if (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 t(CLOCK_MONOTONIC); t < signal_time;}));
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); pid_t pid = fork(); if (pid == 0) { // child for (int i = count; i; --i) { ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); usleep(100); } ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1))); usleep(1000000); _exit(0); } siginfo_t info{}; ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); int expected_count = (count < 2) ? count : 2; int expected_chatty_count = (count <= 2) ? 0 : 1; int expected_expire_count = (count < 2) ? 0 : (count - 2); count = 0; int second_count = 0; int chatty_count = 0; int expire_count = 0; for (;;) { log_msg log_msg; if (android_logger_list_read(logger_list, &log_msg) <= 0) break; if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) || (log_msg.id() != LOG_ID_EVENTS)) continue; char *eventData = log_msg.msg(); if (!eventData) continue; uint32_t tag = get4LE(eventData); if ((eventData[4] == EVENT_TYPE_LONG) && (log_msg.entry.len == (4 + 1 + 8))) { if (tag != 0) continue; log_time tx(eventData + 4 + 1); if (ts == tx) { ++count; } else if (ts1 == tx) { ++second_count; } } else if (eventData[4] == EVENT_TYPE_STRING) { // chatty if (tag != 1004) continue; ++chatty_count; // int len = get4LE(eventData + 4 + 1); const char *cp = strstr(eventData + 4 + 1 + 4, " expire "); if (!cp) continue; unsigned val = 0; sscanf(cp, " expire %u lines", &val); expire_count += val; } } 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(liblog, android_logger_list_read__cpu) { struct logger_list *logger_list; unsigned long long v = 0xDEADBEEFA55A0000ULL; pid_t pid = getpid(); v += pid & 0xFFFF; ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( LOG_ID_EVENTS, O_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)); signal(SIGALRM, caught_blocking); alarm(alarm_time); signaled = 0; do { log_msg log_msg; if (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_LT(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); }
/* * Measure the time it takes for the logd posting call to acquire the * timestamp to place into the internal record. Expect this to be less than * 4 syscalls (3us). This test uses manual injection of timing because it is * comparing the timestamp at send, and then picking up the corresponding log * end-to-end long path from logd to see what actual timestamp was submitted. */ static void BM_log_latency(benchmark::State& state) { pid_t pid = getpid(); struct logger_list* logger_list = android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid); if (!logger_list) { fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); exit(EXIT_FAILURE); } signal(SIGALRM, caught_latency); alarm(alarm_time); for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) { retry: // We allow transitory errors (logd overloaded) to be retried. log_time ts; LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME), android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); for (;;) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); alarm(alarm_time); if (ret <= 0) { state.SkipWithError("android_logger_list_read"); break; } if ((log_msg.entry.len != (4 + 1 + 8)) || (log_msg.id() != LOG_ID_EVENTS)) { continue; } char* eventData = log_msg.msg(); if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) { continue; } log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { state.SkipWithError("signal"); break; } continue; } uint64_t start = ts.nsec(); uint64_t end = log_msg.nsec(); if (end < start) goto retry; state.SetIterationTime((end - start) / (double)NS_PER_SEC); break; } } signal(SIGALRM, SIG_DFL); alarm(0); android_logger_list_free(logger_list); }
/* * In class android.util.EventLog: * static native void readEvents(int[] tags, Collection<Event> output) * * Reads events from the event log */ static void android_util_EventLog_readEvents(JNIEnv* env, jobject clazz UNUSED, jintArray tags, jobject out) { if (tags == NULL || out == NULL) { jniThrowNullPointerException(env, NULL); return; } struct logger_list *logger_list = android_logger_list_open( LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, 0); if (!logger_list) { jniThrowIOException(env, errno); return; } jsize tagLength = env->GetArrayLength(tags); jint *tagValues = env->GetIntArrayElements(tags, NULL); while (1) { log_msg log_msg; int ret = android_logger_list_read(logger_list, &log_msg); if (ret == 0) { break; } if (ret < 0) { if (ret == -EINTR) { continue; } if (ret == -EINVAL) { jniThrowException(env, "java/io/IOException", "Event too short"); } else if (ret != -EAGAIN) { jniThrowIOException(env, -ret); // Will throw on return } break; } if (log_msg.id() != LOG_ID_EVENTS) { continue; } int32_t tag = * (int32_t *) log_msg.msg(); int found = 0; for (int i = 0; !found && i < tagLength; ++i) { found = (tag == tagValues[i]); } if (found) { jsize len = ret; jbyteArray array = env->NewByteArray(len); if (array == NULL) { break; } jbyte *bytes = env->GetByteArrayElements(array, NULL); memcpy(bytes, log_msg.buf, len); env->ReleaseByteArrayElements(array, bytes, 0); jobject event = env->NewObject(gEventClass, gEventInitID, array); if (event == NULL) {