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