1 /* 2 * Copyright (C) 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 <fcntl.h> 18 #include <inttypes.h> 19 #include <poll.h> 20 #include <signal.h> 21 #include <stdio.h> 22 #include <string.h> 23 #include <sys/stat.h> 24 #include <sys/types.h> 25 #include <unistd.h> 26 27 #include <string> 28 29 #include <android-base/macros.h> 30 #include <android-base/stringprintf.h> 31 #include <cutils/sockets.h> 32 #include <gtest/gtest.h> 33 #include <log/log.h> 34 #include <private/android_filesystem_config.h> 35 #ifdef __ANDROID__ 36 #include <selinux/selinux.h> 37 #endif 38 39 #include "../LogReader.h" // pickup LOGD_SNDTIMEO 40 #include "../libaudit.h" // pickup AUDIT_RATE_LIMIT_* 41 42 static void send_to_control(char* buf, size_t len) { 43 int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, 44 SOCK_STREAM); 45 if (sock >= 0) { 46 if (write(sock, buf, strlen(buf) + 1) > 0) { 47 ssize_t ret; 48 while ((ret = read(sock, buf, len)) > 0) { 49 if (((size_t)ret == len) || (len < PAGE_SIZE)) { 50 break; 51 } 52 len -= ret; 53 buf += ret; 54 55 struct pollfd p = {.fd = sock, .events = POLLIN, .revents = 0 }; 56 57 ret = poll(&p, 1, 20); 58 if ((ret <= 0) || !(p.revents & POLLIN)) { 59 break; 60 } 61 } 62 } 63 close(sock); 64 } 65 } 66 67 /* 68 * returns statistics 69 */ 70 static void my_android_logger_get_statistics(char* buf, size_t len) { 71 snprintf(buf, len, "getStatistics 0 1 2 3 4"); 72 send_to_control(buf, len); 73 } 74 75 static void alloc_statistics(char** buffer, size_t* length) { 76 size_t len = 8192; 77 char* buf; 78 79 for (int retry = 32; (retry >= 0); delete[] buf, --retry) { 80 buf = new char[len]; 81 my_android_logger_get_statistics(buf, len); 82 83 buf[len - 1] = '\0'; 84 size_t ret = atol(buf) + 1; 85 if (ret < 4) { 86 delete[] buf; 87 buf = NULL; 88 break; 89 } 90 bool check = ret <= len; 91 len = ret; 92 if (check) { 93 break; 94 } 95 len += len / 8; // allow for some slop 96 } 97 *buffer = buf; 98 *length = len; 99 } 100 101 static char* find_benchmark_spam(char* cp) { 102 // liblog_benchmarks has been run designed to SPAM. The signature of 103 // a noisiest UID statistics is: 104 // 105 // Chattiest UIDs in main log buffer: Size Pruned 106 // UID PACKAGE BYTES LINES 107 // 0 root 54164 147569 108 // 109 char* benchmark = NULL; 110 do { 111 static const char signature[] = "\n0 root "; 112 113 benchmark = strstr(cp, signature); 114 if (!benchmark) { 115 break; 116 } 117 cp = benchmark + sizeof(signature); 118 while (isspace(*cp)) { 119 ++cp; 120 } 121 benchmark = cp; 122 #ifdef DEBUG 123 char* end = strstr(benchmark, "\n"); 124 if (end == NULL) { 125 end = benchmark + strlen(benchmark); 126 } 127 fprintf(stderr, "parse for spam counter in \"%.*s\"\n", 128 (int)(end - benchmark), benchmark); 129 #endif 130 // content 131 while (isdigit(*cp)) { 132 ++cp; 133 } 134 while (isspace(*cp)) { 135 ++cp; 136 } 137 // optional +/- field? 138 if ((*cp == '-') || (*cp == '+')) { 139 while (isdigit(*++cp) || (*cp == '.') || (*cp == '%') || 140 (*cp == 'X')) { 141 ; 142 } 143 while (isspace(*cp)) { 144 ++cp; 145 } 146 } 147 // number of entries pruned 148 unsigned long value = 0; 149 while (isdigit(*cp)) { 150 value = value * 10ULL + *cp - '0'; 151 ++cp; 152 } 153 if (value > 10UL) { 154 break; 155 } 156 benchmark = NULL; 157 } while (*cp); 158 return benchmark; 159 } 160 161 TEST(logd, statistics) { 162 size_t len; 163 char* buf; 164 165 alloc_statistics(&buf, &len); 166 167 ASSERT_TRUE(NULL != buf); 168 169 // remove trailing FF 170 char* cp = buf + len - 1; 171 *cp = '\0'; 172 bool truncated = *--cp != '\f'; 173 if (!truncated) { 174 *cp = '\0'; 175 } 176 177 // squash out the byte count 178 cp = buf; 179 if (!truncated) { 180 while (isdigit(*cp) || (*cp == '\n')) { 181 ++cp; 182 } 183 } 184 185 fprintf(stderr, "%s", cp); 186 187 EXPECT_LT((size_t)64, strlen(cp)); 188 189 EXPECT_EQ(0, truncated); 190 191 char* main_logs = strstr(cp, "\nChattiest UIDs in main "); 192 EXPECT_TRUE(NULL != main_logs); 193 194 char* radio_logs = strstr(cp, "\nChattiest UIDs in radio "); 195 if (!radio_logs) 196 GTEST_LOG_(INFO) << "Value of: NULL != radio_logs\n" 197 "Actual: false\n" 198 "Expected: false\n"; 199 200 char* system_logs = strstr(cp, "\nChattiest UIDs in system "); 201 EXPECT_TRUE(NULL != system_logs); 202 203 char* events_logs = strstr(cp, "\nChattiest UIDs in events "); 204 EXPECT_TRUE(NULL != events_logs); 205 206 delete[] buf; 207 } 208 209 static void caught_signal(int /* signum */) { 210 } 211 212 static void dump_log_msg(const char* prefix, log_msg* msg, unsigned int version, 213 int lid) { 214 std::cout << std::flush; 215 std::cerr << std::flush; 216 fflush(stdout); 217 fflush(stderr); 218 switch (msg->entry.hdr_size) { 219 case 0: 220 version = 1; 221 break; 222 223 case sizeof(msg->entry_v2): /* PLUS case sizeof(msg->entry_v3): */ 224 if (version == 0) { 225 version = (msg->entry_v3.lid < LOG_ID_MAX) ? 3 : 2; 226 } 227 break; 228 229 case sizeof(msg->entry_v4): 230 if (version == 0) { 231 version = 4; 232 } 233 break; 234 } 235 236 fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len()); 237 if (version != 1) { 238 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); 239 } 240 fprintf(stderr, "pid=%u tid=%u %u.%09u ", msg->entry.pid, msg->entry.tid, 241 msg->entry.sec, msg->entry.nsec); 242 switch (version) { 243 case 1: 244 break; 245 case 2: 246 fprintf(stderr, "euid=%u ", msg->entry_v2.euid); 247 break; 248 case 3: 249 default: 250 lid = msg->entry.lid; 251 break; 252 } 253 254 switch (lid) { 255 case 0: 256 fprintf(stderr, "lid=main "); 257 break; 258 case 1: 259 fprintf(stderr, "lid=radio "); 260 break; 261 case 2: 262 fprintf(stderr, "lid=events "); 263 break; 264 case 3: 265 fprintf(stderr, "lid=system "); 266 break; 267 case 4: 268 fprintf(stderr, "lid=crash "); 269 break; 270 case 5: 271 fprintf(stderr, "lid=security "); 272 break; 273 case 6: 274 fprintf(stderr, "lid=kernel "); 275 break; 276 default: 277 if (lid >= 0) { 278 fprintf(stderr, "lid=%d ", lid); 279 } 280 } 281 282 unsigned int len = msg->entry.len; 283 fprintf(stderr, "msg[%u]={", len); 284 unsigned char* cp = reinterpret_cast<unsigned char*>(msg->msg()); 285 if (!cp) { 286 static const unsigned char garbage[] = "<INVALID>"; 287 cp = const_cast<unsigned char*>(garbage); 288 len = strlen(reinterpret_cast<const char*>(garbage)); 289 } 290 while (len) { 291 unsigned char* p = cp; 292 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { 293 ++p; 294 } 295 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { 296 fprintf(stderr, "\""); 297 while (*cp) { 298 if (*cp != '\n') { 299 fprintf(stderr, "%c", *cp); 300 } else { 301 fprintf(stderr, "\\n"); 302 } 303 ++cp; 304 --len; 305 } 306 fprintf(stderr, "\""); 307 } else { 308 fprintf(stderr, "%02x", *cp); 309 } 310 ++cp; 311 if (--len) { 312 fprintf(stderr, ", "); 313 } 314 } 315 fprintf(stderr, "}\n"); 316 fflush(stderr); 317 } 318 319 TEST(logd, both) { 320 log_msg msg; 321 322 // check if we can read any logs from logd 323 bool user_logger_available = false; 324 bool user_logger_content = false; 325 326 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, 327 SOCK_SEQPACKET); 328 if (fd >= 0) { 329 struct sigaction ignore, old_sigaction; 330 memset(&ignore, 0, sizeof(ignore)); 331 ignore.sa_handler = caught_signal; 332 sigemptyset(&ignore.sa_mask); 333 sigaction(SIGALRM, &ignore, &old_sigaction); 334 unsigned int old_alarm = alarm(10); 335 336 static const char ask[] = "dumpAndClose lids=0,1,2,3"; 337 user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask); 338 339 user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0; 340 341 if (user_logger_content) { 342 dump_log_msg("user", &msg, 3, -1); 343 } 344 345 alarm(old_alarm); 346 sigaction(SIGALRM, &old_sigaction, NULL); 347 348 close(fd); 349 } 350 351 // check if we can read any logs from kernel logger 352 bool kernel_logger_available = false; 353 bool kernel_logger_content = false; 354 355 static const char* loggers[] = { 356 "/dev/log/main", "/dev/log_main", "/dev/log/radio", 357 "/dev/log_radio", "/dev/log/events", "/dev/log_events", 358 "/dev/log/system", "/dev/log_system", 359 }; 360 361 for (unsigned int i = 0; i < arraysize(loggers); ++i) { 362 fd = open(loggers[i], O_RDONLY); 363 if (fd < 0) { 364 continue; 365 } 366 kernel_logger_available = true; 367 fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK); 368 int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg))); 369 if (result > 0) { 370 kernel_logger_content = true; 371 dump_log_msg("kernel", &msg, 0, i / 2); 372 } 373 close(fd); 374 } 375 376 static const char yes[] = "\xE2\x9C\x93"; 377 static const char no[] = "\xE2\x9c\x98"; 378 fprintf(stderr, 379 "LOGGER Available Content\n" 380 "user %-13s%s\n" 381 "kernel %-13s%s\n" 382 " status %-11s%s\n", 383 (user_logger_available) ? yes : no, (user_logger_content) ? yes : no, 384 (kernel_logger_available) ? yes : no, 385 (kernel_logger_content) ? yes : no, 386 (user_logger_available && kernel_logger_available) ? "ERROR" : "ok", 387 (user_logger_content && kernel_logger_content) ? "ERROR" : "ok"); 388 389 EXPECT_EQ(0, user_logger_available && kernel_logger_available); 390 EXPECT_EQ(0, !user_logger_available && !kernel_logger_available); 391 EXPECT_EQ(0, user_logger_content && kernel_logger_content); 392 EXPECT_EQ(0, !user_logger_content && !kernel_logger_content); 393 } 394 395 // BAD ROBOT 396 // Benchmark threshold are generally considered bad form unless there is 397 // is some human love applied to the continued maintenance and whether the 398 // thresholds are tuned on a per-target basis. Here we check if the values 399 // are more than double what is expected. Doubling will not prevent failure 400 // on busy or low-end systems that could have a tendency to stretch values. 401 // 402 // The primary goal of this test is to simulate a spammy app (benchmark 403 // being the worst) and check to make sure the logger can deal with it 404 // appropriately by checking all the statistics are in an expected range. 405 // 406 TEST(logd, benchmark) { 407 size_t len; 408 char* buf; 409 410 alloc_statistics(&buf, &len); 411 bool benchmark_already_run = buf && find_benchmark_spam(buf); 412 delete[] buf; 413 414 if (benchmark_already_run) { 415 fprintf(stderr, 416 "WARNING: spam already present and too much history\n" 417 " false OK for prune by worst UID check\n"); 418 } 419 420 FILE* fp; 421 422 // Introduce some extreme spam for the worst UID filter 423 ASSERT_TRUE( 424 NULL != 425 (fp = popen("/data/nativetest/liblog-benchmarks/liblog-benchmarks" 426 " BM_log_maximum_retry" 427 " BM_log_maximum" 428 " BM_clock_overhead" 429 " BM_log_overhead" 430 " BM_log_latency" 431 " BM_log_delay", 432 "r"))); 433 434 char buffer[5120]; 435 436 static const char* benchmarks[] = { 437 "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ", 438 "BM_log_overhead ", "BM_log_latency ", "BM_log_delay " 439 }; 440 static const unsigned int log_maximum_retry = 0; 441 static const unsigned int log_maximum = 1; 442 static const unsigned int clock_overhead = 2; 443 static const unsigned int log_overhead = 3; 444 static const unsigned int log_latency = 4; 445 static const unsigned int log_delay = 5; 446 447 unsigned long ns[arraysize(benchmarks)]; 448 449 memset(ns, 0, sizeof(ns)); 450 451 while (fgets(buffer, sizeof(buffer), fp)) { 452 for (unsigned i = 0; i < arraysize(ns); ++i) { 453 char* cp = strstr(buffer, benchmarks[i]); 454 if (!cp) { 455 continue; 456 } 457 sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]); 458 fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); 459 } 460 } 461 int ret = pclose(fp); 462 463 if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { 464 fprintf(stderr, 465 "WARNING: " 466 "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" 467 " can not perform test\n"); 468 return; 469 } 470 471 EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user 472 473 EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user 474 475 EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 476 477 EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user 478 479 EXPECT_GE(10000000UL, 480 ns[log_latency]); // 1453559 user space (background cgroup) 481 482 EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user 483 484 for (unsigned i = 0; i < arraysize(ns); ++i) { 485 EXPECT_NE(0UL, ns[i]); 486 } 487 488 alloc_statistics(&buf, &len); 489 490 bool collected_statistics = !!buf; 491 EXPECT_EQ(true, collected_statistics); 492 493 ASSERT_TRUE(NULL != buf); 494 495 char* benchmark_statistics_found = find_benchmark_spam(buf); 496 ASSERT_TRUE(benchmark_statistics_found != NULL); 497 498 // Check how effective the SPAM filter is, parse out Now size. 499 // 0 root 54164 147569 500 // ^-- benchmark_statistics_found 501 502 unsigned long nowSpamSize = atol(benchmark_statistics_found); 503 504 delete[] buf; 505 506 ASSERT_NE(0UL, nowSpamSize); 507 508 // Determine if we have the spam filter enabled 509 int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, 510 SOCK_STREAM); 511 512 ASSERT_TRUE(sock >= 0); 513 514 static const char getPruneList[] = "getPruneList"; 515 if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { 516 char buffer[80]; 517 memset(buffer, 0, sizeof(buffer)); 518 read(sock, buffer, sizeof(buffer)); 519 char* cp = strchr(buffer, '\n'); 520 if (!cp || (cp[1] != '~') || (cp[2] != '!')) { 521 close(sock); 522 fprintf(stderr, 523 "WARNING: " 524 "Logger has SPAM filtration turned off \"%s\"\n", 525 buffer); 526 return; 527 } 528 } else { 529 int save_errno = errno; 530 close(sock); 531 FAIL() << "Can not send " << getPruneList << " to logger -- " 532 << strerror(save_errno); 533 } 534 535 static const unsigned long expected_absolute_minimum_log_size = 65536UL; 536 unsigned long totalSize = expected_absolute_minimum_log_size; 537 static const char getSize[] = { 'g', 'e', 't', 'L', 'o', 'g', 538 'S', 'i', 'z', 'e', ' ', LOG_ID_MAIN + '0', 539 '\0' }; 540 if (write(sock, getSize, sizeof(getSize)) > 0) { 541 char buffer[80]; 542 memset(buffer, 0, sizeof(buffer)); 543 read(sock, buffer, sizeof(buffer)); 544 totalSize = atol(buffer); 545 if (totalSize < expected_absolute_minimum_log_size) { 546 fprintf(stderr, 547 "WARNING: " 548 "Logger had unexpected referenced size \"%s\"\n", 549 buffer); 550 totalSize = expected_absolute_minimum_log_size; 551 } 552 } 553 close(sock); 554 555 // logd allows excursions to 110% of total size 556 totalSize = (totalSize * 11) / 10; 557 558 // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) 559 ASSERT_GT(totalSize, nowSpamSize * 2); 560 } 561 562 // b/26447386 confirm fixed 563 void timeout_negative(const char* command) { 564 log_msg msg_wrap, msg_timeout; 565 bool content_wrap = false, content_timeout = false, written = false; 566 unsigned int alarm_wrap = 0, alarm_timeout = 0; 567 // A few tries to get it right just in case wrap kicks in due to 568 // content providers being active during the test. 569 int i = 3; 570 571 while (--i) { 572 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, 573 SOCK_SEQPACKET); 574 ASSERT_LT(0, fd); 575 576 std::string ask(command); 577 578 struct sigaction ignore, old_sigaction; 579 memset(&ignore, 0, sizeof(ignore)); 580 ignore.sa_handler = caught_signal; 581 sigemptyset(&ignore.sa_mask); 582 sigaction(SIGALRM, &ignore, &old_sigaction); 583 unsigned int old_alarm = alarm(3); 584 585 size_t len = ask.length() + 1; 586 written = write(fd, ask.c_str(), len) == (ssize_t)len; 587 if (!written) { 588 alarm(old_alarm); 589 sigaction(SIGALRM, &old_sigaction, NULL); 590 close(fd); 591 continue; 592 } 593 594 // alarm triggers at 50% of the --wrap time out 595 content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; 596 597 alarm_wrap = alarm(5); 598 599 // alarm triggers at 133% of the --wrap time out 600 content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; 601 if (!content_timeout) { // make sure we hit dumpAndClose 602 content_timeout = 603 recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; 604 } 605 606 alarm_timeout = 607 alarm((old_alarm <= 0) ? old_alarm 608 : (old_alarm > (1 + 3 - alarm_wrap)) 609 ? old_alarm - 3 + alarm_wrap 610 : 2); 611 sigaction(SIGALRM, &old_sigaction, NULL); 612 613 close(fd); 614 615 if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { 616 break; 617 } 618 } 619 620 if (content_wrap) { 621 dump_log_msg("wrap", &msg_wrap, 3, -1); 622 } 623 624 if (content_timeout) { 625 dump_log_msg("timeout", &msg_timeout, 3, -1); 626 } 627 628 EXPECT_TRUE(written); 629 EXPECT_TRUE(content_wrap); 630 EXPECT_NE(0U, alarm_wrap); 631 EXPECT_TRUE(content_timeout); 632 EXPECT_NE(0U, alarm_timeout); 633 } 634 635 TEST(logd, timeout_no_start) { 636 timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6"); 637 } 638 639 TEST(logd, timeout_start_epoch) { 640 timeout_negative( 641 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000"); 642 } 643 644 // b/26447386 refined behavior 645 TEST(logd, timeout) { 646 // b/33962045 This test interferes with other log reader tests that 647 // follow because of file descriptor socket persistence in the same 648 // process. So let's fork it to isolate it from giving us pain. 649 650 pid_t pid = fork(); 651 652 if (pid) { 653 siginfo_t info = {}; 654 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); 655 ASSERT_EQ(0, info.si_status); 656 return; 657 } 658 659 log_msg msg_wrap, msg_timeout; 660 bool content_wrap = false, content_timeout = false, written = false; 661 unsigned int alarm_wrap = 0, alarm_timeout = 0; 662 // A few tries to get it right just in case wrap kicks in due to 663 // content providers being active during the test. 664 int i = 5; 665 log_time now(android_log_clockid()); 666 now.tv_sec -= 30; // reach back a moderate period of time 667 668 while (--i) { 669 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, 670 SOCK_SEQPACKET); 671 int save_errno = errno; 672 if (fd < 0) { 673 fprintf(stderr, "failed to open /dev/socket/logdr %s\n", 674 strerror(save_errno)); 675 _exit(fd); 676 } 677 678 std::string ask = android::base::StringPrintf( 679 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32 680 ".%09" PRIu32, 681 now.tv_sec, now.tv_nsec); 682 683 struct sigaction ignore, old_sigaction; 684 memset(&ignore, 0, sizeof(ignore)); 685 ignore.sa_handler = caught_signal; 686 sigemptyset(&ignore.sa_mask); 687 sigaction(SIGALRM, &ignore, &old_sigaction); 688 unsigned int old_alarm = alarm(3); 689 690 size_t len = ask.length() + 1; 691 written = write(fd, ask.c_str(), len) == (ssize_t)len; 692 if (!written) { 693 alarm(old_alarm); 694 sigaction(SIGALRM, &old_sigaction, NULL); 695 close(fd); 696 continue; 697 } 698 699 // alarm triggers at 50% of the --wrap time out 700 content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; 701 702 alarm_wrap = alarm(5); 703 704 // alarm triggers at 133% of the --wrap time out 705 content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; 706 if (!content_timeout) { // make sure we hit dumpAndClose 707 content_timeout = 708 recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; 709 } 710 711 alarm_timeout = 712 alarm((old_alarm <= 0) ? old_alarm 713 : (old_alarm > (1 + 3 - alarm_wrap)) 714 ? old_alarm - 3 + alarm_wrap 715 : 2); 716 sigaction(SIGALRM, &old_sigaction, NULL); 717 718 close(fd); 719 720 if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { 721 break; 722 } 723 724 // modify start time in case content providers are relatively 725 // active _or_ inactive during the test. 726 if (content_timeout) { 727 log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); 728 if (msg < now) { 729 fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec, 730 msg_timeout.entry.nsec, (unsigned)now.tv_sec, 731 (unsigned)now.tv_nsec); 732 _exit(-1); 733 } 734 if (msg > now) { 735 now = msg; 736 now.tv_sec += 30; 737 msg = log_time(android_log_clockid()); 738 if (now > msg) { 739 now = msg; 740 --now.tv_sec; 741 } 742 } 743 } else { 744 now.tv_sec -= 120; // inactive, reach further back! 745 } 746 } 747 748 if (content_wrap) { 749 dump_log_msg("wrap", &msg_wrap, 3, -1); 750 } 751 752 if (content_timeout) { 753 dump_log_msg("timeout", &msg_timeout, 3, -1); 754 } 755 756 if (content_wrap || !content_timeout) { 757 fprintf(stderr, "now=%" PRIu32 ".%09" PRIu32 "\n", now.tv_sec, 758 now.tv_nsec); 759 } 760 761 EXPECT_TRUE(written); 762 EXPECT_FALSE(content_wrap); 763 EXPECT_EQ(0U, alarm_wrap); 764 EXPECT_TRUE(content_timeout); 765 EXPECT_NE(0U, alarm_timeout); 766 767 _exit(!written + content_wrap + alarm_wrap + !content_timeout + 768 !alarm_timeout); 769 } 770 771 // b/27242723 confirmed fixed 772 TEST(logd, SNDTIMEO) { 773 static const unsigned sndtimeo = 774 LOGD_SNDTIMEO; // <sigh> it has to be done! 775 static const unsigned sleep_time = sndtimeo + 3; 776 static const unsigned alarm_time = sleep_time + 5; 777 778 int fd; 779 780 ASSERT_TRUE( 781 (fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, 782 SOCK_SEQPACKET)) > 0); 783 784 struct sigaction ignore, old_sigaction; 785 memset(&ignore, 0, sizeof(ignore)); 786 ignore.sa_handler = caught_signal; 787 sigemptyset(&ignore.sa_mask); 788 sigaction(SIGALRM, &ignore, &old_sigaction); 789 unsigned int old_alarm = alarm(alarm_time); 790 791 static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources 792 bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask); 793 EXPECT_TRUE(reader_requested); 794 795 log_msg msg; 796 bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0; 797 798 EXPECT_TRUE(read_one); 799 if (read_one) { 800 dump_log_msg("user", &msg, 3, -1); 801 } 802 803 fprintf(stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo); 804 sleep(sleep_time); 805 806 // flush will block if we did not trigger. if it did, last entry returns 0 807 int recv_ret; 808 do { 809 recv_ret = recv(fd, msg.buf, sizeof(msg), 0); 810 } while (recv_ret > 0); 811 int save_errno = (recv_ret < 0) ? errno : 0; 812 813 EXPECT_NE(0U, alarm(old_alarm)); 814 sigaction(SIGALRM, &old_sigaction, NULL); 815 816 EXPECT_EQ(0, recv_ret); 817 if (recv_ret > 0) { 818 dump_log_msg("user", &msg, 3, -1); 819 } 820 EXPECT_EQ(0, save_errno); 821 822 close(fd); 823 } 824 825 TEST(logd, getEventTag_list) { 826 #ifdef __ANDROID__ 827 char buffer[256]; 828 memset(buffer, 0, sizeof(buffer)); 829 snprintf(buffer, sizeof(buffer), "getEventTag name=*"); 830 send_to_control(buffer, sizeof(buffer)); 831 buffer[sizeof(buffer) - 1] = '\0'; 832 char* cp; 833 long ret = strtol(buffer, &cp, 10); 834 EXPECT_GT(ret, 4096); 835 #else 836 GTEST_LOG_(INFO) << "This test does nothing.\n"; 837 #endif 838 } 839 840 TEST(logd, getEventTag_42) { 841 #ifdef __ANDROID__ 842 char buffer[256]; 843 memset(buffer, 0, sizeof(buffer)); 844 snprintf(buffer, sizeof(buffer), "getEventTag id=42"); 845 send_to_control(buffer, sizeof(buffer)); 846 buffer[sizeof(buffer) - 1] = '\0'; 847 char* cp; 848 long ret = strtol(buffer, &cp, 10); 849 EXPECT_GT(ret, 16); 850 EXPECT_TRUE(strstr(buffer, "\t(to life the universe etc|3)") != NULL); 851 EXPECT_TRUE(strstr(buffer, "answer") != NULL); 852 #else 853 GTEST_LOG_(INFO) << "This test does nothing.\n"; 854 #endif 855 } 856 857 TEST(logd, getEventTag_newentry) { 858 #ifdef __ANDROID__ 859 char buffer[256]; 860 memset(buffer, 0, sizeof(buffer)); 861 log_time now(CLOCK_MONOTONIC); 862 char name[64]; 863 snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); 864 snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", 865 name); 866 send_to_control(buffer, sizeof(buffer)); 867 buffer[sizeof(buffer) - 1] = '\0'; 868 char* cp; 869 long ret = strtol(buffer, &cp, 10); 870 EXPECT_GT(ret, 16); 871 EXPECT_TRUE(strstr(buffer, "\t(new|1)") != NULL); 872 EXPECT_TRUE(strstr(buffer, name) != NULL); 873 // ToDo: also look for this in /data/misc/logd/event-log-tags and 874 // /dev/event-log-tags. 875 #else 876 GTEST_LOG_(INFO) << "This test does nothing.\n"; 877 #endif 878 } 879 880 static inline int32_t get4LE(const char* src) { 881 return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); 882 } 883 884 void __android_log_btwrite_multiple__helper(int count) { 885 log_time ts(CLOCK_MONOTONIC); 886 887 log_time ts1(CLOCK_MONOTONIC); 888 889 // We fork to create a unique pid for the submitted log messages 890 // so that we do not collide with the other _multiple_ tests. 891 892 pid_t pid = fork(); 893 894 if (pid == 0) { 895 // child 896 for (int i = count; i; --i) { 897 ASSERT_LT( 898 0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); 899 usleep(100); 900 } 901 ASSERT_LT(0, 902 __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1))); 903 usleep(1000000); 904 905 _exit(0); 906 } 907 908 siginfo_t info = {}; 909 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); 910 ASSERT_EQ(0, info.si_status); 911 912 struct logger_list* logger_list; 913 ASSERT_TRUE(NULL != 914 (logger_list = android_logger_list_open( 915 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 916 0, pid))); 917 918 int expected_count = (count < 2) ? count : 2; 919 int expected_chatty_count = (count <= 2) ? 0 : 1; 920 int expected_identical_count = (count < 2) ? 0 : (count - 2); 921 static const int expected_expire_count = 0; 922 923 count = 0; 924 int second_count = 0; 925 int chatty_count = 0; 926 int identical_count = 0; 927 int expire_count = 0; 928 929 for (;;) { 930 log_msg log_msg; 931 if (android_logger_list_read(logger_list, &log_msg) <= 0) break; 932 933 if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) || 934 (log_msg.id() != LOG_ID_EVENTS)) 935 continue; 936 937 char* eventData = log_msg.msg(); 938 if (!eventData) continue; 939 940 uint32_t tag = get4LE(eventData); 941 942 if ((eventData[4] == EVENT_TYPE_LONG) && 943 (log_msg.entry.len == (4 + 1 + 8))) { 944 if (tag != 0) continue; 945 946 log_time tx(eventData + 4 + 1); 947 if (ts == tx) { 948 ++count; 949 } else if (ts1 == tx) { 950 ++second_count; 951 } 952 } else if (eventData[4] == EVENT_TYPE_STRING) { 953 if (tag != CHATTY_LOG_TAG) continue; 954 ++chatty_count; 955 // int len = get4LE(eventData + 4 + 1); 956 log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0'; 957 const char* cp; 958 if ((cp = strstr(eventData + 4 + 1 + 4, " identical "))) { 959 unsigned val = 0; 960 sscanf(cp, " identical %u lines", &val); 961 identical_count += val; 962 } else if ((cp = strstr(eventData + 4 + 1 + 4, " expire "))) { 963 unsigned val = 0; 964 sscanf(cp, " expire %u lines", &val); 965 expire_count += val; 966 } 967 } 968 } 969 970 android_logger_list_close(logger_list); 971 972 EXPECT_EQ(expected_count, count); 973 EXPECT_EQ(1, second_count); 974 EXPECT_EQ(expected_chatty_count, chatty_count); 975 EXPECT_EQ(expected_identical_count, identical_count); 976 EXPECT_EQ(expected_expire_count, expire_count); 977 } 978 979 TEST(logd, multiple_test_1) { 980 __android_log_btwrite_multiple__helper(1); 981 } 982 983 TEST(logd, multiple_test_2) { 984 __android_log_btwrite_multiple__helper(2); 985 } 986 987 TEST(logd, multiple_test_3) { 988 __android_log_btwrite_multiple__helper(3); 989 } 990 991 TEST(logd, multiple_test_10) { 992 __android_log_btwrite_multiple__helper(10); 993 } 994 995 #ifdef __ANDROID__ 996 // returns violating pid 997 static pid_t sepolicy_rate(unsigned rate, unsigned num) { 998 pid_t pid = fork(); 999 1000 if (pid) { 1001 siginfo_t info = {}; 1002 if (TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))) return 0; 1003 if (info.si_status) return 0; 1004 return pid; 1005 } 1006 1007 // We may have DAC, but let's not have MAC 1008 if (setcon("u:object_r:shell:s0") < 0) { 1009 int save_errno = errno; 1010 security_context_t context; 1011 getcon(&context); 1012 fprintf(stderr, "setcon(\"u:r:shell:s0\") failed @\"%s\" %s\n", context, 1013 strerror(save_errno)); 1014 freecon(context); 1015 _exit(-1); 1016 // NOTREACHED 1017 return 0; 1018 } 1019 1020 // The key here is we are root, but we are in u:r:shell:s0, 1021 // and the directory does not provide us DAC access 1022 // (eg: 0700 system system) so we trigger the pair dac_override 1023 // and dac_read_search on every try to get past the message 1024 // de-duper. We will also rotate the file name in the directory 1025 // as another measure. 1026 static const char file[] = "/data/backup/cannot_access_directory_%u"; 1027 static const unsigned avc_requests_per_access = 2; 1028 1029 rate /= avc_requests_per_access; 1030 useconds_t usec; 1031 if (rate == 0) { 1032 rate = 1; 1033 usec = 2000000; 1034 } else { 1035 usec = (1000000 + (rate / 2)) / rate; 1036 } 1037 num = (num + (avc_requests_per_access / 2)) / avc_requests_per_access; 1038 1039 if (usec < 2) usec = 2; 1040 1041 while (num > 0) { 1042 if (access(android::base::StringPrintf(file, num).c_str(), F_OK) == 0) { 1043 _exit(-1); 1044 // NOTREACHED 1045 return 0; 1046 } 1047 usleep(usec); 1048 --num; 1049 } 1050 _exit(0); 1051 // NOTREACHED 1052 return 0; 1053 } 1054 1055 static int count_avc(pid_t pid) { 1056 int count = 0; 1057 1058 if (pid == 0) return count; 1059 1060 struct logger_list* logger_list; 1061 if (!(logger_list = android_logger_list_open( 1062 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, pid))) 1063 return count; 1064 for (;;) { 1065 log_msg log_msg; 1066 1067 if (android_logger_list_read(logger_list, &log_msg) <= 0) break; 1068 1069 if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) || 1070 (log_msg.id() != LOG_ID_EVENTS)) 1071 continue; 1072 1073 char* eventData = log_msg.msg(); 1074 if (!eventData) continue; 1075 1076 uint32_t tag = get4LE(eventData); 1077 if (tag != AUDITD_LOG_TAG) continue; 1078 1079 if (eventData[4] != EVENT_TYPE_STRING) continue; 1080 1081 // int len = get4LE(eventData + 4 + 1); 1082 log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0'; 1083 const char* cp = strstr(eventData + 4 + 1 + 4, "): avc: denied"); 1084 if (!cp) continue; 1085 1086 ++count; 1087 } 1088 1089 android_logger_list_close(logger_list); 1090 1091 return count; 1092 } 1093 #endif 1094 1095 TEST(logd, sepolicy_rate_limiter_maximum) { 1096 #ifdef __ANDROID__ 1097 static const int rate = AUDIT_RATE_LIMIT_MAX; 1098 static const int duration = 2; 1099 // Two seconds of a liveable sustained rate 1100 EXPECT_EQ(rate * duration, count_avc(sepolicy_rate(rate, rate * duration))); 1101 #else 1102 GTEST_LOG_(INFO) << "This test does nothing.\n"; 1103 #endif 1104 } 1105 1106 TEST(logd, sepolicy_rate_limiter_sub_burst) { 1107 #ifdef __ANDROID__ 1108 // maximum period below half way between sustainable and burst rate. 1109 static const int threshold = 1110 ((AUDIT_RATE_LIMIT_BURST_DURATION * 1111 (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) + 1112 1) / 1113 2; 1114 static const int rate = (threshold / AUDIT_RATE_LIMIT_BURST_DURATION) - 1; 1115 static const int duration = AUDIT_RATE_LIMIT_BURST_DURATION; 1116 EXPECT_EQ(rate * duration, count_avc(sepolicy_rate(rate, rate * duration))); 1117 #else 1118 GTEST_LOG_(INFO) << "This test does nothing.\n"; 1119 #endif 1120 } 1121 1122 TEST(logd, sepolicy_rate_limiter_spam) { 1123 #ifdef __ANDROID__ 1124 // maximum period of double the maximum burst rate 1125 static const int threshold = 1126 ((AUDIT_RATE_LIMIT_BURST_DURATION * 1127 (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) + 1128 1) / 1129 2; 1130 static const int rate = AUDIT_RATE_LIMIT_DEFAULT * 2; 1131 static const int duration = threshold / AUDIT_RATE_LIMIT_DEFAULT; 1132 EXPECT_GE( 1133 ((AUDIT_RATE_LIMIT_DEFAULT * duration) * 115) / 100, // +15% margin 1134 count_avc(sepolicy_rate(rate, rate * duration))); 1135 // give logd another 3 seconds to react to the burst before checking 1136 sepolicy_rate(rate, rate * 3); 1137 // maximum period at double the maximum burst rate (spam filter kicked in) 1138 EXPECT_GE( 1139 threshold * 2, 1140 count_avc(sepolicy_rate(rate, rate * AUDIT_RATE_LIMIT_BURST_DURATION))); 1141 // cool down, and check unspammy rate still works 1142 sleep(2); 1143 EXPECT_LE(AUDIT_RATE_LIMIT_BURST_DURATION - 1, // allow _one_ to be lost 1144 count_avc(sepolicy_rate(1, AUDIT_RATE_LIMIT_BURST_DURATION))); 1145 #else 1146 GTEST_LOG_(INFO) << "This test does nothing.\n"; 1147 #endif 1148 } 1149
