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 <poll.h> 19#include <signal.h> 20#include <stdio.h> 21#include <string.h> 22 23#include <gtest/gtest.h> 24 25#include "cutils/sockets.h" 26#include "log/log.h" 27#include "log/logger.h" 28 29#define __unused __attribute__((__unused__)) 30 31/* 32 * returns statistics 33 */ 34static void my_android_logger_get_statistics(char *buf, size_t len) 35{ 36 snprintf(buf, len, "getStatistics 0 1 2 3 4"); 37 int sock = socket_local_client("logd", 38 ANDROID_SOCKET_NAMESPACE_RESERVED, 39 SOCK_STREAM); 40 if (sock >= 0) { 41 if (write(sock, buf, strlen(buf) + 1) > 0) { 42 ssize_t ret; 43 while ((ret = read(sock, buf, len)) > 0) { 44 if ((size_t)ret == len) { 45 break; 46 } 47 len -= ret; 48 buf += ret; 49 50 struct pollfd p = { 51 .fd = sock, 52 .events = POLLIN, 53 .revents = 0 54 }; 55 56 ret = poll(&p, 1, 20); 57 if ((ret <= 0) || !(p.revents & POLLIN)) { 58 break; 59 } 60 } 61 } 62 close(sock); 63 } 64} 65 66static void alloc_statistics(char **buffer, size_t *length) 67{ 68 size_t len = 8192; 69 char *buf; 70 71 for(int retry = 32; (retry >= 0); delete [] buf, --retry) { 72 buf = new char [len]; 73 my_android_logger_get_statistics(buf, len); 74 75 buf[len-1] = '\0'; 76 size_t ret = atol(buf) + 1; 77 if (ret < 4) { 78 delete [] buf; 79 buf = NULL; 80 break; 81 } 82 bool check = ret <= len; 83 len = ret; 84 if (check) { 85 break; 86 } 87 len += len / 8; // allow for some slop 88 } 89 *buffer = buf; 90 *length = len; 91} 92 93static char *find_benchmark_spam(char *cp) 94{ 95 // liblog_benchmarks has been run designed to SPAM. The signature of 96 // a noisiest UID statistics is one of the following: 97 // 98 // main: UID/PID Total size/num Now UID/PID[?] Total 99 // 0 7500306/304207 71608/3183 0/4225? 7454388/303656 100 // <wrap> 93432/1012 101 // -or- 102 // 0/gone 7454388/303656 93432/1012 103 // 104 // basically if we see a *large* number of 0/????? entries 105 unsigned long value; 106 do { 107 char *benchmark = strstr(cp, " 0/"); 108 char *benchmark_newline = strstr(cp, "\n0/"); 109 if (!benchmark) { 110 benchmark = benchmark_newline; 111 } 112 if (benchmark_newline && (benchmark > benchmark_newline)) { 113 benchmark = benchmark_newline; 114 } 115 cp = benchmark; 116 if (!cp) { 117 break; 118 } 119 cp += 3; 120 while (isdigit(*cp) || (*cp == 'g') || (*cp == 'o') || (*cp == 'n')) { 121 ++cp; 122 } 123 value = 0; 124 // ###? or gone 125 if ((*cp == '?') || (*cp == 'e')) { 126 while (*++cp == ' '); 127 while (isdigit(*cp)) { 128 value = value * 10ULL + *cp - '0'; 129 ++cp; 130 } 131 if (*cp != '/') { 132 value = 0; 133 continue; 134 } 135 while (isdigit(*++cp)); 136 while (*cp == ' ') ++cp; 137 if (!isdigit(*cp)) { 138 value = 0; 139 } 140 } 141 } while ((value < 900000ULL) && *cp); 142 return cp; 143} 144 145TEST(logd, statistics) { 146 size_t len; 147 char *buf; 148 149 alloc_statistics(&buf, &len); 150 151#ifdef TARGET_USES_LOGD 152 ASSERT_TRUE(NULL != buf); 153#else 154 if (!buf) { 155 return; 156 } 157#endif 158 159 // remove trailing FF 160 char *cp = buf + len - 1; 161 *cp = '\0'; 162 bool truncated = *--cp != '\f'; 163 if (!truncated) { 164 *cp = '\0'; 165 } 166 167 // squash out the byte count 168 cp = buf; 169 if (!truncated) { 170 while (isdigit(*cp) || (*cp == '\n')) { 171 ++cp; 172 } 173 } 174 175 fprintf(stderr, "%s", cp); 176 177 EXPECT_LT((size_t)64, strlen(cp)); 178 179 EXPECT_EQ(0, truncated); 180 181#ifdef TARGET_USES_LOGD 182 char *main_logs = strstr(cp, "\nmain:"); 183 EXPECT_TRUE(NULL != main_logs); 184 185 char *radio_logs = strstr(cp, "\nradio:"); 186 EXPECT_TRUE(NULL != radio_logs); 187 188 char *system_logs = strstr(cp, "\nsystem:"); 189 EXPECT_TRUE(NULL != system_logs); 190 191 char *events_logs = strstr(cp, "\nevents:"); 192 EXPECT_TRUE(NULL != events_logs); 193#endif 194 195 // Parse timing stats 196 197 cp = strstr(cp, "Minimum time between log events per dgram_qlen:"); 198 199 if (cp) { 200 while (*cp && (*cp != '\n')) { 201 ++cp; 202 } 203 if (*cp == '\n') { 204 ++cp; 205 } 206 207 char *list_of_spans = cp; 208 EXPECT_NE('\0', *list_of_spans); 209 210 unsigned short number_of_buckets = 0; 211 unsigned short *dgram_qlen = NULL; 212 unsigned short bucket = 0; 213 while (*cp && (*cp != '\n')) { 214 bucket = 0; 215 while (isdigit(*cp)) { 216 bucket = bucket * 10 + *cp - '0'; 217 ++cp; 218 } 219 while (*cp == ' ') { 220 ++cp; 221 } 222 if (!bucket) { 223 break; 224 } 225 unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1]; 226 EXPECT_TRUE(new_dgram_qlen != NULL); 227 if (dgram_qlen) { 228 memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets); 229 delete [] dgram_qlen; 230 } 231 232 dgram_qlen = new_dgram_qlen; 233 dgram_qlen[number_of_buckets++] = bucket; 234 } 235 236 char *end_of_spans = cp; 237 EXPECT_NE('\0', *end_of_spans); 238 239 EXPECT_LT(5, number_of_buckets); 240 241 unsigned long long *times = new unsigned long long [number_of_buckets]; 242 ASSERT_TRUE(times != NULL); 243 244 memset(times, 0, sizeof(*times) * number_of_buckets); 245 246 while (*cp == '\n') { 247 ++cp; 248 } 249 250 unsigned short number_of_values = 0; 251 unsigned long long value; 252 while (*cp && (*cp != '\n')) { 253 EXPECT_GE(number_of_buckets, number_of_values); 254 255 value = 0; 256 while (isdigit(*cp)) { 257 value = value * 10ULL + *cp - '0'; 258 ++cp; 259 } 260 261 switch(*cp) { 262 case ' ': 263 case '\n': 264 value *= 1000ULL; 265 /* FALLTHRU */ 266 case 'm': 267 value *= 1000ULL; 268 /* FALLTHRU */ 269 case 'u': 270 value *= 1000ULL; 271 /* FALLTHRU */ 272 case 'n': 273 default: 274 break; 275 } 276 while (*++cp == ' '); 277 278 if (!value) { 279 break; 280 } 281 282 times[number_of_values] = value; 283 ++number_of_values; 284 } 285 286#ifdef TARGET_USES_LOGD 287 EXPECT_EQ(number_of_values, number_of_buckets); 288#endif 289 290 FILE *fp; 291 ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r"))); 292 293 unsigned max_dgram_qlen = 0; 294 fscanf(fp, "%u", &max_dgram_qlen); 295 296 fclose(fp); 297 298 // Find launch point 299 unsigned short launch = 0; 300 unsigned long long total = 0; 301 do { 302 total += times[launch]; 303 } while (((++launch < number_of_buckets) 304 && ((total / launch) >= (times[launch] / 8ULL))) 305 || (launch == 1)); // too soon 306 307 bool failure = number_of_buckets <= launch; 308 if (!failure) { 309 unsigned short l = launch; 310 if (l >= number_of_buckets) { 311 l = number_of_buckets - 1; 312 } 313 failure = max_dgram_qlen < dgram_qlen[l]; 314 } 315 316 // We can get failure if at any time liblog_benchmarks has been run 317 // because designed to overload /proc/sys/net/unix/max_dgram_qlen even 318 // at excessive values like 20000. It does so to measure the raw processing 319 // performance of logd. 320 if (failure) { 321 cp = find_benchmark_spam(cp); 322 } 323 324 if (cp) { 325 // Fake a failure, but without the failure code 326 if (number_of_buckets <= launch) { 327 printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n", 328 number_of_buckets, launch); 329 } 330 if (launch >= number_of_buckets) { 331 launch = number_of_buckets - 1; 332 } 333 if (max_dgram_qlen < dgram_qlen[launch]) { 334 printf ("Expected: max_dgram_qlen >= dgram_qlen[%d]," 335 " actual: %u vs %u\n", 336 launch, max_dgram_qlen, dgram_qlen[launch]); 337 } 338 } else 339#ifndef TARGET_USES_LOGD 340 if (total) 341#endif 342 { 343 EXPECT_GT(number_of_buckets, launch); 344 if (launch >= number_of_buckets) { 345 launch = number_of_buckets - 1; 346 } 347 EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]); 348 } 349 350 delete [] dgram_qlen; 351 delete [] times; 352 } 353 delete [] buf; 354} 355 356static void caught_signal(int signum __unused) { } 357 358static void dump_log_msg(const char *prefix, 359 log_msg *msg, unsigned int version, int lid) { 360 switch(msg->entry.hdr_size) { 361 case 0: 362 version = 1; 363 break; 364 365 case sizeof(msg->entry_v2): 366 if (version == 0) { 367 version = 2; 368 } 369 break; 370 } 371 372 fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len()); 373 if (version != 1) { 374 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); 375 } 376 fprintf(stderr, "pid=%u tid=%u %u.%09u ", 377 msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec); 378 switch(version) { 379 case 1: 380 break; 381 case 2: 382 fprintf(stderr, "euid=%u ", msg->entry_v2.euid); 383 break; 384 case 3: 385 default: 386 lid = msg->entry.lid; 387 break; 388 } 389 390 switch(lid) { 391 case 0: 392 fprintf(stderr, "lid=main "); 393 break; 394 case 1: 395 fprintf(stderr, "lid=radio "); 396 break; 397 case 2: 398 fprintf(stderr, "lid=events "); 399 break; 400 case 3: 401 fprintf(stderr, "lid=system "); 402 break; 403 default: 404 if (lid >= 0) { 405 fprintf(stderr, "lid=%d ", lid); 406 } 407 } 408 409 unsigned int len = msg->entry.len; 410 fprintf(stderr, "msg[%u]={", len); 411 unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg()); 412 while(len) { 413 unsigned char *p = cp; 414 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { 415 ++p; 416 } 417 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { 418 fprintf(stderr, "\""); 419 while (*cp) { 420 fprintf(stderr, (*cp != '\n') ? "%c" : "\\n", *cp); 421 ++cp; 422 --len; 423 } 424 fprintf(stderr, "\""); 425 } else { 426 fprintf(stderr, "%02x", *cp); 427 } 428 ++cp; 429 if (--len) { 430 fprintf(stderr, ", "); 431 } 432 } 433 fprintf(stderr, "}\n"); 434} 435 436TEST(logd, both) { 437 log_msg msg; 438 439 // check if we can read any logs from logd 440 bool user_logger_available = false; 441 bool user_logger_content = false; 442 443 int fd = socket_local_client("logdr", 444 ANDROID_SOCKET_NAMESPACE_RESERVED, 445 SOCK_SEQPACKET); 446 if (fd >= 0) { 447 struct sigaction ignore, old_sigaction; 448 memset(&ignore, 0, sizeof(ignore)); 449 ignore.sa_handler = caught_signal; 450 sigemptyset(&ignore.sa_mask); 451 sigaction(SIGALRM, &ignore, &old_sigaction); 452 unsigned int old_alarm = alarm(10); 453 454 static const char ask[] = "dumpAndClose lids=0,1,2,3"; 455 user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask); 456 457 user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0; 458 459 if (user_logger_content) { 460 dump_log_msg("user", &msg, 3, -1); 461 } 462 463 alarm(old_alarm); 464 sigaction(SIGALRM, &old_sigaction, NULL); 465 466 close(fd); 467 } 468 469 // check if we can read any logs from kernel logger 470 bool kernel_logger_available = false; 471 bool kernel_logger_content = false; 472 473 static const char *loggers[] = { 474 "/dev/log/main", "/dev/log_main", 475 "/dev/log/radio", "/dev/log_radio", 476 "/dev/log/events", "/dev/log_events", 477 "/dev/log/system", "/dev/log_system", 478 }; 479 480 for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) { 481 fd = open(loggers[i], O_RDONLY); 482 if (fd < 0) { 483 continue; 484 } 485 kernel_logger_available = true; 486 fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK); 487 int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg))); 488 if (result > 0) { 489 kernel_logger_content = true; 490 dump_log_msg("kernel", &msg, 0, i / 2); 491 } 492 close(fd); 493 } 494 495 static const char yes[] = "\xE2\x9C\x93"; 496 static const char no[] = "\xE2\x9c\x98"; 497 fprintf(stderr, 498 "LOGGER Available Content\n" 499 "user %-13s%s\n" 500 "kernel %-13s%s\n" 501 " status %-11s%s\n", 502 (user_logger_available) ? yes : no, 503 (user_logger_content) ? yes : no, 504 (kernel_logger_available) ? yes : no, 505 (kernel_logger_content) ? yes : no, 506 (user_logger_available && kernel_logger_available) ? "ERROR" : "ok", 507 (user_logger_content && kernel_logger_content) ? "ERROR" : "ok"); 508 509 EXPECT_EQ(0, user_logger_available && kernel_logger_available); 510 EXPECT_EQ(0, !user_logger_available && !kernel_logger_available); 511 EXPECT_EQ(0, user_logger_content && kernel_logger_content); 512 EXPECT_EQ(0, !user_logger_content && !kernel_logger_content); 513} 514 515// BAD ROBOT 516// Benchmark threshold are generally considered bad form unless there is 517// is some human love applied to the continued maintenance and whether the 518// thresholds are tuned on a per-target basis. Here we check if the values 519// are more than double what is expected. Doubling will not prevent failure 520// on busy or low-end systems that could have a tendency to stretch values. 521// 522// The primary goal of this test is to simulate a spammy app (benchmark 523// being the worst) and check to make sure the logger can deal with it 524// appropriately by checking all the statistics are in an expected range. 525// 526TEST(logd, benchmark) { 527 size_t len; 528 char *buf; 529 530 alloc_statistics(&buf, &len); 531 bool benchmark_already_run = buf && find_benchmark_spam(buf); 532 delete [] buf; 533 534 if (benchmark_already_run) { 535 fprintf(stderr, "WARNING: spam already present and too much history\n" 536 " false OK for prune by worst UID check\n"); 537 } 538 539 FILE *fp; 540 541 // Introduce some extreme spam for the worst UID filter 542 ASSERT_TRUE(NULL != (fp = popen( 543 "/data/nativetest/liblog-benchmarks/liblog-benchmarks", 544 "r"))); 545 546 char buffer[5120]; 547 548 static const char *benchmarks[] = { 549 "BM_log_maximum_retry ", 550 "BM_log_maximum ", 551 "BM_clock_overhead ", 552 "BM_log_overhead ", 553 "BM_log_latency ", 554 "BM_log_delay " 555 }; 556 static const unsigned int log_maximum_retry = 0; 557 static const unsigned int log_maximum = 1; 558 static const unsigned int clock_overhead = 2; 559 static const unsigned int log_overhead = 3; 560 static const unsigned int log_latency = 4; 561 static const unsigned int log_delay = 5; 562 563 unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])]; 564 565 memset(ns, 0, sizeof(ns)); 566 567 while (fgets(buffer, sizeof(buffer), fp)) { 568 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { 569 char *cp = strstr(buffer, benchmarks[i]); 570 if (!cp) { 571 continue; 572 } 573 sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]); 574 fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); 575 } 576 } 577 int ret = pclose(fp); 578 579 if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { 580 fprintf(stderr, 581 "WARNING: " 582 "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" 583 " can not perform test\n"); 584 return; 585 } 586 587#ifdef TARGET_USES_LOGD 588 EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user 589#else 590 EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel 591#endif 592 593#ifdef TARGET_USES_LOGD 594 EXPECT_GE(30000UL, ns[log_maximum]); // 27305 user 595#else 596 EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel 597#endif 598 599 EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 600 601#ifdef TARGET_USES_LOGD 602 EXPECT_GE(250000UL, ns[log_overhead]); // 121876 user 603#else 604 EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel 605#endif 606 607#ifdef TARGET_USES_LOGD 608 EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space 609#else 610 EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel 611#endif 612 613#ifdef TARGET_USES_LOGD 614 EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user 615#else 616 EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel 617#endif 618 619 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { 620 EXPECT_NE(0UL, ns[i]); 621 } 622 623 alloc_statistics(&buf, &len); 624 625#ifdef TARGET_USES_LOGD 626 bool collected_statistics = !!buf; 627 EXPECT_EQ(true, collected_statistics); 628#else 629 if (!buf) { 630 return; 631 } 632#endif 633 634 ASSERT_TRUE(NULL != buf); 635 636 char *benchmark_statistics_found = find_benchmark_spam(buf); 637 ASSERT_TRUE(benchmark_statistics_found != NULL); 638 639 // Check how effective the SPAM filter is, parse out Now size. 640 // Total Now 641 // 0/4225? 7454388/303656 31488/755 642 // ^-- benchmark_statistics_found 643 644 unsigned long nowSpamSize = atol(benchmark_statistics_found); 645 646 delete [] buf; 647 648 ASSERT_NE(0UL, nowSpamSize); 649 650 // Determine if we have the spam filter enabled 651 int sock = socket_local_client("logd", 652 ANDROID_SOCKET_NAMESPACE_RESERVED, 653 SOCK_STREAM); 654 655 ASSERT_TRUE(sock >= 0); 656 657 static const char getPruneList[] = "getPruneList"; 658 if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { 659 char buffer[80]; 660 memset(buffer, 0, sizeof(buffer)); 661 read(sock, buffer, sizeof(buffer)); 662 char *cp = strchr(buffer, '\n'); 663 if (!cp || (cp[1] != '~') || (cp[2] != '!')) { 664 close(sock); 665 fprintf(stderr, 666 "WARNING: " 667 "Logger has SPAM filtration turned off \"%s\"\n", buffer); 668 return; 669 } 670 } else { 671 int save_errno = errno; 672 close(sock); 673 FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno); 674 } 675 676 static const unsigned long expected_absolute_minimum_log_size = 65536UL; 677 unsigned long totalSize = expected_absolute_minimum_log_size; 678 static const char getSize[] = { 679 'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ', 680 LOG_ID_MAIN + '0', '\0' 681 }; 682 if (write(sock, getSize, sizeof(getSize)) > 0) { 683 char buffer[80]; 684 memset(buffer, 0, sizeof(buffer)); 685 read(sock, buffer, sizeof(buffer)); 686 totalSize = atol(buffer); 687 if (totalSize < expected_absolute_minimum_log_size) { 688 fprintf(stderr, 689 "WARNING: " 690 "Logger had unexpected referenced size \"%s\"\n", buffer); 691 totalSize = expected_absolute_minimum_log_size; 692 } 693 } 694 close(sock); 695 696 // logd allows excursions to 110% of total size 697 totalSize = (totalSize * 11 ) / 10; 698 699 // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) 700 ASSERT_GT(totalSize, nowSpamSize * 2); 701} 702