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