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