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