/* * Copyright (C) 2013-2014 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include #include #include #include #include #include #include #include // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and // non-syscall libs. Since we are only using this in the emergency of // a signal to stuff a terminating code into the logs, we will spin rather // than try a usleep. #define LOG_FAILURE_RETRY(exp) ({ \ typeof (exp) _rc; \ do { \ _rc = (exp); \ } while (((_rc == -1) \ && ((errno == EINTR) \ || (errno == EAGAIN))) \ || (_rc == -EINTR) \ || (_rc == -EAGAIN)); \ _rc; }) static const char begin[] = "--------- beginning of "; TEST(logcat, sorted_order) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -v time -b radio -b events -b system -b main -d 2>/dev/null", "r"))); class timestamp { private: int month; int day; int hour; int minute; int second; int millisecond; bool ok; public: void init(const char *buffer) { ok = false; if (buffer != NULL) { ok = sscanf(buffer, "%d-%d %d:%d:%d.%d ", &month, &day, &hour, &minute, &second, &millisecond) == 6; } } timestamp(const char *buffer) { init(buffer); } bool operator< (timestamp &T) { return !ok || !T.ok || (month < T.month) || ((month == T.month) && ((day < T.day) || ((day == T.day) && ((hour < T.hour) || ((hour == T.hour) && ((minute < T.minute) || ((minute == T.minute) && ((second < T.second) || ((second == T.second) && (millisecond < T.millisecond)))))))))); } bool valid(void) { return ok; } } last(NULL); char *last_buffer = NULL; char buffer[5120]; int count = 0; int next_lt_last = 0; while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(begin, buffer, sizeof(begin) - 1)) { continue; } if (!last.valid()) { free(last_buffer); last_buffer = strdup(buffer); last.init(buffer); } timestamp next(buffer); if (next < last) { if (last_buffer) { fprintf(stderr, "<%s", last_buffer); } fprintf(stderr, ">%s", buffer); ++next_lt_last; } if (next.valid()) { free(last_buffer); last_buffer = strdup(buffer); last.init(buffer); } ++count; } free(last_buffer); pclose(fp); EXPECT_EQ(0, next_lt_last); EXPECT_LT(100, count); } TEST(logcat, buckets) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -b radio -b events -b system -b main -d 2>/dev/null", "r"))); char buffer[5120]; int ids = 0; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(begin, buffer, sizeof(begin) - 1)) { while (char *cp = strrchr(buffer, '\n')) { *cp = '\0'; } log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1); ids |= 1 << id; ++count; } } pclose(fp); EXPECT_EQ(15, ids); EXPECT_EQ(4, count); } TEST(logcat, tail_3) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -v long -b radio -b events -b system -b main -t 3 2>/dev/null", "r"))); char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if ((buffer[0] == '[') && (buffer[1] == ' ') && isdigit(buffer[2]) && isdigit(buffer[3]) && (buffer[4] == '-')) { ++count; } } pclose(fp); ASSERT_EQ(3, count); } TEST(logcat, tail_10) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -v long -b radio -b events -b system -b main -t 10 2>/dev/null", "r"))); char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if ((buffer[0] == '[') && (buffer[1] == ' ') && isdigit(buffer[2]) && isdigit(buffer[3]) && (buffer[4] == '-')) { ++count; } } pclose(fp); ASSERT_EQ(10, count); } TEST(logcat, tail_100) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -v long -b radio -b events -b system -b main -t 100 2>/dev/null", "r"))); char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if ((buffer[0] == '[') && (buffer[1] == ' ') && isdigit(buffer[2]) && isdigit(buffer[3]) && (buffer[4] == '-')) { ++count; } } pclose(fp); ASSERT_EQ(100, count); } TEST(logcat, tail_1000) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -v long -b radio -b events -b system -b main -t 1000 2>/dev/null", "r"))); char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if ((buffer[0] == '[') && (buffer[1] == ' ') && isdigit(buffer[2]) && isdigit(buffer[3]) && (buffer[4] == '-')) { ++count; } } pclose(fp); ASSERT_EQ(1000, count); } TEST(logcat, tail_time) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r"))); char buffer[5120]; char *last_timestamp = NULL; char *first_timestamp = NULL; int count = 0; const unsigned int time_length = 18; const unsigned int time_offset = 2; while (fgets(buffer, sizeof(buffer), fp)) { if ((buffer[0] == '[') && (buffer[1] == ' ') && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1]) && (buffer[time_offset + 2] == '-')) { ++count; buffer[time_length + time_offset] = '\0'; if (!first_timestamp) { first_timestamp = strdup(buffer + time_offset); } free(last_timestamp); last_timestamp = strdup(buffer + time_offset); } } pclose(fp); EXPECT_EQ(10, count); EXPECT_TRUE(last_timestamp != NULL); EXPECT_TRUE(first_timestamp != NULL); snprintf(buffer, sizeof(buffer), "logcat -v long -b all -t '%s' 2>&1", first_timestamp); ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); int second_count = 0; int last_timestamp_count = -1; while (fgets(buffer, sizeof(buffer), fp)) { if ((buffer[0] == '[') && (buffer[1] == ' ') && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1]) && (buffer[time_offset + 2] == '-')) { ++second_count; buffer[time_length + time_offset] = '\0'; if (first_timestamp) { // we can get a transitory *extremely* rare failure if hidden // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000 EXPECT_STREQ(buffer + time_offset, first_timestamp); free(first_timestamp); first_timestamp = NULL; } if (!strcmp(buffer + time_offset, last_timestamp)) { last_timestamp_count = second_count; } } } pclose(fp); free(last_timestamp); last_timestamp = NULL; EXPECT_TRUE(first_timestamp == NULL); EXPECT_LE(count, second_count); EXPECT_LE(count, last_timestamp_count); } TEST(logcat, End_to_End) { pid_t pid = getpid(); log_time ts(CLOCK_MONOTONIC); ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -b events -t 100 2>/dev/null", "r"))); char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { int p; unsigned long long t; if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) || (p != pid)) { continue; } log_time tx((const char *) &t); if (ts == tx) { ++count; } } pclose(fp); ASSERT_EQ(1, count); } TEST(logcat, get_) { FILE *fp; ASSERT_TRUE(NULL != (fp = popen( "logcat -b radio -b events -b system -b main -g 2>/dev/null", "r"))); char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { int size, consumed, max, payload; size = consumed = max = payload = 0; if ((4 == sscanf(buffer, "%*s ring buffer is %dKb (%dKb consumed)," " max entry is %db, max payload is %db", &size, &consumed, &max, &payload)) && ((size * 3) >= consumed) && ((size * 1024) > max) && (max > payload)) { ++count; } } pclose(fp); ASSERT_EQ(4, count); } static void caught_blocking(int signum) { unsigned long long v = 0xDEADBEEFA55A0000ULL; v += getpid() & 0xFFFF; LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); } TEST(logcat, blocking) { FILE *fp; unsigned long long v = 0xDEADBEEFA55F0000ULL; pid_t pid = getpid(); v += pid & 0xFFFF; LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); v &= 0xFFFFFFFFFFFAFFFFULL; ASSERT_TRUE(NULL != (fp = popen( "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" " logcat -b events 2>&1", "r"))); char buffer[5120]; int count = 0; int signals = 0; signal(SIGALRM, caught_blocking); alarm(2); while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(buffer, "DONE", 4)) { break; } ++count; int p; unsigned long long l; if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) { continue; } if (l == v) { ++signals; break; } } alarm(0); signal(SIGALRM, SIG_DFL); // Generate SIGPIPE fclose(fp); caught_blocking(0); pclose(fp); EXPECT_LE(2, count); EXPECT_EQ(1, signals); } static void caught_blocking_tail(int signum) { unsigned long long v = 0xA55ADEADBEEF0000ULL; v += getpid() & 0xFFFF; LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); } TEST(logcat, blocking_tail) { FILE *fp; unsigned long long v = 0xA55FDEADBEEF0000ULL; pid_t pid = getpid(); v += pid & 0xFFFF; LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); v &= 0xFFFAFFFFFFFFFFFFULL; ASSERT_TRUE(NULL != (fp = popen( "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" " logcat -b events -T 5 2>&1", "r"))); char buffer[5120]; int count = 0; int signals = 0; signal(SIGALRM, caught_blocking_tail); alarm(2); while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(buffer, "DONE", 4)) { break; } ++count; int p; unsigned long long l; if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) { continue; } if (l == v) { if (count >= 5) { ++signals; } break; } } alarm(0); signal(SIGALRM, SIG_DFL); // Generate SIGPIPE fclose(fp); caught_blocking_tail(0); pclose(fp); EXPECT_LE(2, count); EXPECT_EQ(1, signals); } static void caught_blocking_clear(int signum) { unsigned long long v = 0xDEADBEEFA55C0000ULL; v += getpid() & 0xFFFF; LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); } TEST(logcat, blocking_clear) { FILE *fp; unsigned long long v = 0xDEADBEEFA55C0000ULL; pid_t pid = getpid(); v += pid & 0xFFFF; // This test is racey; an event occurs between clear and dump. // We accept that we will get a false positive, but never a false negative. ASSERT_TRUE(NULL != (fp = popen( "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" " logcat -b events -c 2>&1 ;" " logcat -b events 2>&1", "r"))); char buffer[5120]; int count = 0; int signals = 0; signal(SIGALRM, caught_blocking_clear); alarm(2); while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(buffer, "clearLog: ", 10)) { fprintf(stderr, "WARNING: Test lacks permission to run :-(\n"); count = signals = 1; break; } if (!strncmp(buffer, "DONE", 4)) { break; } ++count; int p; unsigned long long l; if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) { continue; } if (l == v) { if (count > 1) { fprintf(stderr, "WARNING: Possible false positive\n"); } ++signals; break; } } alarm(0); signal(SIGALRM, SIG_DFL); // Generate SIGPIPE fclose(fp); caught_blocking_clear(0); pclose(fp); EXPECT_LE(1, count); EXPECT_EQ(1, signals); } static bool get_white_black(char **list) { FILE *fp; fp = popen("logcat -p 2>/dev/null", "r"); if (fp == NULL) { fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n"); return false; } char buffer[5120]; while (fgets(buffer, sizeof(buffer), fp)) { char *hold = *list; char *buf = buffer; while (isspace(*buf)) { ++buf; } char *end = buf + strlen(buf); while (isspace(*--end) && (end >= buf)) { *end = '\0'; } if (end < buf) { continue; } if (hold) { asprintf(list, "%s %s", hold, buf); free(hold); } else { asprintf(list, "%s", buf); } } pclose(fp); return *list != NULL; } static bool set_white_black(const char *list) { FILE *fp; char buffer[5120]; snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list); fp = popen(buffer, "r"); if (fp == NULL) { fprintf(stderr, "ERROR: %s\n", buffer); return false; } while (fgets(buffer, sizeof(buffer), fp)) { char *buf = buffer; while (isspace(*buf)) { ++buf; } char *end = buf + strlen(buf); while (isspace(*--end) && (end >= buf)) { *end = '\0'; } if (end < buf) { continue; } fprintf(stderr, "%s\n", buf); pclose(fp); return false; } return pclose(fp) == 0; } TEST(logcat, white_black_adjust) { char *list = NULL; char *adjust = NULL; ASSERT_EQ(true, get_white_black(&list)); static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30"; ASSERT_EQ(true, set_white_black(adjustment)); ASSERT_EQ(true, get_white_black(&adjust)); EXPECT_STREQ(adjustment, adjust); free(adjust); adjust = NULL; static const char adjustment2[] = "300/20 300/21 2000 ~1000"; ASSERT_EQ(true, set_white_black(adjustment2)); ASSERT_EQ(true, get_white_black(&adjust)); EXPECT_STREQ(adjustment2, adjust); free(adjust); adjust = NULL; ASSERT_EQ(true, set_white_black(list)); ASSERT_EQ(true, get_white_black(&adjust)); EXPECT_STREQ(list, adjust); free(adjust); adjust = NULL; free(list); list = NULL; }