logcat_test.cpp revision eba7344fc1aca4ae232b881fdf6c5b16e6f59bc9
1/* 2 * Copyright (C) 2013-2014 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17#include <ctype.h> 18#include <signal.h> 19#include <stdio.h> 20#include <stdlib.h> 21#include <string.h> 22 23#include <gtest/gtest.h> 24#include <log/log.h> 25#include <log/logger.h> 26#include <log/log_read.h> 27 28// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and 29// non-syscall libs. Since we are only using this in the emergency of 30// a signal to stuff a terminating code into the logs, we will spin rather 31// than try a usleep. 32#define LOG_FAILURE_RETRY(exp) ({ \ 33 typeof (exp) _rc; \ 34 do { \ 35 _rc = (exp); \ 36 } while (((_rc == -1) \ 37 && ((errno == EINTR) \ 38 || (errno == EAGAIN))) \ 39 || (_rc == -EINTR) \ 40 || (_rc == -EAGAIN)); \ 41 _rc; }) 42 43static const char begin[] = "--------- beginning of "; 44 45TEST(logcat, buckets) { 46 FILE *fp; 47 48 ASSERT_TRUE(NULL != (fp = popen( 49 "logcat -b radio -b events -b system -b main -d 2>/dev/null", 50 "r"))); 51 52 char buffer[5120]; 53 54 int ids = 0; 55 int count = 0; 56 57 while (fgets(buffer, sizeof(buffer), fp)) { 58 if (!strncmp(begin, buffer, sizeof(begin) - 1)) { 59 while (char *cp = strrchr(buffer, '\n')) { 60 *cp = '\0'; 61 } 62 log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1); 63 ids |= 1 << id; 64 ++count; 65 } 66 } 67 68 pclose(fp); 69 70 EXPECT_EQ(15, ids); 71 72 EXPECT_EQ(4, count); 73} 74 75TEST(logcat, tail_3) { 76 FILE *fp; 77 78 ASSERT_TRUE(NULL != (fp = popen( 79 "logcat -v long -b radio -b events -b system -b main -t 3 2>/dev/null", 80 "r"))); 81 82 char buffer[5120]; 83 84 int count = 0; 85 86 while (fgets(buffer, sizeof(buffer), fp)) { 87 if ((buffer[0] == '[') && (buffer[1] == ' ') 88 && isdigit(buffer[2]) && isdigit(buffer[3]) 89 && (buffer[4] == '-')) { 90 ++count; 91 } 92 } 93 94 pclose(fp); 95 96 ASSERT_EQ(3, count); 97} 98 99TEST(logcat, tail_10) { 100 FILE *fp; 101 102 ASSERT_TRUE(NULL != (fp = popen( 103 "logcat -v long -b radio -b events -b system -b main -t 10 2>/dev/null", 104 "r"))); 105 106 char buffer[5120]; 107 108 int count = 0; 109 110 while (fgets(buffer, sizeof(buffer), fp)) { 111 if ((buffer[0] == '[') && (buffer[1] == ' ') 112 && isdigit(buffer[2]) && isdigit(buffer[3]) 113 && (buffer[4] == '-')) { 114 ++count; 115 } 116 } 117 118 pclose(fp); 119 120 ASSERT_EQ(10, count); 121} 122 123TEST(logcat, tail_100) { 124 FILE *fp; 125 126 ASSERT_TRUE(NULL != (fp = popen( 127 "logcat -v long -b radio -b events -b system -b main -t 100 2>/dev/null", 128 "r"))); 129 130 char buffer[5120]; 131 132 int count = 0; 133 134 while (fgets(buffer, sizeof(buffer), fp)) { 135 if ((buffer[0] == '[') && (buffer[1] == ' ') 136 && isdigit(buffer[2]) && isdigit(buffer[3]) 137 && (buffer[4] == '-')) { 138 ++count; 139 } 140 } 141 142 pclose(fp); 143 144 ASSERT_EQ(100, count); 145} 146 147TEST(logcat, tail_1000) { 148 FILE *fp; 149 150 ASSERT_TRUE(NULL != (fp = popen( 151 "logcat -v long -b radio -b events -b system -b main -t 1000 2>/dev/null", 152 "r"))); 153 154 char buffer[5120]; 155 156 int count = 0; 157 158 while (fgets(buffer, sizeof(buffer), fp)) { 159 if ((buffer[0] == '[') && (buffer[1] == ' ') 160 && isdigit(buffer[2]) && isdigit(buffer[3]) 161 && (buffer[4] == '-')) { 162 ++count; 163 } 164 } 165 166 pclose(fp); 167 168 ASSERT_EQ(1000, count); 169} 170 171TEST(logcat, tail_time) { 172 FILE *fp; 173 174 ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r"))); 175 176 char buffer[5120]; 177 char *last_timestamp = NULL; 178 char *first_timestamp = NULL; 179 int count = 0; 180 const unsigned int time_length = 18; 181 const unsigned int time_offset = 2; 182 183 while (fgets(buffer, sizeof(buffer), fp)) { 184 if ((buffer[0] == '[') && (buffer[1] == ' ') 185 && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1]) 186 && (buffer[time_offset + 2] == '-')) { 187 ++count; 188 buffer[time_length + time_offset] = '\0'; 189 if (!first_timestamp) { 190 first_timestamp = strdup(buffer + time_offset); 191 } 192 free(last_timestamp); 193 last_timestamp = strdup(buffer + time_offset); 194 } 195 } 196 pclose(fp); 197 198 EXPECT_EQ(10, count); 199 EXPECT_TRUE(last_timestamp != NULL); 200 EXPECT_TRUE(first_timestamp != NULL); 201 202 snprintf(buffer, sizeof(buffer), "logcat -v long -b all -t '%s' 2>&1", 203 first_timestamp); 204 ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); 205 206 int second_count = 0; 207 int last_timestamp_count = -1; 208 209 while (fgets(buffer, sizeof(buffer), fp)) { 210 if ((buffer[0] == '[') && (buffer[1] == ' ') 211 && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1]) 212 && (buffer[time_offset + 2] == '-')) { 213 ++second_count; 214 buffer[time_length + time_offset] = '\0'; 215 if (first_timestamp) { 216 // we can get a transitory *extremely* rare failure if hidden 217 // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000 218 EXPECT_STREQ(buffer + time_offset, first_timestamp); 219 free(first_timestamp); 220 first_timestamp = NULL; 221 } 222 if (!strcmp(buffer + time_offset, last_timestamp)) { 223 last_timestamp_count = second_count; 224 } 225 } 226 } 227 pclose(fp); 228 229 free(last_timestamp); 230 last_timestamp = NULL; 231 232 EXPECT_TRUE(first_timestamp == NULL); 233 EXPECT_LE(count, second_count); 234 EXPECT_LE(count, last_timestamp_count); 235} 236 237TEST(logcat, End_to_End) { 238 pid_t pid = getpid(); 239 240 log_time ts(CLOCK_MONOTONIC); 241 242 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); 243 244 FILE *fp; 245 ASSERT_TRUE(NULL != (fp = popen( 246 "logcat -v brief -b events -t 100 2>/dev/null", 247 "r"))); 248 249 char buffer[5120]; 250 251 int count = 0; 252 253 while (fgets(buffer, sizeof(buffer), fp)) { 254 int p; 255 unsigned long long t; 256 257 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) 258 || (p != pid)) { 259 continue; 260 } 261 262 log_time tx((const char *) &t); 263 if (ts == tx) { 264 ++count; 265 } 266 } 267 268 pclose(fp); 269 270 ASSERT_EQ(1, count); 271} 272 273TEST(logcat, get_size) { 274 FILE *fp; 275 276 // NB: crash log only available in user space 277 ASSERT_TRUE(NULL != (fp = popen( 278 "logcat -v brief -b radio -b events -b system -b main -g 2>/dev/null", 279 "r"))); 280 281 char buffer[5120]; 282 283 int count = 0; 284 285 while (fgets(buffer, sizeof(buffer), fp)) { 286 int size, consumed, max, payload; 287 char size_mult[2], consumed_mult[2]; 288 long full_size, full_consumed; 289 290 size = consumed = max = payload = 0; 291 // NB: crash log can be very small, not hit a Kb of consumed space 292 // doubly lucky we are not including it. 293 if (6 != sscanf(buffer, "%*s ring buffer is %d%2s (%d%2s consumed)," 294 " max entry is %db, max payload is %db", 295 &size, size_mult, &consumed, consumed_mult, 296 &max, &payload)) { 297 fprintf(stderr, "WARNING: Parse error: %s", buffer); 298 continue; 299 } 300 full_size = size; 301 switch(size_mult[0]) { 302 case 'G': 303 full_size *= 1024; 304 /* FALLTHRU */ 305 case 'M': 306 full_size *= 1024; 307 /* FALLTHRU */ 308 case 'K': 309 full_size *= 1024; 310 /* FALLTHRU */ 311 case 'b': 312 break; 313 } 314 full_consumed = consumed; 315 switch(consumed_mult[0]) { 316 case 'G': 317 full_consumed *= 1024; 318 /* FALLTHRU */ 319 case 'M': 320 full_consumed *= 1024; 321 /* FALLTHRU */ 322 case 'K': 323 full_consumed *= 1024; 324 /* FALLTHRU */ 325 case 'b': 326 break; 327 } 328 EXPECT_GT((full_size * 9) / 4, full_consumed); 329 EXPECT_GT(full_size, max); 330 EXPECT_GT(max, payload); 331 332 if ((((full_size * 9) / 4) >= full_consumed) 333 && (full_size > max) 334 && (max > payload)) { 335 ++count; 336 } 337 } 338 339 pclose(fp); 340 341 ASSERT_EQ(4, count); 342} 343 344static void caught_blocking(int /*signum*/) 345{ 346 unsigned long long v = 0xDEADBEEFA55A0000ULL; 347 348 v += getpid() & 0xFFFF; 349 350 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 351} 352 353TEST(logcat, blocking) { 354 FILE *fp; 355 unsigned long long v = 0xDEADBEEFA55F0000ULL; 356 357 pid_t pid = getpid(); 358 359 v += pid & 0xFFFF; 360 361 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 362 363 v &= 0xFFFFFFFFFFFAFFFFULL; 364 365 ASSERT_TRUE(NULL != (fp = popen( 366 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" 367 " logcat -v brief -b events 2>&1", 368 "r"))); 369 370 char buffer[5120]; 371 372 int count = 0; 373 374 int signals = 0; 375 376 signal(SIGALRM, caught_blocking); 377 alarm(2); 378 while (fgets(buffer, sizeof(buffer), fp)) { 379 380 if (!strncmp(buffer, "DONE", 4)) { 381 break; 382 } 383 384 ++count; 385 386 int p; 387 unsigned long long l; 388 389 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) 390 || (p != pid)) { 391 continue; 392 } 393 394 if (l == v) { 395 ++signals; 396 break; 397 } 398 } 399 alarm(0); 400 signal(SIGALRM, SIG_DFL); 401 402 // Generate SIGPIPE 403 fclose(fp); 404 caught_blocking(0); 405 406 pclose(fp); 407 408 EXPECT_LE(2, count); 409 410 EXPECT_EQ(1, signals); 411} 412 413static void caught_blocking_tail(int /*signum*/) 414{ 415 unsigned long long v = 0xA55ADEADBEEF0000ULL; 416 417 v += getpid() & 0xFFFF; 418 419 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 420} 421 422TEST(logcat, blocking_tail) { 423 FILE *fp; 424 unsigned long long v = 0xA55FDEADBEEF0000ULL; 425 426 pid_t pid = getpid(); 427 428 v += pid & 0xFFFF; 429 430 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 431 432 v &= 0xFFFAFFFFFFFFFFFFULL; 433 434 ASSERT_TRUE(NULL != (fp = popen( 435 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" 436 " logcat -v brief -b events -T 5 2>&1", 437 "r"))); 438 439 char buffer[5120]; 440 441 int count = 0; 442 443 int signals = 0; 444 445 signal(SIGALRM, caught_blocking_tail); 446 alarm(2); 447 while (fgets(buffer, sizeof(buffer), fp)) { 448 449 if (!strncmp(buffer, "DONE", 4)) { 450 break; 451 } 452 453 ++count; 454 455 int p; 456 unsigned long long l; 457 458 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) 459 || (p != pid)) { 460 continue; 461 } 462 463 if (l == v) { 464 if (count >= 5) { 465 ++signals; 466 } 467 break; 468 } 469 } 470 alarm(0); 471 signal(SIGALRM, SIG_DFL); 472 473 // Generate SIGPIPE 474 fclose(fp); 475 caught_blocking_tail(0); 476 477 pclose(fp); 478 479 EXPECT_LE(2, count); 480 481 EXPECT_EQ(1, signals); 482} 483 484TEST(logcat, logrotate) { 485 static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; 486 char buf[sizeof(form)]; 487 ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form))); 488 489 static const char comm[] = "logcat -b radio -b events -b system -b main" 490 " -d -f %s/log.txt -n 7 -r 1"; 491 char command[sizeof(buf) + sizeof(comm)]; 492 sprintf(command, comm, buf); 493 494 int ret; 495 EXPECT_FALSE((ret = system(command))); 496 if (!ret) { 497 sprintf(command, "ls -s %s 2>/dev/null", buf); 498 499 FILE *fp; 500 EXPECT_TRUE(NULL != (fp = popen(command, "r"))); 501 if (fp) { 502 char buffer[5120]; 503 int count = 0; 504 505 while (fgets(buffer, sizeof(buffer), fp)) { 506 static const char match_1[] = "4 log.txt"; 507 static const char match_2[] = "8 log.txt"; 508 static const char match_3[] = "16 log.txt"; 509 static const char total[] = "total "; 510 511 if (!strncmp(buffer, match_1, sizeof(match_1) - 1) 512 || !strncmp(buffer, match_2, sizeof(match_2) - 1) 513 || !strncmp(buffer, match_3, sizeof(match_3) - 1)) { 514 ++count; 515 } else if (strncmp(buffer, total, sizeof(total) - 1)) { 516 fprintf(stderr, "WARNING: Parse error: %s", buffer); 517 } 518 } 519 pclose(fp); 520 EXPECT_TRUE(count == 7 || count == 8); 521 } 522 } 523 sprintf(command, "rm -rf %s", buf); 524 EXPECT_FALSE(system(command)); 525} 526 527TEST(logcat, logrotate_suffix) { 528 static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; 529 char tmp_out_dir[sizeof(tmp_out_dir_form)]; 530 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); 531 532 static const char logcat_cmd[] = "logcat -b radio -b events -b system -b main" 533 " -d -f %s/log.txt -n 10 -r 1"; 534 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)]; 535 sprintf(command, logcat_cmd, tmp_out_dir); 536 537 int ret; 538 EXPECT_FALSE((ret = system(command))); 539 if (!ret) { 540 sprintf(command, "ls %s 2>/dev/null", tmp_out_dir); 541 542 FILE *fp; 543 EXPECT_TRUE(NULL != (fp = popen(command, "r"))); 544 char buffer[5120]; 545 int log_file_count = 0; 546 547 while (fgets(buffer, sizeof(buffer), fp)) { 548 static const char rotated_log_filename_prefix[] = "log.txt."; 549 static const size_t rotated_log_filename_prefix_len = 550 strlen(rotated_log_filename_prefix); 551 static const char total[] = "total "; 552 static const char log_filename[] = "log.txt"; 553 554 if (!strncmp(buffer, rotated_log_filename_prefix, rotated_log_filename_prefix_len)) { 555 // Rotated file should have form log.txt.## 556 char* rotated_log_filename_suffix = buffer + rotated_log_filename_prefix_len; 557 char* endptr; 558 const long int suffix_value = strtol(rotated_log_filename_suffix, &endptr, 10); 559 EXPECT_EQ(rotated_log_filename_suffix + 2, endptr); 560 EXPECT_LE(suffix_value, 10); 561 EXPECT_GT(suffix_value, 0); 562 ++log_file_count; 563 continue; 564 } 565 566 if (!strncmp(buffer, log_filename, strlen(log_filename))) { 567 ++log_file_count; 568 continue; 569 } 570 571 fprintf(stderr, "ERROR: Unexpected file: %s", buffer); 572 ADD_FAILURE(); 573 } 574 pclose(fp); 575 EXPECT_EQ(11, log_file_count); 576 } 577 sprintf(command, "rm -rf %s", tmp_out_dir); 578 EXPECT_FALSE(system(command)); 579} 580 581static void caught_blocking_clear(int /*signum*/) 582{ 583 unsigned long long v = 0xDEADBEEFA55C0000ULL; 584 585 v += getpid() & 0xFFFF; 586 587 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 588} 589 590TEST(logcat, blocking_clear) { 591 FILE *fp; 592 unsigned long long v = 0xDEADBEEFA55C0000ULL; 593 594 pid_t pid = getpid(); 595 596 v += pid & 0xFFFF; 597 598 // This test is racey; an event occurs between clear and dump. 599 // We accept that we will get a false positive, but never a false negative. 600 ASSERT_TRUE(NULL != (fp = popen( 601 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" 602 " logcat -b events -c 2>&1 ;" 603 " logcat -v brief -b events 2>&1", 604 "r"))); 605 606 char buffer[5120]; 607 608 int count = 0; 609 610 int signals = 0; 611 612 signal(SIGALRM, caught_blocking_clear); 613 alarm(2); 614 while (fgets(buffer, sizeof(buffer), fp)) { 615 616 if (!strncmp(buffer, "clearLog: ", 10)) { 617 fprintf(stderr, "WARNING: Test lacks permission to run :-(\n"); 618 count = signals = 1; 619 break; 620 } 621 622 if (!strncmp(buffer, "DONE", 4)) { 623 break; 624 } 625 626 ++count; 627 628 int p; 629 unsigned long long l; 630 631 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) 632 || (p != pid)) { 633 continue; 634 } 635 636 if (l == v) { 637 if (count > 1) { 638 fprintf(stderr, "WARNING: Possible false positive\n"); 639 } 640 ++signals; 641 break; 642 } 643 } 644 alarm(0); 645 signal(SIGALRM, SIG_DFL); 646 647 // Generate SIGPIPE 648 fclose(fp); 649 caught_blocking_clear(0); 650 651 pclose(fp); 652 653 EXPECT_LE(1, count); 654 655 EXPECT_EQ(1, signals); 656} 657 658static bool get_white_black(char **list) { 659 FILE *fp; 660 661 fp = popen("logcat -p 2>/dev/null", "r"); 662 if (fp == NULL) { 663 fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n"); 664 return false; 665 } 666 667 char buffer[5120]; 668 669 while (fgets(buffer, sizeof(buffer), fp)) { 670 char *hold = *list; 671 char *buf = buffer; 672 while (isspace(*buf)) { 673 ++buf; 674 } 675 char *end = buf + strlen(buf); 676 while (isspace(*--end) && (end >= buf)) { 677 *end = '\0'; 678 } 679 if (end < buf) { 680 continue; 681 } 682 if (hold) { 683 asprintf(list, "%s %s", hold, buf); 684 free(hold); 685 } else { 686 asprintf(list, "%s", buf); 687 } 688 } 689 pclose(fp); 690 return *list != NULL; 691} 692 693static bool set_white_black(const char *list) { 694 FILE *fp; 695 696 char buffer[5120]; 697 698 snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list ? list : ""); 699 fp = popen(buffer, "r"); 700 if (fp == NULL) { 701 fprintf(stderr, "ERROR: %s\n", buffer); 702 return false; 703 } 704 705 while (fgets(buffer, sizeof(buffer), fp)) { 706 char *buf = buffer; 707 while (isspace(*buf)) { 708 ++buf; 709 } 710 char *end = buf + strlen(buf); 711 while ((end > buf) && isspace(*--end)) { 712 *end = '\0'; 713 } 714 if (end <= buf) { 715 continue; 716 } 717 fprintf(stderr, "%s\n", buf); 718 pclose(fp); 719 return false; 720 } 721 return pclose(fp) == 0; 722} 723 724TEST(logcat, white_black_adjust) { 725 char *list = NULL; 726 char *adjust = NULL; 727 728 get_white_black(&list); 729 730 static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30"; 731 ASSERT_EQ(true, set_white_black(adjustment)); 732 ASSERT_EQ(true, get_white_black(&adjust)); 733 EXPECT_STREQ(adjustment, adjust); 734 free(adjust); 735 adjust = NULL; 736 737 static const char adjustment2[] = "300/20 300/21 2000 ~1000"; 738 ASSERT_EQ(true, set_white_black(adjustment2)); 739 ASSERT_EQ(true, get_white_black(&adjust)); 740 EXPECT_STREQ(adjustment2, adjust); 741 free(adjust); 742 adjust = NULL; 743 744 ASSERT_EQ(true, set_white_black(list)); 745 get_white_black(&adjust); 746 EXPECT_STREQ(list ? list : "", adjust ? adjust : ""); 747 free(adjust); 748 adjust = NULL; 749 750 free(list); 751 list = NULL; 752} 753