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 <dirent.h> 19 #include <signal.h> 20 #include <stdio.h> 21 #include <stdlib.h> 22 #include <string.h> 23 #include <sys/cdefs.h> 24 #include <sys/stat.h> 25 #include <sys/types.h> 26 #include <sys/wait.h> 27 #include <unistd.h> 28 29 #include <memory> 30 #include <string> 31 32 #include <android-base/file.h> 33 #include <gtest/gtest.h> 34 #include <log/log.h> 35 #include <log/log_event_list.h> 36 37 #ifndef logcat_popen 38 #define logcat_define(context) 39 #define logcat_popen(context, command) popen((command), "r") 40 #define logcat_pclose(context, fp) pclose(fp) 41 #define logcat_system(command) system(command) 42 #endif 43 #ifndef logcat_executable 44 #define USING_LOGCAT_EXECUTABLE_DEFAULT 45 #define logcat_executable "logcat" 46 #endif 47 48 #define BIG_BUFFER (5 * 1024) 49 50 // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and 51 // non-syscall libs. Since we are only using this in the emergency of 52 // a signal to stuff a terminating code into the logs, we will spin rather 53 // than try a usleep. 54 #define LOG_FAILURE_RETRY(exp) \ 55 ({ \ 56 typeof(exp) _rc; \ 57 do { \ 58 _rc = (exp); \ 59 } while (((_rc == -1) && ((errno == EINTR) || (errno == EAGAIN))) || \ 60 (_rc == -EINTR) || (_rc == -EAGAIN)); \ 61 _rc; \ 62 }) 63 64 static const char begin[] = "--------- beginning of "; 65 66 TEST(logcat, buckets) { 67 FILE* fp; 68 logcat_define(ctx); 69 70 #undef LOG_TAG 71 #define LOG_TAG "inject" 72 RLOGE(logcat_executable ".buckets"); 73 sleep(1); 74 75 ASSERT_TRUE(NULL != 76 (fp = logcat_popen( 77 ctx, logcat_executable 78 " -b radio -b events -b system -b main -d 2>/dev/null"))); 79 80 char buffer[BIG_BUFFER]; 81 82 int ids = 0; 83 int count = 0; 84 85 while (fgets(buffer, sizeof(buffer), fp)) { 86 if (!strncmp(begin, buffer, sizeof(begin) - 1)) { 87 while (char* cp = strrchr(buffer, '\n')) { 88 *cp = '\0'; 89 } 90 log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1); 91 ids |= 1 << id; 92 ++count; 93 } 94 } 95 96 logcat_pclose(ctx, fp); 97 98 EXPECT_EQ(15, ids); 99 100 EXPECT_EQ(4, count); 101 } 102 103 TEST(logcat, event_tag_filter) { 104 FILE* fp; 105 logcat_define(ctx); 106 107 ASSERT_TRUE(NULL != 108 (fp = logcat_popen(ctx, logcat_executable 109 " -b events -d -s auditd " 110 "am_proc_start am_pss am_proc_bound " 111 "dvm_lock_sample am_wtf 2>/dev/null"))); 112 113 char buffer[BIG_BUFFER]; 114 115 int count = 0; 116 117 while (fgets(buffer, sizeof(buffer), fp)) { 118 ++count; 119 } 120 121 logcat_pclose(ctx, fp); 122 123 EXPECT_LT(4, count); 124 } 125 126 // If there is not enough background noise in the logs, then spam the logs to 127 // permit tail checking so that the tests can progress. 128 static size_t inject(ssize_t count) { 129 if (count <= 0) return 0; 130 131 static const size_t retry = 4; 132 size_t errors = retry; 133 size_t num = 0; 134 for (;;) { 135 log_time ts(CLOCK_MONOTONIC); 136 if (__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) >= 0) { 137 if (++num >= (size_t)count) { 138 // let data settle end-to-end 139 sleep(3); 140 return num; 141 } 142 errors = retry; 143 usleep(100); // ~32 per timer tick, we are a spammer regardless 144 } else if (--errors <= 0) { 145 return num; 146 } 147 } 148 // NOTREACH 149 return num; 150 } 151 152 TEST(logcat, year) { 153 if (android_log_clockid() == CLOCK_MONOTONIC) { 154 fprintf(stderr, "Skipping test, logd is monotonic time\n"); 155 return; 156 } 157 158 int count; 159 int tries = 3; // in case run too soon after system start or buffer clear 160 161 do { 162 FILE* fp; 163 logcat_define(ctx); 164 165 char needle[32]; 166 time_t now; 167 time(&now); 168 struct tm* ptm; 169 #if !defined(_WIN32) 170 struct tm tmBuf; 171 ptm = localtime_r(&now, &tmBuf); 172 #else 173 ptm = localtime(&&now); 174 #endif 175 strftime(needle, sizeof(needle), "[ %Y-", ptm); 176 177 ASSERT_TRUE(NULL != (fp = logcat_popen( 178 ctx, logcat_executable 179 " -v long -v year -b all -t 3 2>/dev/null"))); 180 181 char buffer[BIG_BUFFER]; 182 183 count = 0; 184 185 while (fgets(buffer, sizeof(buffer), fp)) { 186 if (!strncmp(buffer, needle, strlen(needle))) { 187 ++count; 188 } 189 } 190 logcat_pclose(ctx, fp); 191 192 } while ((count < 3) && --tries && inject(3 - count)); 193 194 ASSERT_EQ(3, count); 195 } 196 197 // Return a pointer to each null terminated -v long time field. 198 static char* fgetLongTime(char* buffer, size_t buflen, FILE* fp) { 199 while (fgets(buffer, buflen, fp)) { 200 char* cp = buffer; 201 if (*cp != '[') { 202 continue; 203 } 204 while (*++cp == ' ') { 205 ; 206 } 207 char* ep = cp; 208 while (isdigit(*ep)) { 209 ++ep; 210 } 211 if ((*ep != '-') && (*ep != '.')) { 212 continue; 213 } 214 // Find PID field. Look for ': ' or ':[0-9][0-9][0-9]' 215 while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) { 216 if (isdigit(ep[0]) && isdigit(ep[1]) && isdigit(ep[2])) break; 217 } 218 if (!ep) { 219 continue; 220 } 221 static const size_t pid_field_width = 7; 222 ep -= pid_field_width; 223 *ep = '\0'; 224 return cp; 225 } 226 return NULL; 227 } 228 229 TEST(logcat, tz) { 230 if (android_log_clockid() == CLOCK_MONOTONIC) { 231 fprintf(stderr, "Skipping test, logd is monotonic time\n"); 232 return; 233 } 234 235 int tries = 4; // in case run too soon after system start or buffer clear 236 int count; 237 238 do { 239 FILE* fp; 240 logcat_define(ctx); 241 242 ASSERT_TRUE(NULL != 243 (fp = logcat_popen(ctx, logcat_executable 244 " -v long -v America/Los_Angeles " 245 "-b all -t 3 2>/dev/null"))); 246 247 char buffer[BIG_BUFFER]; 248 249 count = 0; 250 251 while (fgetLongTime(buffer, sizeof(buffer), fp)) { 252 if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) { 253 ++count; 254 } else { 255 fprintf(stderr, "ts=\"%s\"\n", buffer + 2); 256 } 257 } 258 259 logcat_pclose(ctx, fp); 260 261 } while ((count < 3) && --tries && inject(3 - count)); 262 263 ASSERT_EQ(3, count); 264 } 265 266 TEST(logcat, ntz) { 267 FILE* fp; 268 logcat_define(ctx); 269 270 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, logcat_executable 271 " -v long -v America/Los_Angeles -v " 272 "zone -b all -t 3 2>/dev/null"))); 273 274 char buffer[BIG_BUFFER]; 275 276 int count = 0; 277 278 while (fgetLongTime(buffer, sizeof(buffer), fp)) { 279 if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) { 280 ++count; 281 } 282 } 283 284 logcat_pclose(ctx, fp); 285 286 ASSERT_EQ(0, count); 287 } 288 289 static void do_tail(int num) { 290 int tries = 4; // in case run too soon after system start or buffer clear 291 int count; 292 293 if (num > 10) ++tries; 294 if (num > 100) ++tries; 295 do { 296 char buffer[BIG_BUFFER]; 297 298 snprintf(buffer, sizeof(buffer), 299 "ANDROID_PRINTF_LOG=long logcat -b all -t %d 2>/dev/null", num); 300 301 FILE* fp; 302 logcat_define(ctx); 303 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); 304 305 count = 0; 306 307 while (fgetLongTime(buffer, sizeof(buffer), fp)) { 308 ++count; 309 } 310 311 logcat_pclose(ctx, fp); 312 313 } while ((count < num) && --tries && inject(num - count)); 314 315 ASSERT_EQ(num, count); 316 } 317 318 TEST(logcat, tail_3) { 319 do_tail(3); 320 } 321 322 TEST(logcat, tail_10) { 323 do_tail(10); 324 } 325 326 TEST(logcat, tail_100) { 327 do_tail(100); 328 } 329 330 TEST(logcat, tail_1000) { 331 do_tail(1000); 332 } 333 334 static void do_tail_time(const char* cmd) { 335 FILE* fp; 336 int count; 337 char buffer[BIG_BUFFER]; 338 char* last_timestamp = NULL; 339 // Hard to predict 100% if first (overlap) or second line will match. 340 // -v nsec will in a substantial majority be the second line. 341 char* first_timestamp = NULL; 342 char* second_timestamp = NULL; 343 char* input; 344 345 int tries = 4; // in case run too soon after system start or buffer clear 346 347 do { 348 snprintf(buffer, sizeof(buffer), "%s -t 10 2>&1", cmd); 349 logcat_define(ctx); 350 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); 351 count = 0; 352 353 while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) { 354 ++count; 355 if (!first_timestamp) { 356 first_timestamp = strdup(input); 357 } else if (!second_timestamp) { 358 second_timestamp = strdup(input); 359 } 360 free(last_timestamp); 361 last_timestamp = strdup(input); 362 } 363 logcat_pclose(ctx, fp); 364 365 } while ((count < 10) && --tries && inject(10 - count)); 366 367 EXPECT_EQ(10, count); // We want _some_ history, too small, falses below 368 EXPECT_TRUE(last_timestamp != NULL); 369 EXPECT_TRUE(first_timestamp != NULL); 370 EXPECT_TRUE(second_timestamp != NULL); 371 372 snprintf(buffer, sizeof(buffer), "%s -t '%s' 2>&1", cmd, first_timestamp); 373 logcat_define(ctx); 374 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); 375 376 int second_count = 0; 377 int last_timestamp_count = -1; 378 379 --count; // One less unless we match the first_timestamp 380 bool found = false; 381 while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) { 382 ++second_count; 383 // We want to highlight if we skip to the next entry. 384 // WAI, if the time in logd is *exactly* 385 // XX-XX XX:XX:XX.XXXXXX000 (usec) or XX-XX XX:XX:XX.XXX000000 386 // this can happen, but it should not happen with nsec. 387 // We can make this WAI behavior happen 1000 times less 388 // frequently if the caller does not use the -v usec flag, 389 // but always the second (always skip) if they use the 390 // (undocumented) -v nsec flag. 391 if (first_timestamp) { 392 found = !strcmp(input, first_timestamp); 393 if (found) { 394 ++count; 395 GTEST_LOG_(INFO) 396 << "input = first(" << first_timestamp << ")\n"; 397 } 398 free(first_timestamp); 399 first_timestamp = NULL; 400 } 401 if (second_timestamp) { 402 found = found || !strcmp(input, second_timestamp); 403 if (!found) { 404 GTEST_LOG_(INFO) << "input(" << input << ") != second(" 405 << second_timestamp << ")\n"; 406 } 407 free(second_timestamp); 408 second_timestamp = NULL; 409 } 410 if (!strcmp(input, last_timestamp)) { 411 last_timestamp_count = second_count; 412 } 413 } 414 logcat_pclose(ctx, fp); 415 416 EXPECT_TRUE(found); 417 if (!found) { 418 if (first_timestamp) { 419 GTEST_LOG_(INFO) << "first = " << first_timestamp << "\n"; 420 } 421 if (second_timestamp) { 422 GTEST_LOG_(INFO) << "second = " << second_timestamp << "\n"; 423 } 424 if (last_timestamp) { 425 GTEST_LOG_(INFO) << "last = " << last_timestamp << "\n"; 426 } 427 } 428 free(last_timestamp); 429 last_timestamp = NULL; 430 free(first_timestamp); 431 free(second_timestamp); 432 433 EXPECT_TRUE(first_timestamp == NULL); 434 EXPECT_TRUE(second_timestamp == NULL); 435 EXPECT_LE(count, second_count); 436 EXPECT_LE(count, last_timestamp_count); 437 } 438 439 TEST(logcat, tail_time) { 440 do_tail_time(logcat_executable " -v long -v nsec -b all"); 441 } 442 443 TEST(logcat, tail_time_epoch) { 444 do_tail_time(logcat_executable " -v long -v nsec -v epoch -b all"); 445 } 446 447 TEST(logcat, End_to_End) { 448 pid_t pid = getpid(); 449 450 log_time ts(CLOCK_MONOTONIC); 451 452 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); 453 454 FILE* fp; 455 logcat_define(ctx); 456 ASSERT_TRUE(NULL != 457 (fp = logcat_popen(ctx, logcat_executable 458 " -v brief -b events -t 100 2>/dev/null"))); 459 460 char buffer[BIG_BUFFER]; 461 462 int count = 0; 463 464 while (fgets(buffer, sizeof(buffer), fp)) { 465 int p; 466 unsigned long long t; 467 468 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) || 469 (p != pid)) { 470 continue; 471 } 472 473 log_time tx((const char*)&t); 474 if (ts == tx) { 475 ++count; 476 } 477 } 478 479 logcat_pclose(ctx, fp); 480 481 ASSERT_EQ(1, count); 482 } 483 484 TEST(logcat, End_to_End_multitude) { 485 pid_t pid = getpid(); 486 487 log_time ts(CLOCK_MONOTONIC); 488 489 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); 490 491 FILE* fp[256]; // does this count as a multitude! 492 memset(fp, 0, sizeof(fp)); 493 logcat_define(ctx[sizeof(fp) / sizeof(fp[0])]); 494 size_t num = 0; 495 do { 496 EXPECT_TRUE(NULL != 497 (fp[num] = logcat_popen(ctx[num], logcat_executable 498 " -v brief -b events -t 100"))); 499 if (!fp[num]) { 500 fprintf(stderr, 501 "WARNING: limiting to %zu simultaneous logcat operations\n", 502 num); 503 break; 504 } 505 } while (++num < sizeof(fp) / sizeof(fp[0])); 506 507 char buffer[BIG_BUFFER]; 508 509 size_t count = 0; 510 511 for (size_t idx = 0; idx < sizeof(fp) / sizeof(fp[0]); ++idx) { 512 if (!fp[idx]) break; 513 while (fgets(buffer, sizeof(buffer), fp[idx])) { 514 int p; 515 unsigned long long t; 516 517 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) || 518 (p != pid)) { 519 continue; 520 } 521 522 log_time tx((const char*)&t); 523 if (ts == tx) { 524 ++count; 525 } 526 } 527 528 logcat_pclose(ctx[idx], fp[idx]); 529 } 530 531 ASSERT_EQ(num, count); 532 } 533 534 static int get_groups(const char* cmd) { 535 FILE* fp; 536 logcat_define(ctx); 537 538 // NB: crash log only available in user space 539 EXPECT_TRUE(NULL != (fp = logcat_popen(ctx, cmd))); 540 541 if (fp == NULL) { 542 return 0; 543 } 544 545 char buffer[BIG_BUFFER]; 546 547 int count = 0; 548 549 while (fgets(buffer, sizeof(buffer), fp)) { 550 int size, consumed, max, payload; 551 char size_mult[3], consumed_mult[3]; 552 long full_size, full_consumed; 553 554 size = consumed = max = payload = 0; 555 // NB: crash log can be very small, not hit a Kb of consumed space 556 // doubly lucky we are not including it. 557 if (6 != sscanf(buffer, 558 "%*s ring buffer is %d%2s (%d%2s consumed)," 559 " max entry is %db, max payload is %db", 560 &size, size_mult, &consumed, consumed_mult, &max, 561 &payload)) { 562 fprintf(stderr, "WARNING: Parse error: %s", buffer); 563 continue; 564 } 565 full_size = size; 566 switch (size_mult[0]) { 567 case 'G': 568 full_size *= 1024; 569 /* FALLTHRU */ 570 case 'M': 571 full_size *= 1024; 572 /* FALLTHRU */ 573 case 'K': 574 full_size *= 1024; 575 /* FALLTHRU */ 576 case 'b': 577 break; 578 } 579 full_consumed = consumed; 580 switch (consumed_mult[0]) { 581 case 'G': 582 full_consumed *= 1024; 583 /* FALLTHRU */ 584 case 'M': 585 full_consumed *= 1024; 586 /* FALLTHRU */ 587 case 'K': 588 full_consumed *= 1024; 589 /* FALLTHRU */ 590 case 'b': 591 break; 592 } 593 EXPECT_GT((full_size * 9) / 4, full_consumed); 594 EXPECT_GT(full_size, max); 595 EXPECT_GT(max, payload); 596 597 if ((((full_size * 9) / 4) >= full_consumed) && (full_size > max) && 598 (max > payload)) { 599 ++count; 600 } 601 } 602 603 logcat_pclose(ctx, fp); 604 605 return count; 606 } 607 608 TEST(logcat, get_size) { 609 ASSERT_EQ(4, get_groups(logcat_executable 610 " -v brief -b radio -b events -b system -b " 611 "main -g 2>/dev/null")); 612 } 613 614 // duplicate test for get_size, but use comma-separated list of buffers 615 TEST(logcat, multiple_buffer) { 616 ASSERT_EQ( 617 4, get_groups(logcat_executable 618 " -v brief -b radio,events,system,main -g 2>/dev/null")); 619 } 620 621 TEST(logcat, bad_buffer) { 622 ASSERT_EQ(0, 623 get_groups( 624 logcat_executable 625 " -v brief -b radio,events,bogo,system,main -g 2>/dev/null")); 626 } 627 628 #ifndef logcat 629 static void caught_blocking(int signum) { 630 unsigned long long v = 0xDEADBEEFA55A0000ULL; 631 632 v += getpid() & 0xFFFF; 633 if (signum == 0) ++v; 634 635 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 636 } 637 638 TEST(logcat, blocking) { 639 FILE* fp; 640 unsigned long long v = 0xDEADBEEFA55F0000ULL; 641 642 pid_t pid = getpid(); 643 644 v += pid & 0xFFFF; 645 646 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 647 648 v &= 0xFFFFFFFFFFFAFFFFULL; 649 650 ASSERT_TRUE( 651 NULL != 652 (fp = popen("( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" 653 " logcat -v brief -b events 2>&1", 654 "r"))); 655 656 char buffer[BIG_BUFFER]; 657 658 int count = 0; 659 660 int signals = 0; 661 662 signal(SIGALRM, caught_blocking); 663 alarm(2); 664 while (fgets(buffer, sizeof(buffer), fp)) { 665 if (!strncmp(buffer, "DONE", 4)) { 666 break; 667 } 668 669 ++count; 670 671 int p; 672 unsigned long long l; 673 674 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) { 675 continue; 676 } 677 678 if (l == v) { 679 ++signals; 680 break; 681 } 682 } 683 alarm(0); 684 signal(SIGALRM, SIG_DFL); 685 686 // Generate SIGPIPE 687 fclose(fp); 688 caught_blocking(0); 689 690 pclose(fp); 691 692 EXPECT_LE(2, count); 693 694 EXPECT_EQ(1, signals); 695 } 696 697 static void caught_blocking_tail(int signum) { 698 unsigned long long v = 0xA55ADEADBEEF0000ULL; 699 700 v += getpid() & 0xFFFF; 701 if (signum == 0) ++v; 702 703 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 704 } 705 706 TEST(logcat, blocking_tail) { 707 FILE* fp; 708 unsigned long long v = 0xA55FDEADBEEF0000ULL; 709 710 pid_t pid = getpid(); 711 712 v += pid & 0xFFFF; 713 714 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 715 716 v &= 0xFFFAFFFFFFFFFFFFULL; 717 718 ASSERT_TRUE( 719 NULL != 720 (fp = popen("( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" 721 " logcat -v brief -b events -T 5 2>&1", 722 "r"))); 723 724 char buffer[BIG_BUFFER]; 725 726 int count = 0; 727 728 int signals = 0; 729 730 signal(SIGALRM, caught_blocking_tail); 731 alarm(2); 732 while (fgets(buffer, sizeof(buffer), fp)) { 733 if (!strncmp(buffer, "DONE", 4)) { 734 break; 735 } 736 737 ++count; 738 739 int p; 740 unsigned long long l; 741 742 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) { 743 continue; 744 } 745 746 if (l == v) { 747 if (count >= 5) { 748 ++signals; 749 } 750 break; 751 } 752 } 753 alarm(0); 754 signal(SIGALRM, SIG_DFL); 755 756 // Generate SIGPIPE 757 fclose(fp); 758 caught_blocking_tail(0); 759 760 pclose(fp); 761 762 EXPECT_LE(2, count); 763 764 EXPECT_EQ(1, signals); 765 } 766 #endif 767 768 // meant to be handed to ASSERT_FALSE / EXPECT_FALSE to expand the message 769 static testing::AssertionResult IsFalse(int ret, const char* command) { 770 return ret ? (testing::AssertionSuccess() 771 << "ret=" << ret << " command=\"" << command << "\"") 772 : testing::AssertionFailure(); 773 } 774 775 TEST(logcat, logrotate) { 776 static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; 777 char buf[sizeof(form)]; 778 ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form))); 779 780 static const char comm[] = logcat_executable 781 " -b radio -b events -b system -b main" 782 " -d -f %s/log.txt -n 7 -r 1"; 783 char command[sizeof(buf) + sizeof(comm)]; 784 snprintf(command, sizeof(command), comm, buf); 785 786 int ret; 787 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command)); 788 if (!ret) { 789 snprintf(command, sizeof(command), "ls -s %s 2>/dev/null", buf); 790 791 FILE* fp; 792 EXPECT_TRUE(NULL != (fp = popen(command, "r"))); 793 if (fp) { 794 char buffer[BIG_BUFFER]; 795 int count = 0; 796 797 while (fgets(buffer, sizeof(buffer), fp)) { 798 static const char total[] = "total "; 799 int num; 800 char c; 801 802 if ((2 == sscanf(buffer, "%d log.tx%c", &num, &c)) && 803 (num <= 40)) { 804 ++count; 805 } else if (strncmp(buffer, total, sizeof(total) - 1)) { 806 fprintf(stderr, "WARNING: Parse error: %s", buffer); 807 } 808 } 809 pclose(fp); 810 if ((count != 7) && (count != 8)) { 811 fprintf(stderr, "count=%d\n", count); 812 } 813 EXPECT_TRUE(count == 7 || count == 8); 814 } 815 } 816 snprintf(command, sizeof(command), "rm -rf %s", buf); 817 EXPECT_FALSE(IsFalse(system(command), command)); 818 } 819 820 TEST(logcat, logrotate_suffix) { 821 static const char tmp_out_dir_form[] = 822 "/data/local/tmp/logcat.logrotate.XXXXXX"; 823 char tmp_out_dir[sizeof(tmp_out_dir_form)]; 824 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); 825 826 static const char logcat_cmd[] = logcat_executable 827 " -b radio -b events -b system -b main" 828 " -d -f %s/log.txt -n 10 -r 1"; 829 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)]; 830 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir); 831 832 int ret; 833 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command)); 834 if (!ret) { 835 snprintf(command, sizeof(command), "ls %s 2>/dev/null", tmp_out_dir); 836 837 FILE* fp; 838 EXPECT_TRUE(NULL != (fp = popen(command, "r"))); 839 char buffer[BIG_BUFFER]; 840 int log_file_count = 0; 841 842 while (fgets(buffer, sizeof(buffer), fp)) { 843 static const char rotated_log_filename_prefix[] = "log.txt."; 844 static const size_t rotated_log_filename_prefix_len = 845 strlen(rotated_log_filename_prefix); 846 static const char log_filename[] = "log.txt"; 847 848 if (!strncmp(buffer, rotated_log_filename_prefix, 849 rotated_log_filename_prefix_len)) { 850 // Rotated file should have form log.txt.## 851 char* rotated_log_filename_suffix = 852 buffer + rotated_log_filename_prefix_len; 853 char* endptr; 854 const long int suffix_value = 855 strtol(rotated_log_filename_suffix, &endptr, 10); 856 EXPECT_EQ(rotated_log_filename_suffix + 2, endptr); 857 EXPECT_LE(suffix_value, 10); 858 EXPECT_GT(suffix_value, 0); 859 ++log_file_count; 860 continue; 861 } 862 863 if (!strncmp(buffer, log_filename, strlen(log_filename))) { 864 ++log_file_count; 865 continue; 866 } 867 868 fprintf(stderr, "ERROR: Unexpected file: %s", buffer); 869 ADD_FAILURE(); 870 } 871 pclose(fp); 872 EXPECT_EQ(11, log_file_count); 873 } 874 snprintf(command, sizeof(command), "rm -rf %s", tmp_out_dir); 875 EXPECT_FALSE(IsFalse(system(command), command)); 876 } 877 878 TEST(logcat, logrotate_continue) { 879 static const char tmp_out_dir_form[] = 880 "/data/local/tmp/logcat.logrotate.XXXXXX"; 881 char tmp_out_dir[sizeof(tmp_out_dir_form)]; 882 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); 883 884 static const char log_filename[] = "log.txt"; 885 static const char logcat_cmd[] = 886 logcat_executable " -b all -v nsec -d -f %s/%s -n 256 -r 1024"; 887 static const char cleanup_cmd[] = "rm -rf %s"; 888 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)]; 889 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); 890 891 int ret; 892 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command)); 893 if (ret) { 894 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 895 EXPECT_FALSE(IsFalse(system(command), command)); 896 return; 897 } 898 FILE* fp; 899 snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, log_filename); 900 EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); 901 if (!fp) { 902 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 903 EXPECT_FALSE(IsFalse(system(command), command)); 904 return; 905 } 906 char* line = NULL; 907 char* last_line = 908 NULL; // this line is allowed to stutter, one-line overlap 909 char* second_last_line = NULL; // should never stutter 910 char* first_line = NULL; // help diagnose failure? 911 size_t len = 0; 912 while (getline(&line, &len, fp) != -1) { 913 if (!first_line) { 914 first_line = line; 915 line = NULL; 916 continue; 917 } 918 free(second_last_line); 919 second_last_line = last_line; 920 last_line = line; 921 line = NULL; 922 } 923 fclose(fp); 924 free(line); 925 if (second_last_line == NULL) { 926 fprintf(stderr, "No second to last line, using last, test may fail\n"); 927 second_last_line = last_line; 928 last_line = NULL; 929 } 930 free(last_line); 931 EXPECT_TRUE(NULL != second_last_line); 932 if (!second_last_line) { 933 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 934 EXPECT_FALSE(IsFalse(system(command), command)); 935 free(first_line); 936 return; 937 } 938 // re-run the command, it should only add a few lines more content if it 939 // continues where it left off. 940 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); 941 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command)); 942 if (ret) { 943 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 944 EXPECT_FALSE(IsFalse(system(command), command)); 945 free(second_last_line); 946 free(first_line); 947 return; 948 } 949 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), 950 closedir); 951 EXPECT_NE(nullptr, dir); 952 if (!dir) { 953 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 954 EXPECT_FALSE(IsFalse(system(command), command)); 955 free(second_last_line); 956 free(first_line); 957 return; 958 } 959 struct dirent* entry; 960 unsigned count = 0; 961 while ((entry = readdir(dir.get()))) { 962 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { 963 continue; 964 } 965 snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, entry->d_name); 966 EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); 967 if (!fp) { 968 fprintf(stderr, "%s ?\n", command); 969 continue; 970 } 971 line = NULL; 972 size_t number = 0; 973 while (getline(&line, &len, fp) != -1) { 974 ++number; 975 if (!strcmp(line, second_last_line)) { 976 EXPECT_TRUE(++count <= 1); 977 fprintf(stderr, "%s(%zu):\n", entry->d_name, number); 978 } 979 } 980 fclose(fp); 981 free(line); 982 unlink(command); 983 } 984 if (count > 1) { 985 char* brk = strpbrk(second_last_line, "\r\n"); 986 if (!brk) brk = second_last_line + strlen(second_last_line); 987 fprintf(stderr, "\"%.*s\" occurred %u times\n", 988 (int)(brk - second_last_line), second_last_line, count); 989 if (first_line) { 990 brk = strpbrk(first_line, "\r\n"); 991 if (!brk) brk = first_line + strlen(first_line); 992 fprintf(stderr, "\"%.*s\" was first line, fault?\n", 993 (int)(brk - first_line), first_line); 994 } 995 } 996 free(second_last_line); 997 free(first_line); 998 999 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1000 EXPECT_FALSE(IsFalse(system(command), command)); 1001 } 1002 1003 TEST(logcat, logrotate_clear) { 1004 static const char tmp_out_dir_form[] = 1005 "/data/local/tmp/logcat.logrotate.XXXXXX"; 1006 char tmp_out_dir[sizeof(tmp_out_dir_form)]; 1007 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); 1008 1009 static const char log_filename[] = "log.txt"; 1010 static const unsigned num_val = 32; 1011 static const char logcat_cmd[] = 1012 logcat_executable " -b all -d -f %s/%s -n %d -r 1"; 1013 static const char clear_cmd[] = " -c"; 1014 static const char cleanup_cmd[] = "rm -rf %s"; 1015 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + 1016 sizeof(log_filename) + sizeof(clear_cmd) + 32]; 1017 1018 // Run command with all data 1019 { 1020 snprintf(command, sizeof(command) - sizeof(clear_cmd), logcat_cmd, 1021 tmp_out_dir, log_filename, num_val); 1022 1023 int ret; 1024 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command)); 1025 if (ret) { 1026 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1027 EXPECT_FALSE(IsFalse(system(command), command)); 1028 return; 1029 } 1030 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), 1031 closedir); 1032 EXPECT_NE(nullptr, dir); 1033 if (!dir) { 1034 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1035 EXPECT_FALSE(IsFalse(system(command), command)); 1036 return; 1037 } 1038 struct dirent* entry; 1039 unsigned count = 0; 1040 while ((entry = readdir(dir.get()))) { 1041 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { 1042 continue; 1043 } 1044 ++count; 1045 } 1046 EXPECT_EQ(count, num_val + 1); 1047 } 1048 1049 { 1050 // Now with -c option tacked onto the end 1051 strcat(command, clear_cmd); 1052 1053 int ret; 1054 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command)); 1055 if (ret) { 1056 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1057 EXPECT_FALSE(system(command)); 1058 EXPECT_FALSE(IsFalse(system(command), command)); 1059 return; 1060 } 1061 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), 1062 closedir); 1063 EXPECT_NE(nullptr, dir); 1064 if (!dir) { 1065 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1066 EXPECT_FALSE(IsFalse(system(command), command)); 1067 return; 1068 } 1069 struct dirent* entry; 1070 unsigned count = 0; 1071 while ((entry = readdir(dir.get()))) { 1072 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { 1073 continue; 1074 } 1075 fprintf(stderr, "Found %s/%s!!!\n", tmp_out_dir, entry->d_name); 1076 ++count; 1077 } 1078 EXPECT_EQ(count, 0U); 1079 } 1080 1081 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1082 EXPECT_FALSE(IsFalse(system(command), command)); 1083 } 1084 1085 static int logrotate_count_id(const char* logcat_cmd, const char* tmp_out_dir) { 1086 static const char log_filename[] = "log.txt"; 1087 char command[strlen(tmp_out_dir) + strlen(logcat_cmd) + 1088 strlen(log_filename) + 32]; 1089 1090 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); 1091 1092 int ret = logcat_system(command); 1093 if (ret) { 1094 fprintf(stderr, "system(\"%s\")=%d", command, ret); 1095 return -1; 1096 } 1097 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), 1098 closedir); 1099 if (!dir) { 1100 fprintf(stderr, "opendir(\"%s\") failed", tmp_out_dir); 1101 return -1; 1102 } 1103 struct dirent* entry; 1104 int count = 0; 1105 while ((entry = readdir(dir.get()))) { 1106 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { 1107 continue; 1108 } 1109 ++count; 1110 } 1111 return count; 1112 } 1113 1114 TEST(logcat, logrotate_id) { 1115 static const char logcat_cmd[] = 1116 logcat_executable " -b all -d -f %s/%s -n 32 -r 1 --id=test"; 1117 static const char logcat_short_cmd[] = 1118 logcat_executable " -b all -t 10 -f %s/%s -n 32 -r 1 --id=test"; 1119 static const char tmp_out_dir_form[] = 1120 "/data/local/tmp/logcat.logrotate.XXXXXX"; 1121 static const char log_filename[] = "log.txt"; 1122 char tmp_out_dir[strlen(tmp_out_dir_form) + 1]; 1123 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); 1124 1125 EXPECT_EQ(34, logrotate_count_id(logcat_cmd, tmp_out_dir)); 1126 EXPECT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); 1127 1128 char id_file[strlen(tmp_out_dir_form) + strlen(log_filename) + 5]; 1129 snprintf(id_file, sizeof(id_file), "%s/%s.id", tmp_out_dir, log_filename); 1130 if (getuid() != 0) { 1131 chmod(id_file, 0); 1132 EXPECT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); 1133 } 1134 unlink(id_file); 1135 EXPECT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); 1136 1137 FILE* fp = fopen(id_file, "w"); 1138 if (fp) { 1139 fprintf(fp, "not_a_test"); 1140 fclose(fp); 1141 } 1142 if (getuid() != 0) { 1143 chmod(id_file, 1144 0); // API to preserve content even with signature change 1145 ASSERT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); 1146 chmod(id_file, 0600); 1147 } 1148 1149 int new_signature; 1150 EXPECT_LE( 1151 2, (new_signature = logrotate_count_id(logcat_short_cmd, tmp_out_dir))); 1152 EXPECT_GT(34, new_signature); 1153 1154 static const char cleanup_cmd[] = "rm -rf %s"; 1155 char command[strlen(cleanup_cmd) + strlen(tmp_out_dir_form)]; 1156 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); 1157 EXPECT_FALSE(IsFalse(system(command), command)); 1158 } 1159 1160 TEST(logcat, logrotate_nodir) { 1161 // expect logcat to error out on writing content and not exit(0) for nodir 1162 static const char command[] = logcat_executable 1163 " -b all -d" 1164 " -f /das/nein/gerfingerpoken/logcat/log.txt" 1165 " -n 256 -r 1024"; 1166 EXPECT_FALSE(IsFalse(0 == logcat_system(command), command)); 1167 } 1168 1169 #ifndef logcat 1170 static void caught_blocking_clear(int signum) { 1171 unsigned long long v = 0xDEADBEEFA55C0000ULL; 1172 1173 v += getpid() & 0xFFFF; 1174 if (signum == 0) ++v; 1175 1176 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); 1177 } 1178 1179 TEST(logcat, blocking_clear) { 1180 FILE* fp; 1181 unsigned long long v = 0xDEADBEEFA55C0000ULL; 1182 1183 pid_t pid = getpid(); 1184 1185 v += pid & 0xFFFF; 1186 1187 // This test is racey; an event occurs between clear and dump. 1188 // We accept that we will get a false positive, but never a false negative. 1189 ASSERT_TRUE( 1190 NULL != 1191 (fp = popen("( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" 1192 " logcat -b events -c 2>&1 ;" 1193 " logcat -b events -g 2>&1 ;" 1194 " logcat -v brief -b events 2>&1", 1195 "r"))); 1196 1197 char buffer[BIG_BUFFER]; 1198 1199 int count = 0; 1200 int minus_g = 0; 1201 1202 int signals = 0; 1203 1204 signal(SIGALRM, caught_blocking_clear); 1205 alarm(2); 1206 while (fgets(buffer, sizeof(buffer), fp)) { 1207 if (!strncmp(buffer, "clearLog: ", 10)) { 1208 fprintf(stderr, "WARNING: Test lacks permission to run :-(\n"); 1209 count = signals = 1; 1210 break; 1211 } 1212 1213 if (!strncmp(buffer, "DONE", 4)) { 1214 break; 1215 } 1216 1217 int size, consumed, max, payload; 1218 char size_mult[3], consumed_mult[3]; 1219 size = consumed = max = payload = 0; 1220 if (6 == sscanf(buffer, 1221 "events: ring buffer is %d%2s (%d%2s consumed)," 1222 " max entry is %db, max payload is %db", 1223 &size, size_mult, &consumed, consumed_mult, &max, 1224 &payload)) { 1225 long full_size = size, full_consumed = consumed; 1226 1227 switch (size_mult[0]) { 1228 case 'G': 1229 full_size *= 1024; 1230 /* FALLTHRU */ 1231 case 'M': 1232 full_size *= 1024; 1233 /* FALLTHRU */ 1234 case 'K': 1235 full_size *= 1024; 1236 /* FALLTHRU */ 1237 case 'b': 1238 break; 1239 } 1240 switch (consumed_mult[0]) { 1241 case 'G': 1242 full_consumed *= 1024; 1243 /* FALLTHRU */ 1244 case 'M': 1245 full_consumed *= 1024; 1246 /* FALLTHRU */ 1247 case 'K': 1248 full_consumed *= 1024; 1249 /* FALLTHRU */ 1250 case 'b': 1251 break; 1252 } 1253 EXPECT_GT(full_size, full_consumed); 1254 EXPECT_GT(full_size, max); 1255 EXPECT_GT(max, payload); 1256 EXPECT_GT(max, full_consumed); 1257 1258 ++minus_g; 1259 continue; 1260 } 1261 1262 ++count; 1263 1264 int p; 1265 unsigned long long l; 1266 1267 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) { 1268 continue; 1269 } 1270 1271 if (l == v) { 1272 if (count > 1) { 1273 fprintf(stderr, "WARNING: Possible false positive\n"); 1274 } 1275 ++signals; 1276 break; 1277 } 1278 } 1279 alarm(0); 1280 signal(SIGALRM, SIG_DFL); 1281 1282 // Generate SIGPIPE 1283 fclose(fp); 1284 caught_blocking_clear(0); 1285 1286 pclose(fp); 1287 1288 EXPECT_LE(1, count); 1289 EXPECT_EQ(1, minus_g); 1290 1291 EXPECT_EQ(1, signals); 1292 } 1293 #endif 1294 1295 static bool get_white_black(char** list) { 1296 FILE* fp; 1297 logcat_define(ctx); 1298 1299 fp = logcat_popen(ctx, logcat_executable " -p 2>/dev/null"); 1300 if (fp == NULL) { 1301 fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n"); 1302 return false; 1303 } 1304 1305 char buffer[BIG_BUFFER]; 1306 1307 while (fgets(buffer, sizeof(buffer), fp)) { 1308 char* hold = *list; 1309 char* buf = buffer; 1310 while (isspace(*buf)) { 1311 ++buf; 1312 } 1313 char* end = buf + strlen(buf); 1314 while (isspace(*--end) && (end >= buf)) { 1315 *end = '\0'; 1316 } 1317 if (end < buf) { 1318 continue; 1319 } 1320 if (hold) { 1321 asprintf(list, "%s %s", hold, buf); 1322 free(hold); 1323 } else { 1324 asprintf(list, "%s", buf); 1325 } 1326 } 1327 logcat_pclose(ctx, fp); 1328 return *list != NULL; 1329 } 1330 1331 static bool set_white_black(const char* list) { 1332 FILE* fp; 1333 logcat_define(ctx); 1334 1335 char buffer[BIG_BUFFER]; 1336 1337 snprintf(buffer, sizeof(buffer), logcat_executable " -P '%s' 2>&1", 1338 list ? list : ""); 1339 fp = logcat_popen(ctx, buffer); 1340 if (fp == NULL) { 1341 fprintf(stderr, "ERROR: %s\n", buffer); 1342 return false; 1343 } 1344 1345 while (fgets(buffer, sizeof(buffer), fp)) { 1346 char* buf = buffer; 1347 while (isspace(*buf)) { 1348 ++buf; 1349 } 1350 char* end = buf + strlen(buf); 1351 while ((end > buf) && isspace(*--end)) { 1352 *end = '\0'; 1353 } 1354 if (end <= buf) { 1355 continue; 1356 } 1357 fprintf(stderr, "%s\n", buf); 1358 logcat_pclose(ctx, fp); 1359 return false; 1360 } 1361 return logcat_pclose(ctx, fp) == 0; 1362 } 1363 1364 TEST(logcat, white_black_adjust) { 1365 char* list = NULL; 1366 char* adjust = NULL; 1367 1368 get_white_black(&list); 1369 1370 static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30"; 1371 ASSERT_EQ(true, set_white_black(adjustment)); 1372 ASSERT_EQ(true, get_white_black(&adjust)); 1373 EXPECT_STREQ(adjustment, adjust); 1374 free(adjust); 1375 adjust = NULL; 1376 1377 static const char adjustment2[] = "300/20 300/21 2000 ~1000"; 1378 ASSERT_EQ(true, set_white_black(adjustment2)); 1379 ASSERT_EQ(true, get_white_black(&adjust)); 1380 EXPECT_STREQ(adjustment2, adjust); 1381 free(adjust); 1382 adjust = NULL; 1383 1384 ASSERT_EQ(true, set_white_black(list)); 1385 get_white_black(&adjust); 1386 EXPECT_STREQ(list ? list : "", adjust ? adjust : ""); 1387 free(adjust); 1388 adjust = NULL; 1389 1390 free(list); 1391 list = NULL; 1392 } 1393 1394 TEST(logcat, regex) { 1395 FILE* fp; 1396 logcat_define(ctx); 1397 int count = 0; 1398 1399 char buffer[BIG_BUFFER]; 1400 #define logcat_regex_prefix ___STRING(logcat) "_test" 1401 1402 snprintf(buffer, sizeof(buffer), 1403 logcat_executable " --pid %d -d -e " logcat_regex_prefix "_a+b", 1404 getpid()); 1405 1406 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, 1407 logcat_regex_prefix "_ab")); 1408 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, 1409 logcat_regex_prefix "_b")); 1410 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, 1411 logcat_regex_prefix "_aaaab")); 1412 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix, 1413 logcat_regex_prefix "_aaaa")); 1414 // Let the logs settle 1415 sleep(1); 1416 1417 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); 1418 1419 while (fgets(buffer, sizeof(buffer), fp)) { 1420 if (!strncmp(begin, buffer, sizeof(begin) - 1)) { 1421 continue; 1422 } 1423 1424 EXPECT_TRUE(strstr(buffer, logcat_regex_prefix "_") != NULL); 1425 1426 count++; 1427 } 1428 1429 logcat_pclose(ctx, fp); 1430 1431 ASSERT_EQ(2, count); 1432 } 1433 1434 TEST(logcat, maxcount) { 1435 FILE* fp; 1436 logcat_define(ctx); 1437 int count = 0; 1438 1439 char buffer[BIG_BUFFER]; 1440 1441 snprintf(buffer, sizeof(buffer), 1442 logcat_executable " --pid %d -d --max-count 3", getpid()); 1443 1444 LOG_FAILURE_RETRY( 1445 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); 1446 LOG_FAILURE_RETRY( 1447 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); 1448 LOG_FAILURE_RETRY( 1449 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); 1450 LOG_FAILURE_RETRY( 1451 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); 1452 1453 // Let the logs settle 1454 sleep(1); 1455 1456 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer))); 1457 1458 while (fgets(buffer, sizeof(buffer), fp)) { 1459 if (!strncmp(begin, buffer, sizeof(begin) - 1)) { 1460 continue; 1461 } 1462 1463 count++; 1464 } 1465 1466 logcat_pclose(ctx, fp); 1467 1468 ASSERT_EQ(3, count); 1469 } 1470 1471 static bool End_to_End(const char* tag, const char* fmt, ...) 1472 #if defined(__GNUC__) 1473 __attribute__((__format__(printf, 2, 3))) 1474 #endif 1475 ; 1476 1477 static bool End_to_End(const char* tag, const char* fmt, ...) { 1478 logcat_define(ctx); 1479 FILE* fp = logcat_popen(ctx, 1480 "logcat" 1481 " -v brief" 1482 " -b events" 1483 " -v descriptive" 1484 " -t 100" 1485 " 2>/dev/null"); 1486 if (!fp) { 1487 fprintf(stderr, "End_to_End: popen failed"); 1488 return false; 1489 } 1490 1491 char buffer[BIG_BUFFER]; 1492 va_list ap; 1493 1494 va_start(ap, fmt); 1495 vsnprintf(buffer, sizeof(buffer), fmt, ap); 1496 va_end(ap); 1497 1498 char* str = NULL; 1499 asprintf(&str, "I/%s ( %%d):%%c%s%%c", tag, buffer); 1500 std::string expect(str); 1501 free(str); 1502 1503 int count = 0; 1504 pid_t pid = getpid(); 1505 std::string lastMatch; 1506 int maxMatch = 1; 1507 while (fgets(buffer, sizeof(buffer), fp)) { 1508 char space; 1509 char newline; 1510 int p; 1511 int ret = sscanf(buffer, expect.c_str(), &p, &space, &newline); 1512 if ((ret == 3) && (p == pid) && (space == ' ') && (newline == '\n')) { 1513 ++count; 1514 } else if ((ret >= maxMatch) && (p == pid) && (count == 0)) { 1515 lastMatch = buffer; 1516 maxMatch = ret; 1517 } 1518 } 1519 1520 logcat_pclose(ctx, fp); 1521 1522 if ((count == 0) && (lastMatch.length() > 0)) { 1523 // Help us pinpoint where things went wrong ... 1524 fprintf(stderr, "Closest match for\n %s\n is\n %s", 1525 expect.c_str(), lastMatch.c_str()); 1526 } else if (count > 2) { 1527 fprintf(stderr, "Too many matches (%d) for %s\n", count, expect.c_str()); 1528 } 1529 1530 // Expect one the first time around as either liblogcat.descriptive or 1531 // logcat.descriptive. Expect two the second time as the other. 1532 return count == 1 || count == 2; 1533 } 1534 1535 TEST(logcat, descriptive) { 1536 struct tag { 1537 uint32_t tagNo; 1538 const char* tagStr; 1539 }; 1540 1541 { 1542 static const struct tag hhgtg = { 42, "answer" }; 1543 android_log_event_list ctx(hhgtg.tagNo); 1544 static const char theAnswer[] = "what is five by seven"; 1545 ctx << theAnswer; 1546 ctx.write(); 1547 EXPECT_TRUE( 1548 End_to_End(hhgtg.tagStr, "to life the universe etc=%s", theAnswer)); 1549 } 1550 1551 { 1552 static const struct tag sync = { 2720, "sync" }; 1553 static const char id[] = "logcat.decriptive"; 1554 { 1555 android_log_event_list ctx(sync.tagNo); 1556 ctx << id << (int32_t)42 << (int32_t)-1 << (int32_t)0; 1557 ctx.write(); 1558 EXPECT_TRUE(End_to_End(sync.tagStr, 1559 "[id=%s,event=42,source=-1,account=0]", id)); 1560 } 1561 1562 // Partial match to description 1563 { 1564 android_log_event_list ctx(sync.tagNo); 1565 ctx << id << (int32_t)43 << (int64_t)-1 << (int32_t)0; 1566 ctx.write(); 1567 EXPECT_TRUE(End_to_End(sync.tagStr, "[id=%s,event=43,-1,0]", id)); 1568 } 1569 1570 // Negative Test of End_to_End, ensure it is working 1571 { 1572 android_log_event_list ctx(sync.tagNo); 1573 ctx << id << (int32_t)44 << (int32_t)-1 << (int64_t)0; 1574 ctx.write(); 1575 fprintf(stderr, "Expect a \"Closest match\" message\n"); 1576 EXPECT_FALSE(End_to_End( 1577 sync.tagStr, "[id=%s,event=44,source=-1,account=0]", id)); 1578 } 1579 } 1580 1581 { 1582 static const struct tag sync = { 2747, "contacts_aggregation" }; 1583 { 1584 android_log_event_list ctx(sync.tagNo); 1585 ctx << (uint64_t)30 << (int32_t)2; 1586 ctx.write(); 1587 EXPECT_TRUE( 1588 End_to_End(sync.tagStr, "[aggregation time=30ms,count=2]")); 1589 } 1590 1591 { 1592 android_log_event_list ctx(sync.tagNo); 1593 ctx << (uint64_t)31570 << (int32_t)911; 1594 ctx.write(); 1595 EXPECT_TRUE( 1596 End_to_End(sync.tagStr, "[aggregation time=31.57s,count=911]")); 1597 } 1598 } 1599 1600 { 1601 static const struct tag sync = { 75000, "sqlite_mem_alarm_current" }; 1602 { 1603 android_log_event_list ctx(sync.tagNo); 1604 ctx << (uint32_t)512; 1605 ctx.write(); 1606 EXPECT_TRUE(End_to_End(sync.tagStr, "current=512B")); 1607 } 1608 1609 { 1610 android_log_event_list ctx(sync.tagNo); 1611 ctx << (uint32_t)3072; 1612 ctx.write(); 1613 EXPECT_TRUE(End_to_End(sync.tagStr, "current=3KB")); 1614 } 1615 1616 { 1617 android_log_event_list ctx(sync.tagNo); 1618 ctx << (uint32_t)2097152; 1619 ctx.write(); 1620 EXPECT_TRUE(End_to_End(sync.tagStr, "current=2MB")); 1621 } 1622 1623 { 1624 android_log_event_list ctx(sync.tagNo); 1625 ctx << (uint32_t)2097153; 1626 ctx.write(); 1627 EXPECT_TRUE(End_to_End(sync.tagStr, "current=2097153B")); 1628 } 1629 1630 { 1631 android_log_event_list ctx(sync.tagNo); 1632 ctx << (uint32_t)1073741824; 1633 ctx.write(); 1634 EXPECT_TRUE(End_to_End(sync.tagStr, "current=1GB")); 1635 } 1636 1637 { 1638 android_log_event_list ctx(sync.tagNo); 1639 ctx << (uint32_t)3221225472; // 3MB, but on purpose overflowed 1640 ctx.write(); 1641 EXPECT_TRUE(End_to_End(sync.tagStr, "current=-1GB")); 1642 } 1643 } 1644 1645 { 1646 static const struct tag sync = { 27501, "notification_panel_hidden" }; 1647 android_log_event_list ctx(sync.tagNo); 1648 ctx.write(); 1649 EXPECT_TRUE(End_to_End(sync.tagStr, "")); 1650 } 1651 } 1652 1653 static bool reportedSecurity(const char* command) { 1654 logcat_define(ctx); 1655 FILE* fp = logcat_popen(ctx, command); 1656 if (!fp) return true; 1657 1658 std::string ret; 1659 bool val = android::base::ReadFdToString(fileno(fp), &ret); 1660 logcat_pclose(ctx, fp); 1661 1662 if (!val) return true; 1663 return std::string::npos != ret.find("'security'"); 1664 } 1665 1666 TEST(logcat, security) { 1667 EXPECT_FALSE(reportedSecurity(logcat_executable " -b all -g 2>&1")); 1668 EXPECT_TRUE(reportedSecurity(logcat_executable " -b security -g 2>&1")); 1669 EXPECT_TRUE(reportedSecurity(logcat_executable " -b security -c 2>&1")); 1670 EXPECT_TRUE( 1671 reportedSecurity(logcat_executable " -b security -G 256K 2>&1")); 1672 } 1673 1674 static size_t commandOutputSize(const char* command) { 1675 logcat_define(ctx); 1676 FILE* fp = logcat_popen(ctx, command); 1677 if (!fp) return 0; 1678 1679 std::string ret; 1680 if (!android::base::ReadFdToString(fileno(fp), &ret)) return 0; 1681 if (logcat_pclose(ctx, fp) != 0) return 0; 1682 1683 return ret.size(); 1684 } 1685 1686 TEST(logcat, help) { 1687 size_t logcatHelpTextSize = commandOutputSize(logcat_executable " -h 2>&1"); 1688 EXPECT_LT(4096UL, logcatHelpTextSize); 1689 size_t logcatLastHelpTextSize = 1690 commandOutputSize(logcat_executable " -L -h 2>&1"); 1691 #ifdef USING_LOGCAT_EXECUTABLE_DEFAULT // logcat and liblogcat 1692 EXPECT_EQ(logcatHelpTextSize, logcatLastHelpTextSize); 1693 #else 1694 // logcatd -L -h prints the help twice, as designed. 1695 EXPECT_EQ(logcatHelpTextSize * 2, logcatLastHelpTextSize); 1696 #endif 1697 } 1698
