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);
}
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_logger_get_) {
#ifdef __ANDROID__
// This test assumes the log buffers are filled with noise from
// normal operations. It will fail if done immediately after a
// logcat -c.
struct logger_list* logger_list =
android_logger_list_alloc(ANDROID_LOG_WRONLY, 0, 0);
for (int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) {
log_id_t id = static_cast<log_id_t>(i);
const char* name = android_log_id_to_name(id);
if (id != android_name_to_log_id(name)) {
continue;
}
fprintf(stderr, "log buffer %s\r", name);
struct logger* logger;
EXPECT_TRUE(NULL != (logger = android_logger_open(logger_list, id)));
EXPECT_EQ(id, android_logger_get_id(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!
// kernel buffer is allowed to be empty on "user" builds
// stats buffer is allowed to be empty TEMPORARILY.
// TODO: remove stats buffer from here once we start to use it in
// framework (b/68266385).
EXPECT_LE( // boolean 1 or 0 depending on expected content or empty
!!((strcmp("crash", name) != 0) &&
((strcmp("kernel", name) != 0) ||
__android_logger_property_get_bool(
"ro.logd.kernel", BOOL_DEFAULT_TRUE | BOOL_DEFAULT_FLAG_ENG |
BOOL_DEFAULT_FLAG_SVELTE)) &&
(strcmp("stats", 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));
}
android_logger_list_close(logger_list);
#else
GTEST_LOG_(INFO) << "This test does nothing.\n";
#endif
}
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);
}
TEST(liblog, android_logger_get_) {
struct logger_list * logger_list = android_logger_list_alloc(O_WRONLY, 0, 0);
for(int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) {
log_id_t id = static_cast<log_id_t>(i);
const char *name = android_log_id_to_name(id);
if (id != android_name_to_log_id(name)) {
continue;
}
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));
EXPECT_LT(0, android_logger_get_log_readable_size(logger));
EXPECT_LT(0, android_logger_get_log_version(logger));
}
android_logger_list_close(logger_list);
}
TEST(liblog, android_logger_get_) {
struct logger_list * logger_list = android_logger_list_alloc(ANDROID_LOG_WRONLY, 0, 0);
for(int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) {
log_id_t id = static_cast<log_id_t>(i);
const char *name = android_log_id_to_name(id);
if (id != android_name_to_log_id(name)) {
continue;
}
fprintf(stderr, "log buffer %s\r", name);
struct logger * logger;
EXPECT_TRUE(NULL != (logger = android_logger_open(logger_list, id)));
EXPECT_EQ(id, android_logger_get_id(logger));
/* crash buffer is allowed to be empty, that is actually healthy! */
if (android_logger_get_log_size(logger) || strcmp("crash", name)) {
EXPECT_LT(0, android_logger_get_log_size(logger));
}
EXPECT_LT(0, android_logger_get_log_readable_size(logger));
EXPECT_LT(0, android_logger_get_log_version(logger));
}
android_logger_list_close(logger_list);
}
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);
}
