/* * 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 <ctype.h> #include <signal.h> #include <stdio.h> #include <stdlib.h> #include <string.h> #include <gtest/gtest.h> #include <log/log.h> #include <log/logger.h> #include <log/log_read.h> // 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; 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 -v brief -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_size) { FILE *fp; // NB: crash log only available in user space ASSERT_TRUE(NULL != (fp = popen( "logcat -v brief -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; char size_mult[2], consumed_mult[2]; 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. if (6 != sscanf(buffer, "%*s ring buffer is %d%2s (%d%2s consumed)," " max entry is %db, max payload is %db", &size, size_mult, &consumed, consumed_mult, &max, &payload)) { fprintf(stderr, "WARNING: Parse error: %s", buffer); continue; } full_size = size; switch(size_mult[0]) { case 'G': full_size *= 1024; /* FALLTHRU */ case 'M': full_size *= 1024; /* FALLTHRU */ case 'K': full_size *= 1024; /* FALLTHRU */ case 'b': break; } full_consumed = consumed; switch(consumed_mult[0]) { case 'G': full_consumed *= 1024; /* FALLTHRU */ case 'M': full_consumed *= 1024; /* FALLTHRU */ case 'K': full_consumed *= 1024; /* FALLTHRU */ case 'b': break; } 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); 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 -v brief -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 -v brief -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); } 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 -b radio -b events -b system -b main" " -d -f %s/log.txt -n 7 -r 1"; char command[sizeof(buf) + sizeof(comm)]; sprintf(command, comm, buf); int ret; EXPECT_FALSE((ret = system(command))); if (!ret) { sprintf(command, "ls -s %s 2>/dev/null", buf); FILE *fp; EXPECT_TRUE(NULL != (fp = popen(command, "r"))); if (fp) { char buffer[5120]; int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { static const char match_1[] = "4 log.txt"; static const char match_2[] = "8 log.txt"; static const char match_3[] = "12 log.txt"; static const char match_4[] = "16 log.txt"; static const char total[] = "total "; if (!strncmp(buffer, match_1, sizeof(match_1) - 1) || !strncmp(buffer, match_2, sizeof(match_2) - 1) || !strncmp(buffer, match_3, sizeof(match_3) - 1) || !strncmp(buffer, match_4, sizeof(match_4) - 1)) { ++count; } else if (strncmp(buffer, total, sizeof(total) - 1)) { fprintf(stderr, "WARNING: Parse error: %s", buffer); } } pclose(fp); EXPECT_TRUE(count == 7 || count == 8); } } sprintf(command, "rm -rf %s", buf); EXPECT_FALSE(system(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 -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)]; sprintf(command, logcat_cmd, tmp_out_dir); int ret; EXPECT_FALSE((ret = system(command))); if (!ret) { sprintf(command, "ls %s 2>/dev/null", tmp_out_dir); FILE *fp; EXPECT_TRUE(NULL != (fp = popen(command, "r"))); char buffer[5120]; 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(11, log_file_count); } sprintf(command, "rm -rf %s", tmp_out_dir); EXPECT_FALSE(system(command)); } 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 -v brief -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 ? 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 ((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, white_black_adjust) { char *list = NULL; char *adjust = NULL; 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)); get_white_black(&adjust); EXPECT_STREQ(list ? list : "", adjust ? adjust : ""); free(adjust); adjust = NULL; free(list); list = NULL; }