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 if (old_alarm > 0) { 650 unsigned int time_spent = 3 - alarm_wrap; 651 if (old_alarm > time_spent + 1) { 652 old_alarm -= time_spent; 653 } else { 654 old_alarm = 2; 655 } 656 } 657 alarm_timeout = alarm(old_alarm); 658 sigaction(SIGALRM, &old_sigaction, nullptr); 659 660 close(fd); 661 662 if (content_wrap && alarm_wrap && content_timeout && alarm_timeout) { 663 break; 664 } 665 } 666 667 if (content_wrap) { 668 dump_log_msg("wrap", &msg_wrap, 3, -1); 669 } 670 671 if (content_timeout) { 672 dump_log_msg("timeout", &msg_timeout, 3, -1); 673 } 674 675 EXPECT_TRUE(written); 676 EXPECT_TRUE(content_wrap); 677 EXPECT_NE(0U, alarm_wrap); 678 EXPECT_TRUE(content_timeout); 679 EXPECT_NE(0U, alarm_timeout); 680 #else 681 command = nullptr; 682 GTEST_LOG_(INFO) << "This test does nothing.\n"; 683 #endif 684 } 685 686 TEST(logd, timeout_no_start) { 687 timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6"); 688 } 689 690 TEST(logd, timeout_start_epoch) { 691 timeout_negative( 692 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000"); 693 } 694 695 // b/26447386 refined behavior 696 TEST(logd, timeout) { 697 #ifdef __ANDROID__ 698 // b/33962045 This test interferes with other log reader tests that 699 // follow because of file descriptor socket persistence in the same 700 // process. So let's fork it to isolate it from giving us pain. 701 702 pid_t pid = fork(); 703 704 if (pid) { 705 siginfo_t info = {}; 706 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); 707 ASSERT_EQ(0, info.si_status); 708 return; 709 } 710 711 log_msg msg_wrap, msg_timeout; 712 bool content_wrap = false, content_timeout = false, written = false; 713 unsigned int alarm_wrap = 0, alarm_timeout = 0; 714 // A few tries to get it right just in case wrap kicks in due to 715 // content providers being active during the test. 716 int i = 5; 717 log_time start(android_log_clockid()); 718 start.tv_sec -= 30; // reach back a moderate period of time 719 720 while (--i) { 721 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, 722 SOCK_SEQPACKET); 723 int save_errno = errno; 724 if (fd < 0) { 725 fprintf(stderr, "failed to open /dev/socket/logdr %s\n", 726 strerror(save_errno)); 727 _exit(fd); 728 } 729 730 std::string ask = android::base::StringPrintf( 731 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32 732 ".%09" PRIu32, 733 start.tv_sec, start.tv_nsec); 734 735 struct sigaction ignore, old_sigaction; 736 memset(&ignore, 0, sizeof(ignore)); 737 ignore.sa_handler = caught_signal; 738 sigemptyset(&ignore.sa_mask); 739 sigaction(SIGALRM, &ignore, &old_sigaction); 740 unsigned int old_alarm = alarm(3); 741 742 size_t len = ask.length() + 1; 743 written = write(fd, ask.c_str(), len) == (ssize_t)len; 744 if (!written) { 745 alarm(old_alarm); 746 sigaction(SIGALRM, &old_sigaction, nullptr); 747 close(fd); 748 continue; 749 } 750 751 // alarm triggers at 50% of the --wrap time out 752 content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; 753 754 alarm_wrap = alarm(5); 755 756 // alarm triggers at 133% of the --wrap time out 757 content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; 758 if (!content_timeout) { // make sure we hit dumpAndClose 759 content_timeout = 760 recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; 761 } 762 763 if (old_alarm > 0) { 764 unsigned int time_spent = 3 - alarm_wrap; 765 if (old_alarm > time_spent + 1) { 766 old_alarm -= time_spent; 767 } else { 768 old_alarm = 2; 769 } 770 } 771 alarm_timeout = alarm(old_alarm); 772 sigaction(SIGALRM, &old_sigaction, nullptr); 773 774 close(fd); 775 776 if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { 777 break; 778 } 779 780 // modify start time in case content providers are relatively 781 // active _or_ inactive during the test. 782 if (content_timeout) { 783 log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); 784 if (msg < start) { 785 fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec, 786 msg_timeout.entry.nsec, (unsigned)start.tv_sec, 787 (unsigned)start.tv_nsec); 788 _exit(-1); 789 } 790 if (msg > start) { 791 start = msg; 792 start.tv_sec += 30; 793 log_time now = log_time(android_log_clockid()); 794 if (start > now) { 795 start = now; 796 --start.tv_sec; 797 } 798 } 799 } else { 800 start.tv_sec -= 120; // inactive, reach further back! 801 } 802 } 803 804 if (content_wrap) { 805 dump_log_msg("wrap", &msg_wrap, 3, -1); 806 } 807 808 if (content_timeout) { 809 dump_log_msg("timeout", &msg_timeout, 3, -1); 810 } 811 812 if (content_wrap || !content_timeout) { 813 fprintf(stderr, "start=%" PRIu32 ".%09" PRIu32 "\n", start.tv_sec, 814 start.tv_nsec); 815 } 816 817 EXPECT_TRUE(written); 818 EXPECT_FALSE(content_wrap); 819 EXPECT_EQ(0U, alarm_wrap); 820 EXPECT_TRUE(content_timeout); 821 EXPECT_NE(0U, alarm_timeout); 822 823 _exit(!written + content_wrap + alarm_wrap + !content_timeout + 824 !alarm_timeout); 825 #else 826 GTEST_LOG_(INFO) << "This test does nothing.\n"; 827 #endif 828 } 829 830 // b/27242723 confirmed fixed 831 TEST(logd, SNDTIMEO) { 832 #ifdef __ANDROID__ 833 static const unsigned sndtimeo = 834 LOGD_SNDTIMEO; // <sigh> it has to be done! 835 static const unsigned sleep_time = sndtimeo + 3; 836 static const unsigned alarm_time = sleep_time + 5; 837 838 int fd; 839 840 ASSERT_TRUE( 841 (fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, 842 SOCK_SEQPACKET)) > 0); 843 844 struct sigaction ignore, old_sigaction; 845 memset(&ignore, 0, sizeof(ignore)); 846 ignore.sa_handler = caught_signal; 847 sigemptyset(&ignore.sa_mask); 848 sigaction(SIGALRM, &ignore, &old_sigaction); 849 unsigned int old_alarm = alarm(alarm_time); 850 851 static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources 852 bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask); 853 EXPECT_TRUE(reader_requested); 854 855 log_msg msg; 856 bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0; 857 858 EXPECT_TRUE(read_one); 859 if (read_one) { 860 dump_log_msg("user", &msg, 3, -1); 861 } 862 863 fprintf(stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo); 864 sleep(sleep_time); 865 866 // flush will block if we did not trigger. if it did, last entry returns 0 867 int recv_ret; 868 do { 869 recv_ret = recv(fd, msg.buf, sizeof(msg), 0); 870 } while (recv_ret > 0); 871 int save_errno = (recv_ret < 0) ? errno : 0; 872 873 EXPECT_NE(0U, alarm(old_alarm)); 874 sigaction(SIGALRM, &old_sigaction, nullptr); 875 876 EXPECT_EQ(0, recv_ret); 877 if (recv_ret > 0) { 878 dump_log_msg("user", &msg, 3, -1); 879 } 880 EXPECT_EQ(0, save_errno); 881 882 close(fd); 883 #else 884 GTEST_LOG_(INFO) << "This test does nothing.\n"; 885 #endif 886 } 887 888 TEST(logd, getEventTag_list) { 889 #ifdef __ANDROID__ 890 char buffer[256]; 891 memset(buffer, 0, sizeof(buffer)); 892 snprintf(buffer, sizeof(buffer), "getEventTag name=*"); 893 send_to_control(buffer, sizeof(buffer)); 894 buffer[sizeof(buffer) - 1] = '\0'; 895 char* cp; 896 long ret = strtol(buffer, &cp, 10); 897 EXPECT_GT(ret, 4096); 898 #else 899 GTEST_LOG_(INFO) << "This test does nothing.\n"; 900 #endif 901 } 902 903 TEST(logd, getEventTag_42) { 904 #ifdef __ANDROID__ 905 char buffer[256]; 906 memset(buffer, 0, sizeof(buffer)); 907 snprintf(buffer, sizeof(buffer), "getEventTag id=42"); 908 send_to_control(buffer, sizeof(buffer)); 909 buffer[sizeof(buffer) - 1] = '\0'; 910 char* cp; 911 long ret = strtol(buffer, &cp, 10); 912 EXPECT_GT(ret, 16); 913 EXPECT_TRUE(strstr(buffer, "\t(to life the universe etc|3)") != nullptr); 914 EXPECT_TRUE(strstr(buffer, "answer") != nullptr); 915 #else 916 GTEST_LOG_(INFO) << "This test does nothing.\n"; 917 #endif 918 } 919 920 TEST(logd, getEventTag_newentry) { 921 #ifdef __ANDROID__ 922 char buffer[256]; 923 memset(buffer, 0, sizeof(buffer)); 924 log_time now(CLOCK_MONOTONIC); 925 char name[64]; 926 snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); 927 snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", 928 name); 929 send_to_control(buffer, sizeof(buffer)); 930 buffer[sizeof(buffer) - 1] = '\0'; 931 char* cp; 932 long ret = strtol(buffer, &cp, 10); 933 EXPECT_GT(ret, 16); 934 EXPECT_TRUE(strstr(buffer, "\t(new|1)") != nullptr); 935 EXPECT_TRUE(strstr(buffer, name) != nullptr); 936 // ToDo: also look for this in /data/misc/logd/event-log-tags and 937 // /dev/event-log-tags. 938 #else 939 GTEST_LOG_(INFO) << "This test does nothing.\n"; 940 #endif 941 } 942 943 #ifdef __ANDROID__ 944 static inline uint32_t get4LE(const uint8_t* src) { 945 return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); 946 } 947 948 static inline uint32_t get4LE(const char* src) { 949 return get4LE(reinterpret_cast<const uint8_t*>(src)); 950 } 951 #endif 952 953 void __android_log_btwrite_multiple__helper(int count) { 954 #ifdef __ANDROID__ 955 log_time ts(CLOCK_MONOTONIC); 956 957 log_time ts1(CLOCK_MONOTONIC); 958 959 // We fork to create a unique pid for the submitted log messages 960 // so that we do not collide with the other _multiple_ tests. 961 962 pid_t pid = fork(); 963 964 if (pid == 0) { 965 // child 966 for (int i = count; i; --i) { 967 ASSERT_LT( 968 0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); 969 usleep(100); 970 } 971 ASSERT_LT(0, 972 __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1))); 973 usleep(1000000); 974 975 _exit(0); 976 } 977 978 siginfo_t info = {}; 979 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); 980 ASSERT_EQ(0, info.si_status); 981 982 struct logger_list* logger_list; 983 ASSERT_TRUE(nullptr != 984 (logger_list = android_logger_list_open( 985 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 986 0, pid))); 987 988 int expected_count = (count < 2) ? count : 2; 989 int expected_chatty_count = (count <= 2) ? 0 : 1; 990 int expected_identical_count = (count < 2) ? 0 : (count - 2); 991 static const int expected_expire_count = 0; 992 993 count = 0; 994 int second_count = 0; 995 int chatty_count = 0; 996 int identical_count = 0; 997 int expire_count = 0; 998 999 for (;;) { 1000 log_msg log_msg; 1001 if (android_logger_list_read(logger_list, &log_msg) <= 0) break; 1002 1003 if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) || 1004 (log_msg.id() != LOG_ID_EVENTS)) 1005 continue; 1006 1007 char* eventData = log_msg.msg(); 1008 if (!eventData) continue; 1009 1010 uint32_t tag = get4LE(eventData); 1011 1012 if ((eventData[4] == EVENT_TYPE_LONG) && 1013 (log_msg.entry.len == (4 + 1 + 8))) { 1014 if (tag != 0) continue; 1015 1016 log_time tx(eventData + 4 + 1); 1017 if (ts == tx) { 1018 ++count; 1019 } else if (ts1 == tx) { 1020 ++second_count; 1021 } 1022 } else if (eventData[4] == EVENT_TYPE_STRING) { 1023 if (tag != CHATTY_LOG_TAG) continue; 1024 ++chatty_count; 1025 // int len = get4LE(eventData + 4 + 1); 1026 log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0'; 1027 const char* cp; 1028 if ((cp = strstr(eventData + 4 + 1 + 4, " identical "))) { 1029 unsigned val = 0; 1030 sscanf(cp, " identical %u lines", &val); 1031 identical_count += val; 1032 } else if ((cp = strstr(eventData + 4 + 1 + 4, " expire "))) { 1033 unsigned val = 0; 1034 sscanf(cp, " expire %u lines", &val); 1035 expire_count += val; 1036 } 1037 } 1038 } 1039 1040 android_logger_list_close(logger_list); 1041 1042 EXPECT_EQ(expected_count, count); 1043 EXPECT_EQ(1, second_count); 1044 EXPECT_EQ(expected_chatty_count, chatty_count); 1045 EXPECT_EQ(expected_identical_count, identical_count); 1046 EXPECT_EQ(expected_expire_count, expire_count); 1047 #else 1048 count = 0; 1049 GTEST_LOG_(INFO) << "This test does nothing.\n"; 1050 #endif 1051 } 1052 1053 TEST(logd, multiple_test_1) { 1054 __android_log_btwrite_multiple__helper(1); 1055 } 1056 1057 TEST(logd, multiple_test_2) { 1058 __android_log_btwrite_multiple__helper(2); 1059 } 1060 1061 TEST(logd, multiple_test_3) { 1062 __android_log_btwrite_multiple__helper(3); 1063 } 1064 1065 TEST(logd, multiple_test_10) { 1066 __android_log_btwrite_multiple__helper(10); 1067 } 1068 1069 #ifdef __ANDROID__ 1070 // returns violating pid 1071 static pid_t sepolicy_rate(unsigned rate, unsigned num) { 1072 pid_t pid = fork(); 1073 1074 if (pid) { 1075 siginfo_t info = {}; 1076 if (TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))) return -1; 1077 if (info.si_status) return -1; 1078 return pid; 1079 } 1080 1081 // We may have DAC, but let's not have MAC 1082 if ((setcon("u:object_r:shell:s0") < 0) && (setcon("u:r:shell:s0") < 0)) { 1083 int save_errno = errno; 1084 security_context_t context; 1085 getcon(&context); 1086 if (strcmp(context, "u:r:shell:s0")) { 1087 fprintf(stderr, "setcon(\"u:r:shell:s0\") failed @\"%s\" %s\n", 1088 context, strerror(save_errno)); 1089 freecon(context); 1090 _exit(-1); 1091 // NOTREACHED 1092 return -1; 1093 } 1094 } 1095 1096 // The key here is we are root, but we are in u:r:shell:s0, 1097 // and the directory does not provide us DAC access 1098 // (eg: 0700 system system) so we trigger the pair dac_override 1099 // and dac_read_search on every try to get past the message 1100 // de-duper. We will also rotate the file name in the directory 1101 // as another measure. 1102 static const char file[] = "/data/drm/cannot_access_directory_%u"; 1103 static const unsigned avc_requests_per_access = 2; 1104 1105 rate /= avc_requests_per_access; 1106 useconds_t usec; 1107 if (rate == 0) { 1108 rate = 1; 1109 usec = 2000000; 1110 } else { 1111 usec = (1000000 + (rate / 2)) / rate; 1112 } 1113 num = (num + (avc_requests_per_access / 2)) / avc_requests_per_access; 1114 1115 if (usec < 2) usec = 2; 1116 1117 while (num > 0) { 1118 if (access(android::base::StringPrintf(file, num).c_str(), F_OK) == 0) { 1119 _exit(-1); 1120 // NOTREACHED 1121 return -1; 1122 } 1123 usleep(usec); 1124 --num; 1125 } 1126 _exit(0); 1127 // NOTREACHED 1128 return -1; 1129 } 1130 1131 static constexpr int background_period = 10; 1132 1133 static int count_avc(pid_t pid) { 1134 int count = 0; 1135 1136 // pid=-1 skip as pid is in error 1137 if (pid == (pid_t)-1) return count; 1138 1139 // pid=0 means we want to report the background count of avc: activities 1140 struct logger_list* logger_list = 1141 pid ? android_logger_list_alloc( 1142 ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, pid) 1143 : android_logger_list_alloc_time( 1144 ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1145 log_time(android_log_clockid()) - 1146 log_time(background_period, 0), 1147 0); 1148 if (!logger_list) return count; 1149 struct logger* logger = android_logger_open(logger_list, LOG_ID_EVENTS); 1150 if (!logger) { 1151 android_logger_list_close(logger_list); 1152 return count; 1153 } 1154 for (;;) { 1155 log_msg log_msg; 1156 1157 if (android_logger_list_read(logger_list, &log_msg) <= 0) break; 1158 1159 if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) || 1160 (log_msg.id() != LOG_ID_EVENTS)) 1161 continue; 1162 1163 char* eventData = log_msg.msg(); 1164 if (!eventData) continue; 1165 1166 uint32_t tag = get4LE(eventData); 1167 if (tag != AUDITD_LOG_TAG) continue; 1168 1169 if (eventData[4] != EVENT_TYPE_STRING) continue; 1170 1171 // int len = get4LE(eventData + 4 + 1); 1172 log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0'; 1173 const char* cp = strstr(eventData + 4 + 1 + 4, "): avc: denied"); 1174 if (!cp) continue; 1175 1176 ++count; 1177 } 1178 1179 android_logger_list_close(logger_list); 1180 1181 return count; 1182 } 1183 #endif 1184 1185 TEST(logd, sepolicy_rate_limiter) { 1186 #ifdef __ANDROID__ 1187 int background_selinux_activity_too_high = count_avc(0); 1188 if (background_selinux_activity_too_high > 2) { 1189 GTEST_LOG_(ERROR) << "Too much background selinux activity " 1190 << background_selinux_activity_too_high * 60 / 1191 background_period 1192 << "/minute on the device, this test\n" 1193 << "can not measure the functionality of the " 1194 << "sepolicy rate limiter. Expect test to\n" 1195 << "fail as this device is in a bad state, " 1196 << "but is not strictly a unit test failure."; 1197 } 1198 1199 static const int rate = AUDIT_RATE_LIMIT; 1200 static const int duration = 2; 1201 // Two seconds of sustained denials. Depending on the overlap in the time 1202 // window that the kernel is considering vs what this test is considering, 1203 // allow some additional denials to prevent a flaky test. 1204 EXPECT_LE(count_avc(sepolicy_rate(rate, rate * duration)), 1205 rate * duration + rate); 1206 #else 1207 GTEST_LOG_(INFO) << "This test does nothing.\n"; 1208 #endif 1209 } 1210
