logd_test.cpp revision 4ed16b4381e6723670575ff8da3cfe12fe74998a
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 delete [] buf; 196} 197 198static void caught_signal(int signum __unused) { } 199 200static void dump_log_msg(const char *prefix, 201 log_msg *msg, unsigned int version, int lid) { 202 switch(msg->entry.hdr_size) { 203 case 0: 204 version = 1; 205 break; 206 207 case sizeof(msg->entry_v2): 208 if (version == 0) { 209 version = 2; 210 } 211 break; 212 } 213 214 fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len()); 215 if (version != 1) { 216 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); 217 } 218 fprintf(stderr, "pid=%u tid=%u %u.%09u ", 219 msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec); 220 switch(version) { 221 case 1: 222 break; 223 case 2: 224 fprintf(stderr, "euid=%u ", msg->entry_v2.euid); 225 break; 226 case 3: 227 default: 228 lid = msg->entry.lid; 229 break; 230 } 231 232 switch(lid) { 233 case 0: 234 fprintf(stderr, "lid=main "); 235 break; 236 case 1: 237 fprintf(stderr, "lid=radio "); 238 break; 239 case 2: 240 fprintf(stderr, "lid=events "); 241 break; 242 case 3: 243 fprintf(stderr, "lid=system "); 244 break; 245 default: 246 if (lid >= 0) { 247 fprintf(stderr, "lid=%d ", lid); 248 } 249 } 250 251 unsigned int len = msg->entry.len; 252 fprintf(stderr, "msg[%u]={", len); 253 unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg()); 254 while(len) { 255 unsigned char *p = cp; 256 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { 257 ++p; 258 } 259 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { 260 fprintf(stderr, "\""); 261 while (*cp) { 262 if (*cp != '\n') { 263 fprintf(stderr, "%c", *cp); 264 } else { 265 fprintf(stderr, "\\n"); 266 } 267 ++cp; 268 --len; 269 } 270 fprintf(stderr, "\""); 271 } else { 272 fprintf(stderr, "%02x", *cp); 273 } 274 ++cp; 275 if (--len) { 276 fprintf(stderr, ", "); 277 } 278 } 279 fprintf(stderr, "}\n"); 280} 281 282TEST(logd, both) { 283 log_msg msg; 284 285 // check if we can read any logs from logd 286 bool user_logger_available = false; 287 bool user_logger_content = false; 288 289 int fd = socket_local_client("logdr", 290 ANDROID_SOCKET_NAMESPACE_RESERVED, 291 SOCK_SEQPACKET); 292 if (fd >= 0) { 293 struct sigaction ignore, old_sigaction; 294 memset(&ignore, 0, sizeof(ignore)); 295 ignore.sa_handler = caught_signal; 296 sigemptyset(&ignore.sa_mask); 297 sigaction(SIGALRM, &ignore, &old_sigaction); 298 unsigned int old_alarm = alarm(10); 299 300 static const char ask[] = "dumpAndClose lids=0,1,2,3"; 301 user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask); 302 303 user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0; 304 305 if (user_logger_content) { 306 dump_log_msg("user", &msg, 3, -1); 307 } 308 309 alarm(old_alarm); 310 sigaction(SIGALRM, &old_sigaction, NULL); 311 312 close(fd); 313 } 314 315 // check if we can read any logs from kernel logger 316 bool kernel_logger_available = false; 317 bool kernel_logger_content = false; 318 319 static const char *loggers[] = { 320 "/dev/log/main", "/dev/log_main", 321 "/dev/log/radio", "/dev/log_radio", 322 "/dev/log/events", "/dev/log_events", 323 "/dev/log/system", "/dev/log_system", 324 }; 325 326 for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) { 327 fd = open(loggers[i], O_RDONLY); 328 if (fd < 0) { 329 continue; 330 } 331 kernel_logger_available = true; 332 fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK); 333 int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg))); 334 if (result > 0) { 335 kernel_logger_content = true; 336 dump_log_msg("kernel", &msg, 0, i / 2); 337 } 338 close(fd); 339 } 340 341 static const char yes[] = "\xE2\x9C\x93"; 342 static const char no[] = "\xE2\x9c\x98"; 343 fprintf(stderr, 344 "LOGGER Available Content\n" 345 "user %-13s%s\n" 346 "kernel %-13s%s\n" 347 " status %-11s%s\n", 348 (user_logger_available) ? yes : no, 349 (user_logger_content) ? yes : no, 350 (kernel_logger_available) ? yes : no, 351 (kernel_logger_content) ? yes : no, 352 (user_logger_available && kernel_logger_available) ? "ERROR" : "ok", 353 (user_logger_content && kernel_logger_content) ? "ERROR" : "ok"); 354 355 EXPECT_EQ(0, user_logger_available && kernel_logger_available); 356 EXPECT_EQ(0, !user_logger_available && !kernel_logger_available); 357 EXPECT_EQ(0, user_logger_content && kernel_logger_content); 358 EXPECT_EQ(0, !user_logger_content && !kernel_logger_content); 359} 360 361// BAD ROBOT 362// Benchmark threshold are generally considered bad form unless there is 363// is some human love applied to the continued maintenance and whether the 364// thresholds are tuned on a per-target basis. Here we check if the values 365// are more than double what is expected. Doubling will not prevent failure 366// on busy or low-end systems that could have a tendency to stretch values. 367// 368// The primary goal of this test is to simulate a spammy app (benchmark 369// being the worst) and check to make sure the logger can deal with it 370// appropriately by checking all the statistics are in an expected range. 371// 372TEST(logd, benchmark) { 373 size_t len; 374 char *buf; 375 376 alloc_statistics(&buf, &len); 377 bool benchmark_already_run = buf && find_benchmark_spam(buf); 378 delete [] buf; 379 380 if (benchmark_already_run) { 381 fprintf(stderr, "WARNING: spam already present and too much history\n" 382 " false OK for prune by worst UID check\n"); 383 } 384 385 FILE *fp; 386 387 // Introduce some extreme spam for the worst UID filter 388 ASSERT_TRUE(NULL != (fp = popen( 389 "/data/nativetest/liblog-benchmarks/liblog-benchmarks", 390 "r"))); 391 392 char buffer[5120]; 393 394 static const char *benchmarks[] = { 395 "BM_log_maximum_retry ", 396 "BM_log_maximum ", 397 "BM_clock_overhead ", 398 "BM_log_overhead ", 399 "BM_log_latency ", 400 "BM_log_delay " 401 }; 402 static const unsigned int log_maximum_retry = 0; 403 static const unsigned int log_maximum = 1; 404 static const unsigned int clock_overhead = 2; 405 static const unsigned int log_overhead = 3; 406 static const unsigned int log_latency = 4; 407 static const unsigned int log_delay = 5; 408 409 unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])]; 410 411 memset(ns, 0, sizeof(ns)); 412 413 while (fgets(buffer, sizeof(buffer), fp)) { 414 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { 415 char *cp = strstr(buffer, benchmarks[i]); 416 if (!cp) { 417 continue; 418 } 419 sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]); 420 fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); 421 } 422 } 423 int ret = pclose(fp); 424 425 if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { 426 fprintf(stderr, 427 "WARNING: " 428 "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" 429 " can not perform test\n"); 430 return; 431 } 432 433#ifdef TARGET_USES_LOGD 434 EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user 435#else 436 EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel 437#endif 438 439#ifdef TARGET_USES_LOGD 440 EXPECT_GE(30000UL, ns[log_maximum]); // 27305 user 441#else 442 EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel 443#endif 444 445 EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 446 447#ifdef TARGET_USES_LOGD 448 EXPECT_GE(250000UL, ns[log_overhead]); // 121876 user 449#else 450 EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel 451#endif 452 453#ifdef TARGET_USES_LOGD 454 EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space 455#else 456 EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel 457#endif 458 459#ifdef TARGET_USES_LOGD 460 EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user 461#else 462 EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel 463#endif 464 465 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { 466 EXPECT_NE(0UL, ns[i]); 467 } 468 469 alloc_statistics(&buf, &len); 470 471#ifdef TARGET_USES_LOGD 472 bool collected_statistics = !!buf; 473 EXPECT_EQ(true, collected_statistics); 474#else 475 if (!buf) { 476 return; 477 } 478#endif 479 480 ASSERT_TRUE(NULL != buf); 481 482 char *benchmark_statistics_found = find_benchmark_spam(buf); 483 ASSERT_TRUE(benchmark_statistics_found != NULL); 484 485 // Check how effective the SPAM filter is, parse out Now size. 486 // Total Now 487 // 0/4225? 7454388/303656 31488/755 488 // ^-- benchmark_statistics_found 489 490 unsigned long nowSpamSize = atol(benchmark_statistics_found); 491 492 delete [] buf; 493 494 ASSERT_NE(0UL, nowSpamSize); 495 496 // Determine if we have the spam filter enabled 497 int sock = socket_local_client("logd", 498 ANDROID_SOCKET_NAMESPACE_RESERVED, 499 SOCK_STREAM); 500 501 ASSERT_TRUE(sock >= 0); 502 503 static const char getPruneList[] = "getPruneList"; 504 if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { 505 char buffer[80]; 506 memset(buffer, 0, sizeof(buffer)); 507 read(sock, buffer, sizeof(buffer)); 508 char *cp = strchr(buffer, '\n'); 509 if (!cp || (cp[1] != '~') || (cp[2] != '!')) { 510 close(sock); 511 fprintf(stderr, 512 "WARNING: " 513 "Logger has SPAM filtration turned off \"%s\"\n", buffer); 514 return; 515 } 516 } else { 517 int save_errno = errno; 518 close(sock); 519 FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno); 520 } 521 522 static const unsigned long expected_absolute_minimum_log_size = 65536UL; 523 unsigned long totalSize = expected_absolute_minimum_log_size; 524 static const char getSize[] = { 525 'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ', 526 LOG_ID_MAIN + '0', '\0' 527 }; 528 if (write(sock, getSize, sizeof(getSize)) > 0) { 529 char buffer[80]; 530 memset(buffer, 0, sizeof(buffer)); 531 read(sock, buffer, sizeof(buffer)); 532 totalSize = atol(buffer); 533 if (totalSize < expected_absolute_minimum_log_size) { 534 fprintf(stderr, 535 "WARNING: " 536 "Logger had unexpected referenced size \"%s\"\n", buffer); 537 totalSize = expected_absolute_minimum_log_size; 538 } 539 } 540 close(sock); 541 542 // logd allows excursions to 110% of total size 543 totalSize = (totalSize * 11 ) / 10; 544 545 // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) 546 ASSERT_GT(totalSize, nowSpamSize * 2); 547} 548