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