/* * 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 #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #ifndef logcat_executable #define USING_LOGCAT_EXECUTABLE_DEFAULT #define logcat_executable "logcat" #endif #define BIG_BUFFER (5 * 1024) // rest(), let the logs settle. // // logd is in a background cgroup and under extreme load can take up to // 3 seconds to land a log entry. Under moderate load we can do with 200ms. static void rest() { static const useconds_t restPeriod = 200000; usleep(restPeriod); } // 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, buckets) { FILE* fp; #undef LOG_TAG #define LOG_TAG "inject.buckets" // inject messages into radio, system, main and events buffers to // ensure that we see all the begin[] bucket messages. RLOGE(logcat_executable); SLOGE(logcat_executable); ALOGE(logcat_executable); __android_log_bswrite(0, logcat_executable ".inject.buckets"); rest(); ASSERT_TRUE(NULL != (fp = popen(logcat_executable " -b radio -b events -b system -b main -d 2>/dev/null", "r"))); char buffer[BIG_BUFFER]; 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(ids, 15); EXPECT_EQ(count, 4); } TEST(logcat, event_tag_filter) { FILE* fp; #undef LOG_TAG #define LOG_TAG "inject.filter" // inject messages into radio, system and main buffers // with our unique log tag to test logcat filter. RLOGE(logcat_executable); SLOGE(logcat_executable); ALOGE(logcat_executable); rest(); std::string command = android::base::StringPrintf( logcat_executable " -b radio -b system -b main --pid=%d -d -s inject.filter 2>/dev/null", getpid()); ASSERT_TRUE(NULL != (fp = popen(command.c_str(), "r"))); char buffer[BIG_BUFFER]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if (strncmp(begin, buffer, sizeof(begin) - 1)) ++count; } pclose(fp); // logcat, liblogcat and logcatd test instances result in the progression // of 3, 6 and 9 for our counts as each round is performed. EXPECT_GE(count, 3); EXPECT_LE(count, 9); EXPECT_EQ(count % 3, 0); } // If there is not enough background noise in the logs, then spam the logs to // permit tail checking so that the tests can progress. static size_t inject(ssize_t count) { if (count <= 0) return 0; static const size_t retry = 4; size_t errors = retry; size_t num = 0; for (;;) { log_time ts(CLOCK_MONOTONIC); if (__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) >= 0) { if (++num >= (size_t)count) { // let data settle end-to-end sleep(3); return num; } errors = retry; usleep(100); // ~32 per timer tick, we are a spammer regardless } else if (--errors <= 0) { return num; } } // NOTREACH return num; } TEST(logcat, year) { int count; int tries = 3; // in case run too soon after system start or buffer clear do { FILE* fp; char needle[32]; time_t now; time(&now); struct tm* ptm; #if !defined(_WIN32) struct tm tmBuf; ptm = localtime_r(&now, &tmBuf); #else ptm = localtime(&&now); #endif strftime(needle, sizeof(needle), "[ %Y-", ptm); ASSERT_TRUE(NULL != (fp = popen(logcat_executable " -v long -v year -b all -t 3 2>/dev/null", "r"))); char buffer[BIG_BUFFER]; count = 0; while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(buffer, needle, strlen(needle))) { ++count; } } pclose(fp); } while ((count < 3) && --tries && inject(3 - count)); ASSERT_EQ(3, count); } // Return a pointer to each null terminated -v long time field. static char* fgetLongTime(char* buffer, size_t buflen, FILE* fp) { while (fgets(buffer, buflen, fp)) { char* cp = buffer; if (*cp != '[') { continue; } while (*++cp == ' ') { ; } char* ep = cp; while (isdigit(*ep)) { ++ep; } if ((*ep != '-') && (*ep != '.')) { continue; } // Find PID field. Look for ': ' or ':[0-9][0-9][0-9]' while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) { if (isdigit(ep[0]) && isdigit(ep[1]) && isdigit(ep[2])) break; } if (!ep) { continue; } static const size_t pid_field_width = 7; ep -= pid_field_width; *ep = '\0'; return cp; } return NULL; } TEST(logcat, tz) { int tries = 4; // in case run too soon after system start or buffer clear int count; do { FILE* fp; ASSERT_TRUE(NULL != (fp = popen(logcat_executable " -v long -v America/Los_Angeles -b all -t 3 2>/dev/null", "r"))); char buffer[BIG_BUFFER]; count = 0; while (fgetLongTime(buffer, sizeof(buffer), fp)) { if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) { ++count; } else { fprintf(stderr, "ts=\"%s\"\n", buffer + 2); } } pclose(fp); } while ((count < 3) && --tries && inject(3 - count)); ASSERT_EQ(3, count); } TEST(logcat, ntz) { FILE* fp; ASSERT_TRUE(NULL != (fp = popen(logcat_executable " -v long -v America/Los_Angeles -v zone -b all -t 3 2>/dev/null", "r"))); char buffer[BIG_BUFFER]; int count = 0; while (fgetLongTime(buffer, sizeof(buffer), fp)) { if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) { ++count; } } pclose(fp); ASSERT_EQ(0, count); } static void do_tail(int num) { int tries = 4; // in case run too soon after system start or buffer clear int count; if (num > 10) ++tries; if (num > 100) ++tries; do { char buffer[BIG_BUFFER]; snprintf(buffer, sizeof(buffer), "ANDROID_PRINTF_LOG=long logcat -b all -t %d 2>/dev/null", num); FILE* fp; ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); count = 0; while (fgetLongTime(buffer, sizeof(buffer), fp)) { ++count; } pclose(fp); } while ((count < num) && --tries && inject(num - count)); ASSERT_EQ(num, count); } TEST(logcat, tail_3) { do_tail(3); } TEST(logcat, tail_10) { do_tail(10); } TEST(logcat, tail_100) { do_tail(100); } TEST(logcat, tail_1000) { do_tail(1000); } static void do_tail_time(const char* cmd) { FILE* fp; int count; char buffer[BIG_BUFFER]; char* last_timestamp = NULL; // Hard to predict 100% if first (overlap) or second line will match. // -v nsec will in a substantial majority be the second line. char* first_timestamp = NULL; char* second_timestamp = NULL; char* input; int tries = 4; // in case run too soon after system start or buffer clear do { snprintf(buffer, sizeof(buffer), "%s -t 10 2>&1", cmd); ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); count = 0; while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) { ++count; if (!first_timestamp) { first_timestamp = strdup(input); } else if (!second_timestamp) { second_timestamp = strdup(input); } free(last_timestamp); last_timestamp = strdup(input); } pclose(fp); } while ((count < 10) && --tries && inject(10 - count)); EXPECT_EQ(count, 10); // We want _some_ history, too small, falses below EXPECT_TRUE(last_timestamp != NULL); EXPECT_TRUE(first_timestamp != NULL); EXPECT_TRUE(second_timestamp != NULL); snprintf(buffer, sizeof(buffer), "%s -t '%s' 2>&1", cmd, first_timestamp); ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); int second_count = 0; int last_timestamp_count = -1; --count; // One less unless we match the first_timestamp bool found = false; while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) { ++second_count; // We want to highlight if we skip to the next entry. // WAI, if the time in logd is *exactly* // XX-XX XX:XX:XX.XXXXXX000 (usec) or XX-XX XX:XX:XX.XXX000000 // this can happen, but it should not happen with nsec. // We can make this WAI behavior happen 1000 times less // frequently if the caller does not use the -v usec flag, // but always the second (always skip) if they use the // (undocumented) -v nsec flag. if (first_timestamp) { found = !strcmp(input, first_timestamp); if (found) { ++count; GTEST_LOG_(INFO) << "input = first(" << first_timestamp << ")\n"; } free(first_timestamp); first_timestamp = NULL; } if (second_timestamp) { found = found || !strcmp(input, second_timestamp); if (!found) { GTEST_LOG_(INFO) << "input(" << input << ") != second(" << second_timestamp << ")\n"; } free(second_timestamp); second_timestamp = NULL; } if (!strcmp(input, last_timestamp)) { last_timestamp_count = second_count; } } pclose(fp); EXPECT_TRUE(found); if (!found) { if (first_timestamp) { GTEST_LOG_(INFO) << "first = " << first_timestamp << "\n"; } if (second_timestamp) { GTEST_LOG_(INFO) << "second = " << second_timestamp << "\n"; } if (last_timestamp) { GTEST_LOG_(INFO) << "last = " << last_timestamp << "\n"; } } free(last_timestamp); last_timestamp = NULL; free(first_timestamp); free(second_timestamp); EXPECT_TRUE(first_timestamp == NULL); EXPECT_TRUE(second_timestamp == NULL); EXPECT_LE(count, second_count); EXPECT_LE(count, last_timestamp_count); } TEST(logcat, tail_time) { do_tail_time(logcat_executable " -v long -v nsec -b all"); } TEST(logcat, tail_time_epoch) { do_tail_time(logcat_executable " -v long -v nsec -v epoch -b all"); } 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_executable " -v brief -b events -t 100 2>/dev/null", "r"))); char buffer[BIG_BUFFER]; 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 = reinterpret_cast(&t); if (ts == *tx) { ++count; } } pclose(fp); ASSERT_EQ(1, count); } TEST(logcat, End_to_End_multitude) { pid_t pid = getpid(); log_time ts(CLOCK_MONOTONIC); ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); FILE* fp[256]; // does this count as a multitude! memset(fp, 0, sizeof(fp)); size_t num = 0; do { EXPECT_TRUE(NULL != (fp[num] = popen(logcat_executable " -v brief -b events -t 100", "r"))); if (!fp[num]) { fprintf(stderr, "WARNING: limiting to %zu simultaneous logcat operations\n", num); break; } } while (++num < sizeof(fp) / sizeof(fp[0])); char buffer[BIG_BUFFER]; size_t count = 0; for (size_t idx = 0; idx < sizeof(fp) / sizeof(fp[0]); ++idx) { if (!fp[idx]) break; while (fgets(buffer, sizeof(buffer), fp[idx])) { int p; unsigned long long t; if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) || (p != pid)) { continue; } log_time* tx = reinterpret_cast(&t); if (ts == *tx) { ++count; } } pclose(fp[idx]); } ASSERT_EQ(num, count); } static int get_groups(const char* cmd) { FILE* fp; // NB: crash log only available in user space EXPECT_TRUE(NULL != (fp = popen(cmd, "r"))); if (fp == NULL) { return 0; } char buffer[BIG_BUFFER]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { int size, consumed, max, payload; char size_mult[4], consumed_mult[4]; long full_size, full_consumed; size = consumed = max = payload = 0; // NB: crash log can be very small, not hit a Kb of consumed space // doubly lucky we are not including it. EXPECT_EQ(6, sscanf(buffer, "%*s ring buffer is %d %3s (%d %3s consumed)," " max entry is %d B, max payload is %d B", &size, size_mult, &consumed, consumed_mult, &max, &payload)) << "Parse error on: " << buffer; full_size = size; switch (size_mult[0]) { case 'G': full_size *= 1024; FALLTHROUGH_INTENDED; case 'M': full_size *= 1024; FALLTHROUGH_INTENDED; case 'K': full_size *= 1024; FALLTHROUGH_INTENDED; case 'B': break; default: ADD_FAILURE() << "Parse error on multiplier: " << size_mult; } full_consumed = consumed; switch (consumed_mult[0]) { case 'G': full_consumed *= 1024; FALLTHROUGH_INTENDED; case 'M': full_consumed *= 1024; FALLTHROUGH_INTENDED; case 'K': full_consumed *= 1024; FALLTHROUGH_INTENDED; case 'B': break; default: ADD_FAILURE() << "Parse error on multiplier: " << consumed_mult; } EXPECT_GT((full_size * 9) / 4, full_consumed); EXPECT_GT(full_size, max); EXPECT_GT(max, payload); if ((((full_size * 9) / 4) >= full_consumed) && (full_size > max) && (max > payload)) { ++count; } } pclose(fp); return count; } TEST(logcat, get_size) { ASSERT_EQ(4, get_groups(logcat_executable " -v brief -b radio -b events -b system -b " "main -g 2>/dev/null")); } // duplicate test for get_size, but use comma-separated list of buffers TEST(logcat, multiple_buffer) { ASSERT_EQ( 4, get_groups(logcat_executable " -v brief -b radio,events,system,main -g 2>/dev/null")); } TEST(logcat, bad_buffer) { ASSERT_EQ(0, get_groups( logcat_executable " -v brief -b radio,events,bogo,system,main -g 2>/dev/null")); } #ifndef logcat static void caught_blocking(int signum) { unsigned long long v = 0xDEADBEEFA55A0000ULL; v += getpid() & 0xFFFF; if (signum == 0) ++v; 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 -v brief -b events 2>&1", "r"))); char buffer[BIG_BUFFER]; 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_GE(count, 2); EXPECT_EQ(signals, 1); } static void caught_blocking_tail(int signum) { unsigned long long v = 0xA55ADEADBEEF0000ULL; v += getpid() & 0xFFFF; if (signum == 0) ++v; 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 -v brief -b events -T 5 2>&1", "r"))); char buffer[BIG_BUFFER]; 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_GE(count, 2); EXPECT_EQ(signals, 1); } #endif // meant to be handed to ASSERT_FALSE / EXPECT_FALSE to expand the message static testing::AssertionResult IsFalse(int ret, const char* command) { return ret ? (testing::AssertionSuccess() << "ret=" << ret << " command=\"" << command << "\"") : testing::AssertionFailure(); } TEST(logcat, logrotate) { static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; char buf[sizeof(form)]; ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form))); static const char comm[] = logcat_executable " -b radio -b events -b system -b main" " -d -f %s/log.txt -n 7 -r 1"; char command[sizeof(buf) + sizeof(comm)]; snprintf(command, sizeof(command), comm, buf); int ret; EXPECT_FALSE(IsFalse(ret = system(command), command)); if (!ret) { snprintf(command, sizeof(command), "ls -s %s 2>/dev/null", buf); FILE* fp; EXPECT_TRUE(NULL != (fp = popen(command, "r"))); if (fp) { char buffer[BIG_BUFFER]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { static const char total[] = "total "; int num; char c; if ((2 == sscanf(buffer, "%d log.tx%c", &num, &c)) && (num <= 40)) { ++count; } else if (strncmp(buffer, total, sizeof(total) - 1)) { fprintf(stderr, "WARNING: Parse error: %s", buffer); } } pclose(fp); if ((count != 7) && (count != 8)) { fprintf(stderr, "count=%d\n", count); } EXPECT_TRUE(count == 7 || count == 8); } } snprintf(command, sizeof(command), "rm -rf %s", buf); EXPECT_FALSE(IsFalse(system(command), command)); } TEST(logcat, logrotate_suffix) { static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; char tmp_out_dir[sizeof(tmp_out_dir_form)]; ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); static const char logcat_cmd[] = logcat_executable " -b radio -b events -b system -b main" " -d -f %s/log.txt -n 10 -r 1"; char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)]; snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir); int ret; EXPECT_FALSE(IsFalse(ret = system(command), command)); if (!ret) { snprintf(command, sizeof(command), "ls %s 2>/dev/null", tmp_out_dir); FILE* fp; EXPECT_TRUE(NULL != (fp = popen(command, "r"))); char buffer[BIG_BUFFER]; int log_file_count = 0; while (fgets(buffer, sizeof(buffer), fp)) { static const char rotated_log_filename_prefix[] = "log.txt."; static const size_t rotated_log_filename_prefix_len = strlen(rotated_log_filename_prefix); static const char log_filename[] = "log.txt"; if (!strncmp(buffer, rotated_log_filename_prefix, rotated_log_filename_prefix_len)) { // Rotated file should have form log.txt.## char* rotated_log_filename_suffix = buffer + rotated_log_filename_prefix_len; char* endptr; const long int suffix_value = strtol(rotated_log_filename_suffix, &endptr, 10); EXPECT_EQ(rotated_log_filename_suffix + 2, endptr); EXPECT_LE(suffix_value, 10); EXPECT_GT(suffix_value, 0); ++log_file_count; continue; } if (!strncmp(buffer, log_filename, strlen(log_filename))) { ++log_file_count; continue; } fprintf(stderr, "ERROR: Unexpected file: %s", buffer); ADD_FAILURE(); } pclose(fp); EXPECT_EQ(log_file_count, 11); } snprintf(command, sizeof(command), "rm -rf %s", tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); } TEST(logcat, logrotate_continue) { static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; char tmp_out_dir[sizeof(tmp_out_dir_form)]; ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); static const char log_filename[] = "log.txt"; static const char logcat_cmd[] = logcat_executable " -b all -v nsec -d -f %s/%s -n 256 -r 1024"; static const char cleanup_cmd[] = "rm -rf %s"; char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)]; snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); int ret; EXPECT_FALSE(IsFalse(ret = system(command), command)); if (ret) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); return; } FILE* fp; snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, log_filename); EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); if (!fp) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); return; } char* line = NULL; char* last_line = NULL; // this line is allowed to stutter, one-line overlap char* second_last_line = NULL; // should never stutter char* first_line = NULL; // help diagnose failure? size_t len = 0; while (getline(&line, &len, fp) != -1) { if (!first_line) { first_line = line; line = NULL; continue; } free(second_last_line); second_last_line = last_line; last_line = line; line = NULL; } fclose(fp); free(line); if (second_last_line == NULL) { fprintf(stderr, "No second to last line, using last, test may fail\n"); second_last_line = last_line; last_line = NULL; } free(last_line); EXPECT_TRUE(NULL != second_last_line); if (!second_last_line) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); free(first_line); return; } // re-run the command, it should only add a few lines more content if it // continues where it left off. snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); EXPECT_FALSE(IsFalse(ret = system(command), command)); if (ret) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); free(second_last_line); free(first_line); return; } std::unique_ptr dir(opendir(tmp_out_dir), closedir); EXPECT_NE(nullptr, dir); if (!dir) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); free(second_last_line); free(first_line); return; } struct dirent* entry; unsigned count = 0; while ((entry = readdir(dir.get()))) { if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { continue; } snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, entry->d_name); EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); if (!fp) { fprintf(stderr, "%s ?\n", command); continue; } line = NULL; size_t number = 0; while (getline(&line, &len, fp) != -1) { ++number; if (!strcmp(line, second_last_line)) { EXPECT_TRUE(++count <= 1); fprintf(stderr, "%s(%zu):\n", entry->d_name, number); } } fclose(fp); free(line); unlink(command); } if (count > 1) { char* brk = strpbrk(second_last_line, "\r\n"); if (!brk) brk = second_last_line + strlen(second_last_line); fprintf(stderr, "\"%.*s\" occurred %u times\n", (int)(brk - second_last_line), second_last_line, count); if (first_line) { brk = strpbrk(first_line, "\r\n"); if (!brk) brk = first_line + strlen(first_line); fprintf(stderr, "\"%.*s\" was first line, fault?\n", (int)(brk - first_line), first_line); } } free(second_last_line); free(first_line); snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); } TEST(logcat, logrotate_clear) { static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; char tmp_out_dir[sizeof(tmp_out_dir_form)]; ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); static const char log_filename[] = "log.txt"; static const unsigned num_val = 32; static const char logcat_cmd[] = logcat_executable " -b all -d -f %s/%s -n %d -r 1"; static const char clear_cmd[] = " -c"; static const char cleanup_cmd[] = "rm -rf %s"; char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename) + sizeof(clear_cmd) + 32]; // Run command with all data { snprintf(command, sizeof(command) - sizeof(clear_cmd), logcat_cmd, tmp_out_dir, log_filename, num_val); int ret; EXPECT_FALSE(IsFalse(ret = system(command), command)); if (ret) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); return; } std::unique_ptr dir(opendir(tmp_out_dir), closedir); EXPECT_NE(nullptr, dir); if (!dir) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); return; } struct dirent* entry; unsigned count = 0; while ((entry = readdir(dir.get()))) { if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { continue; } ++count; } EXPECT_EQ(count, num_val + 1); } { // Now with -c option tacked onto the end strcat(command, clear_cmd); int ret; EXPECT_FALSE(IsFalse(ret = system(command), command)); if (ret) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(system(command)); EXPECT_FALSE(IsFalse(system(command), command)); return; } std::unique_ptr dir(opendir(tmp_out_dir), closedir); EXPECT_NE(nullptr, dir); if (!dir) { snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); return; } struct dirent* entry; unsigned count = 0; while ((entry = readdir(dir.get()))) { if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { continue; } fprintf(stderr, "Found %s/%s!!!\n", tmp_out_dir, entry->d_name); ++count; } EXPECT_EQ(count, 0U); } snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); } static int logrotate_count_id(const char* logcat_cmd, const char* tmp_out_dir) { static const char log_filename[] = "log.txt"; char command[strlen(tmp_out_dir) + strlen(logcat_cmd) + strlen(log_filename) + 32]; snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); int ret = system(command); if (ret) { fprintf(stderr, "system(\"%s\")=%d", command, ret); return -1; } std::unique_ptr dir(opendir(tmp_out_dir), closedir); if (!dir) { fprintf(stderr, "opendir(\"%s\") failed", tmp_out_dir); return -1; } struct dirent* entry; int count = 0; while ((entry = readdir(dir.get()))) { if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { continue; } ++count; } return count; } TEST(logcat, logrotate_id) { static const char logcat_cmd[] = logcat_executable " -b all -d -f %s/%s -n 32 -r 1 --id=test"; static const char logcat_short_cmd[] = logcat_executable " -b all -t 10 -f %s/%s -n 32 -r 1 --id=test"; static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; static const char log_filename[] = "log.txt"; char tmp_out_dir[strlen(tmp_out_dir_form) + 1]; ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); EXPECT_EQ(logrotate_count_id(logcat_cmd, tmp_out_dir), 34); EXPECT_EQ(logrotate_count_id(logcat_short_cmd, tmp_out_dir), 34); char id_file[strlen(tmp_out_dir_form) + strlen(log_filename) + 5]; snprintf(id_file, sizeof(id_file), "%s/%s.id", tmp_out_dir, log_filename); if (getuid() != 0) { chmod(id_file, 0); EXPECT_EQ(logrotate_count_id(logcat_short_cmd, tmp_out_dir), 34); } unlink(id_file); EXPECT_EQ(logrotate_count_id(logcat_short_cmd, tmp_out_dir), 34); FILE* fp = fopen(id_file, "w"); if (fp) { fprintf(fp, "not_a_test"); fclose(fp); } if (getuid() != 0) { chmod(id_file, 0); // API to preserve content even with signature change ASSERT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); chmod(id_file, 0600); } int new_signature; EXPECT_GE( (new_signature = logrotate_count_id(logcat_short_cmd, tmp_out_dir)), 2); EXPECT_LT(new_signature, 34); static const char cleanup_cmd[] = "rm -rf %s"; char command[strlen(cleanup_cmd) + strlen(tmp_out_dir_form)]; snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(IsFalse(system(command), command)); } TEST(logcat, logrotate_nodir) { // expect logcat to error out on writing content and not exit(0) for nodir static const char command[] = logcat_executable " -b all -d" " -f /das/nein/gerfingerpoken/logcat/log.txt" " -n 256 -r 1024"; EXPECT_FALSE(IsFalse(0 == system(command), command)); } #ifndef logcat static void caught_blocking_clear(int signum) { unsigned long long v = 0xDEADBEEFA55C0000ULL; v += getpid() & 0xFFFF; if (signum == 0) ++v; 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 -g 2>&1 ;" " logcat -v brief -b events 2>&1", "r"))); char buffer[BIG_BUFFER]; int count = 0; int minus_g = 0; int signals = 0; signal(SIGALRM, caught_blocking_clear); alarm(2); while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(buffer, "clearLog: ", strlen("clearLog: "))) { fprintf(stderr, "WARNING: Test lacks permission to run :-(\n"); count = signals = 1; break; } if (!strncmp(buffer, "failed to clear", strlen("failed to clear"))) { fprintf(stderr, "WARNING: Test lacks permission to run :-(\n"); count = signals = 1; break; } if (!strncmp(buffer, "DONE", 4)) { break; } int size, consumed, max, payload; char size_mult[4], consumed_mult[4]; size = consumed = max = payload = 0; if (6 == sscanf(buffer, "events: ring buffer is %d %3s (%d %3s consumed)," " max entry is %d B, max payload is %d B", &size, size_mult, &consumed, consumed_mult, &max, &payload)) { long full_size = size, full_consumed = consumed; switch (size_mult[0]) { case 'G': full_size *= 1024; FALLTHROUGH_INTENDED; case 'M': full_size *= 1024; FALLTHROUGH_INTENDED; case 'K': full_size *= 1024; FALLTHROUGH_INTENDED; case 'B': break; } switch (consumed_mult[0]) { case 'G': full_consumed *= 1024; FALLTHROUGH_INTENDED; case 'M': full_consumed *= 1024; FALLTHROUGH_INTENDED; case 'K': full_consumed *= 1024; FALLTHROUGH_INTENDED; case 'B': break; } EXPECT_GT(full_size, full_consumed); EXPECT_GT(full_size, max); EXPECT_GT(max, payload); EXPECT_GT(max, full_consumed); ++minus_g; continue; } ++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_GE(count, 1); EXPECT_EQ(minus_g, 1); EXPECT_EQ(signals, 1); } #endif static bool get_prune_rules(char** list) { FILE* fp = popen(logcat_executable " -p 2>/dev/null", "r"); if (fp == NULL) { fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n"); return false; } char buffer[BIG_BUFFER]; 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_prune_rules(const char* list) { char buffer[BIG_BUFFER]; snprintf(buffer, sizeof(buffer), logcat_executable " -P '%s' 2>&1", list ? list : ""); FILE* 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 ((end > buf) && isspace(*--end)) { *end = '\0'; } if (end <= buf) { continue; } fprintf(stderr, "%s\n", buf); pclose(fp); return false; } return pclose(fp) == 0; } TEST(logcat, prune_rules_adjust) { char* list = NULL; char* adjust = NULL; get_prune_rules(&list); static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30"; ASSERT_EQ(true, set_prune_rules(adjustment)); ASSERT_EQ(true, get_prune_rules(&adjust)); EXPECT_STREQ(adjustment, adjust); free(adjust); adjust = NULL; static const char adjustment2[] = "300/20 300/21 2000 ~1000"; ASSERT_EQ(true, set_prune_rules(adjustment2)); ASSERT_EQ(true, get_prune_rules(&adjust)); EXPECT_STREQ(adjustment2, adjust); free(adjust); adjust = NULL; ASSERT_EQ(true, set_prune_rules(list)); get_prune_rules(&adjust); EXPECT_STREQ(list ? list : "", adjust ? adjust : ""); free(adjust); adjust = NULL; free(list); list = NULL; } TEST(logcat, regex) { FILE* fp; int count = 0; char buffer[BIG_BUFFER]; #define logcat_regex_prefix logcat_executable "_test" snprintf(buffer, sizeof(buffer), logcat_executable " --pid %d -d -e " logcat_regex_prefix "_a+b", getpid()); LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, logcat_regex_prefix "_ab")); LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, logcat_regex_prefix "_b")); LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, logcat_regex_prefix "_aaaab")); LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, logcat_regex_prefix "_aaaa")); // Let the logs settle rest(); ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(begin, buffer, sizeof(begin) - 1)) { continue; } EXPECT_TRUE(strstr(buffer, logcat_regex_prefix "_") != NULL); count++; } pclose(fp); ASSERT_EQ(2, count); } TEST(logcat, maxcount) { FILE* fp; int count = 0; char buffer[BIG_BUFFER]; snprintf(buffer, sizeof(buffer), logcat_executable " --pid %d -d --max-count 3", getpid()); LOG_FAILURE_RETRY( __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); LOG_FAILURE_RETRY( __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); LOG_FAILURE_RETRY( __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); LOG_FAILURE_RETRY( __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); rest(); ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); while (fgets(buffer, sizeof(buffer), fp)) { if (!strncmp(begin, buffer, sizeof(begin) - 1)) { continue; } count++; } pclose(fp); ASSERT_EQ(3, count); } static bool End_to_End(const char* tag, const char* fmt, ...) #if defined(__GNUC__) __attribute__((__format__(printf, 2, 3))) #endif ; static bool End_to_End(const char* tag, const char* fmt, ...) { FILE* fp = popen(logcat_executable " -v brief -b events -v descriptive -t 100 2>/dev/null", "r"); if (!fp) { fprintf(stderr, "End_to_End: popen failed"); return false; } char buffer[BIG_BUFFER]; va_list ap; va_start(ap, fmt); vsnprintf(buffer, sizeof(buffer), fmt, ap); va_end(ap); char* str = NULL; asprintf(&str, "I/%s ( %%d):%%c%s%%c", tag, buffer); std::string expect(str); free(str); int count = 0; pid_t pid = getpid(); std::string lastMatch; int maxMatch = 1; while (fgets(buffer, sizeof(buffer), fp)) { char space; char newline; int p; int ret = sscanf(buffer, expect.c_str(), &p, &space, &newline); if ((ret == 3) && (p == pid) && (space == ' ') && (newline == '\n')) { ++count; } else if ((ret >= maxMatch) && (p == pid) && (count == 0)) { lastMatch = buffer; maxMatch = ret; } } pclose(fp); if ((count == 0) && (lastMatch.length() > 0)) { // Help us pinpoint where things went wrong ... fprintf(stderr, "Closest match for\n %s\n is\n %s", expect.c_str(), lastMatch.c_str()); } else if (count > 3) { fprintf(stderr, "Too many matches (%d) for %s\n", count, expect.c_str()); } // Three different known tests, we can see pollution from the others return count && (count <= 3); } TEST(logcat, descriptive) { struct tag { uint32_t tagNo; const char* tagStr; }; int ret; { static const struct tag hhgtg = { 42, "answer" }; android_log_event_list ctx(hhgtg.tagNo); static const char theAnswer[] = "what is five by seven"; ctx << theAnswer; // crafted to rest at least once after, and rest between retries. for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE( End_to_End(hhgtg.tagStr, "to life the universe etc=%s", theAnswer)); } { static const struct tag sync = { 2720, "sync" }; static const char id[] = logcat_executable ".descriptive-sync"; { android_log_event_list ctx(sync.tagNo); ctx << id << (int32_t)42 << (int32_t)-1 << (int32_t)0; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "[id=%s,event=42,source=-1,account=0]", id)); } // Partial match to description { android_log_event_list ctx(sync.tagNo); ctx << id << (int32_t)43 << (int64_t)-1 << (int32_t)0; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "[id=%s,event=43,-1,0]", id)); } // Negative Test of End_to_End, ensure it is working { android_log_event_list ctx(sync.tagNo); ctx << id << (int32_t)44 << (int32_t)-1 << (int64_t)0; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); fprintf(stderr, "Expect a \"Closest match\" message\n"); EXPECT_FALSE(End_to_End( sync.tagStr, "[id=%s,event=44,source=-1,account=0]", id)); } } { static const struct tag sync = { 2747, "contacts_aggregation" }; { android_log_event_list ctx(sync.tagNo); ctx << (uint64_t)30 << (int32_t)2; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE( End_to_End(sync.tagStr, "[aggregation time=30ms,count=2]")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint64_t)31570 << (int32_t)911; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE( End_to_End(sync.tagStr, "[aggregation time=31.57s,count=911]")); } } { static const struct tag sync = { 75000, "sqlite_mem_alarm_current" }; { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)512; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "current=512B")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)3072; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "current=3KB")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)2097152; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "current=2MB")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)2097153; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "current=2097153B")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)1073741824; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "current=1GB")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)3221225472; // 3MB, but on purpose overflowed for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "current=-1GB")); } } { static const struct tag sync = { 27501, "notification_panel_hidden" }; android_log_event_list ctx(sync.tagNo); for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "")); } { // Invent new entries because existing can not serve EventTagMap* map = android_openEventTagMap(nullptr); ASSERT_TRUE(nullptr != map); static const char name[] = logcat_executable ".descriptive-monotonic"; int myTag = android_lookupEventTagNum(map, name, "(new|1|s)", ANDROID_LOG_UNKNOWN); android_closeEventTagMap(map); ASSERT_NE(-1, myTag); const struct tag sync = { (uint32_t)myTag, name }; { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)7; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "new=7s")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)62; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "new=1:02")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)3673; for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "new=1:01:13")); } { android_log_event_list ctx(sync.tagNo); ctx << (uint32_t)(86400 + 7200 + 180 + 58); for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write(); EXPECT_GE(ret, 0); EXPECT_TRUE(End_to_End(sync.tagStr, "new=1d 2:03:58")); } } } static bool reportedSecurity(const char* command) { FILE* fp = popen(command, "r"); if (!fp) return true; std::string ret; bool val = android::base::ReadFdToString(fileno(fp), &ret); pclose(fp); if (!val) return true; return std::string::npos != ret.find("'security'"); } TEST(logcat, security) { EXPECT_FALSE(reportedSecurity(logcat_executable " -b all -g 2>&1")); EXPECT_TRUE(reportedSecurity(logcat_executable " -b security -g 2>&1")); EXPECT_TRUE(reportedSecurity(logcat_executable " -b security -c 2>&1")); EXPECT_TRUE( reportedSecurity(logcat_executable " -b security -G 256K 2>&1")); } static size_t commandOutputSize(const char* command) { FILE* fp = popen(command, "r"); if (!fp) return 0; std::string ret; if (!android::base::ReadFdToString(fileno(fp), &ret)) return 0; if (pclose(fp) != 0) return 0; return ret.size(); } TEST(logcat, help) { size_t logcatHelpTextSize = commandOutputSize(logcat_executable " -h 2>&1"); EXPECT_GT(logcatHelpTextSize, 4096UL); size_t logcatLastHelpTextSize = commandOutputSize(logcat_executable " -L -h 2>&1"); #ifdef USING_LOGCAT_EXECUTABLE_DEFAULT // logcat and liblogcat EXPECT_EQ(logcatHelpTextSize, logcatLastHelpTextSize); #else // logcatd -L -h prints the help twice, as designed. EXPECT_EQ(logcatHelpTextSize * 2, logcatLastHelpTextSize); #endif } TEST(logcat, invalid_buffer) { FILE* fp = popen("logcat -b foo 2>&1", "r"); ASSERT_NE(nullptr, fp); std::string output; ASSERT_TRUE(android::base::ReadFdToString(fileno(fp), &output)); pclose(fp); ASSERT_TRUE(android::base::StartsWith(output, "unknown buffer foo\n")); } static void SniffUid(const std::string& line, uid_t& uid) { auto uid_regex = std::regex{"\\S+\\s+\\S+\\s+(\\S+).*"}; auto trimmed_line = android::base::Trim(line); std::smatch match_results; ASSERT_TRUE(std::regex_match(trimmed_line, match_results, uid_regex)) << "Unable to find UID in line '" << trimmed_line << "'"; auto uid_string = match_results[1]; if (!android::base::ParseUint(uid_string, &uid)) { auto pwd = getpwnam(uid_string.str().c_str()); ASSERT_NE(nullptr, pwd) << "uid '" << uid_string << "' in line '" << trimmed_line << "'"; uid = pwd->pw_uid; } } static void UidsInLog(std::optional> filter_uid, std::map& uids) { std::string command; if (filter_uid) { std::vector uid_strings; for (const auto& uid : *filter_uid) { uid_strings.emplace_back(std::to_string(uid)); } command = android::base::StringPrintf(logcat_executable " -v uid -b all -d 2>/dev/null --uid=%s", android::base::Join(uid_strings, ",").c_str()); } else { command = logcat_executable " -v uid -b all -d 2>/dev/null"; } auto fp = std::unique_ptr(popen(command.c_str(), "r"), pclose); ASSERT_NE(nullptr, fp); char buffer[BIG_BUFFER]; while (fgets(buffer, sizeof(buffer), fp.get())) { // Ignore dividers, e.g. '--------- beginning of radio' if (android::base::StartsWith(buffer, "---------")) { continue; } uid_t uid; SniffUid(buffer, uid); uids[uid]++; } } static std::vector TopTwoInMap(const std::map& uids) { std::pair top = {0, 0}; std::pair second = {0, 0}; for (const auto& [uid, count] : uids) { if (count > top.second) { top = second; top = {uid, count}; } else if (count > second.second) { second = {uid, count}; } } return {top.first, second.first}; } TEST(logcat, uid_filter) { std::map uids; UidsInLog({}, uids); ASSERT_GT(uids.size(), 2U); auto top_uids = TopTwoInMap(uids); // Test filtering with --uid= std::map uids_only_top; std::vector top_uid = {top_uids[0]}; UidsInLog(top_uid, uids_only_top); EXPECT_EQ(1U, uids_only_top.size()); // Test filtering with --uid=,<2nd top uid> std::map uids_only_top2; std::vector top2_uids = {top_uids[0], top_uids[1]}; UidsInLog(top2_uids, uids_only_top2); EXPECT_EQ(2U, uids_only_top2.size()); }