logd_test.cpp revision cb41e3673b81f246a45ac1ab38ba0c8490ceb0a1
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: 97 // 98 // Chattiest UIDs in main log buffer: Size Pruned 99 // UID PACKAGE BYTES LINES 100 // 0 root 54164 147569 101 // 102 char *benchmark = NULL; 103 do { 104 static const char signature[] = "\n0 root "; 105 106 benchmark = strstr(cp, signature); 107 if (!benchmark) { 108 break; 109 } 110 cp = benchmark + sizeof(signature); 111 while (isspace(*cp)) { 112 ++cp; 113 } 114 benchmark = cp; 115 while (isdigit(*cp)) { 116 ++cp; 117 } 118 while (isspace(*cp)) { 119 ++cp; 120 } 121 unsigned long value = 0; 122 while (isdigit(*cp)) { 123 value = value * 10ULL + *cp - '0'; 124 ++cp; 125 } 126 if (value > 100000UL) { 127 break; 128 } 129 benchmark = NULL; 130 } while (*cp); 131 return benchmark; 132} 133 134TEST(logd, statistics) { 135 size_t len; 136 char *buf; 137 138 alloc_statistics(&buf, &len); 139 140 ASSERT_TRUE(NULL != buf); 141 142 // remove trailing FF 143 char *cp = buf + len - 1; 144 *cp = '\0'; 145 bool truncated = *--cp != '\f'; 146 if (!truncated) { 147 *cp = '\0'; 148 } 149 150 // squash out the byte count 151 cp = buf; 152 if (!truncated) { 153 while (isdigit(*cp) || (*cp == '\n')) { 154 ++cp; 155 } 156 } 157 158 fprintf(stderr, "%s", cp); 159 160 EXPECT_LT((size_t)64, strlen(cp)); 161 162 EXPECT_EQ(0, truncated); 163 164 char *main_logs = strstr(cp, "\nChattiest UIDs in main "); 165 EXPECT_TRUE(NULL != main_logs); 166 167 char *radio_logs = strstr(cp, "\nChattiest UIDs in radio "); 168 EXPECT_TRUE(NULL != radio_logs); 169 170 char *system_logs = strstr(cp, "\nChattiest UIDs in system "); 171 EXPECT_TRUE(NULL != system_logs); 172 173 char *events_logs = strstr(cp, "\nChattiest UIDs in events "); 174 EXPECT_TRUE(NULL != events_logs); 175 176 delete [] buf; 177} 178 179static void caught_signal(int signum __unused) { } 180 181static void dump_log_msg(const char *prefix, 182 log_msg *msg, unsigned int version, int lid) { 183 switch(msg->entry.hdr_size) { 184 case 0: 185 version = 1; 186 break; 187 188 case sizeof(msg->entry_v2): 189 if (version == 0) { 190 version = 2; 191 } 192 break; 193 } 194 195 fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len()); 196 if (version != 1) { 197 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); 198 } 199 fprintf(stderr, "pid=%u tid=%u %u.%09u ", 200 msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec); 201 switch(version) { 202 case 1: 203 break; 204 case 2: 205 fprintf(stderr, "euid=%u ", msg->entry_v2.euid); 206 break; 207 case 3: 208 default: 209 lid = msg->entry.lid; 210 break; 211 } 212 213 switch(lid) { 214 case 0: 215 fprintf(stderr, "lid=main "); 216 break; 217 case 1: 218 fprintf(stderr, "lid=radio "); 219 break; 220 case 2: 221 fprintf(stderr, "lid=events "); 222 break; 223 case 3: 224 fprintf(stderr, "lid=system "); 225 break; 226 default: 227 if (lid >= 0) { 228 fprintf(stderr, "lid=%d ", lid); 229 } 230 } 231 232 unsigned int len = msg->entry.len; 233 fprintf(stderr, "msg[%u]={", len); 234 unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg()); 235 while(len) { 236 unsigned char *p = cp; 237 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { 238 ++p; 239 } 240 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { 241 fprintf(stderr, "\""); 242 while (*cp) { 243 if (*cp != '\n') { 244 fprintf(stderr, "%c", *cp); 245 } else { 246 fprintf(stderr, "\\n"); 247 } 248 ++cp; 249 --len; 250 } 251 fprintf(stderr, "\""); 252 } else { 253 fprintf(stderr, "%02x", *cp); 254 } 255 ++cp; 256 if (--len) { 257 fprintf(stderr, ", "); 258 } 259 } 260 fprintf(stderr, "}\n"); 261} 262 263TEST(logd, both) { 264 log_msg msg; 265 266 // check if we can read any logs from logd 267 bool user_logger_available = false; 268 bool user_logger_content = false; 269 270 int fd = socket_local_client("logdr", 271 ANDROID_SOCKET_NAMESPACE_RESERVED, 272 SOCK_SEQPACKET); 273 if (fd >= 0) { 274 struct sigaction ignore, old_sigaction; 275 memset(&ignore, 0, sizeof(ignore)); 276 ignore.sa_handler = caught_signal; 277 sigemptyset(&ignore.sa_mask); 278 sigaction(SIGALRM, &ignore, &old_sigaction); 279 unsigned int old_alarm = alarm(10); 280 281 static const char ask[] = "dumpAndClose lids=0,1,2,3"; 282 user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask); 283 284 user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0; 285 286 if (user_logger_content) { 287 dump_log_msg("user", &msg, 3, -1); 288 } 289 290 alarm(old_alarm); 291 sigaction(SIGALRM, &old_sigaction, NULL); 292 293 close(fd); 294 } 295 296 // check if we can read any logs from kernel logger 297 bool kernel_logger_available = false; 298 bool kernel_logger_content = false; 299 300 static const char *loggers[] = { 301 "/dev/log/main", "/dev/log_main", 302 "/dev/log/radio", "/dev/log_radio", 303 "/dev/log/events", "/dev/log_events", 304 "/dev/log/system", "/dev/log_system", 305 }; 306 307 for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) { 308 fd = open(loggers[i], O_RDONLY); 309 if (fd < 0) { 310 continue; 311 } 312 kernel_logger_available = true; 313 fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK); 314 int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg))); 315 if (result > 0) { 316 kernel_logger_content = true; 317 dump_log_msg("kernel", &msg, 0, i / 2); 318 } 319 close(fd); 320 } 321 322 static const char yes[] = "\xE2\x9C\x93"; 323 static const char no[] = "\xE2\x9c\x98"; 324 fprintf(stderr, 325 "LOGGER Available Content\n" 326 "user %-13s%s\n" 327 "kernel %-13s%s\n" 328 " status %-11s%s\n", 329 (user_logger_available) ? yes : no, 330 (user_logger_content) ? yes : no, 331 (kernel_logger_available) ? yes : no, 332 (kernel_logger_content) ? yes : no, 333 (user_logger_available && kernel_logger_available) ? "ERROR" : "ok", 334 (user_logger_content && kernel_logger_content) ? "ERROR" : "ok"); 335 336 EXPECT_EQ(0, user_logger_available && kernel_logger_available); 337 EXPECT_EQ(0, !user_logger_available && !kernel_logger_available); 338 EXPECT_EQ(0, user_logger_content && kernel_logger_content); 339 EXPECT_EQ(0, !user_logger_content && !kernel_logger_content); 340} 341 342// BAD ROBOT 343// Benchmark threshold are generally considered bad form unless there is 344// is some human love applied to the continued maintenance and whether the 345// thresholds are tuned on a per-target basis. Here we check if the values 346// are more than double what is expected. Doubling will not prevent failure 347// on busy or low-end systems that could have a tendency to stretch values. 348// 349// The primary goal of this test is to simulate a spammy app (benchmark 350// being the worst) and check to make sure the logger can deal with it 351// appropriately by checking all the statistics are in an expected range. 352// 353TEST(logd, benchmark) { 354 size_t len; 355 char *buf; 356 357 alloc_statistics(&buf, &len); 358 bool benchmark_already_run = buf && find_benchmark_spam(buf); 359 delete [] buf; 360 361 if (benchmark_already_run) { 362 fprintf(stderr, "WARNING: spam already present and too much history\n" 363 " false OK for prune by worst UID check\n"); 364 } 365 366 FILE *fp; 367 368 // Introduce some extreme spam for the worst UID filter 369 ASSERT_TRUE(NULL != (fp = popen( 370 "/data/nativetest/liblog-benchmarks/liblog-benchmarks", 371 "r"))); 372 373 char buffer[5120]; 374 375 static const char *benchmarks[] = { 376 "BM_log_maximum_retry ", 377 "BM_log_maximum ", 378 "BM_clock_overhead ", 379 "BM_log_overhead ", 380 "BM_log_latency ", 381 "BM_log_delay " 382 }; 383 static const unsigned int log_maximum_retry = 0; 384 static const unsigned int log_maximum = 1; 385 static const unsigned int clock_overhead = 2; 386 static const unsigned int log_overhead = 3; 387 static const unsigned int log_latency = 4; 388 static const unsigned int log_delay = 5; 389 390 unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])]; 391 392 memset(ns, 0, sizeof(ns)); 393 394 while (fgets(buffer, sizeof(buffer), fp)) { 395 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { 396 char *cp = strstr(buffer, benchmarks[i]); 397 if (!cp) { 398 continue; 399 } 400 sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]); 401 fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); 402 } 403 } 404 int ret = pclose(fp); 405 406 if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { 407 fprintf(stderr, 408 "WARNING: " 409 "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" 410 " can not perform test\n"); 411 return; 412 } 413 414 EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user 415 416 EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user 417 418 EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 419 420 EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user 421 422 EXPECT_GE(10000UL, ns[log_latency]); // 5669 user space 423 424 EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user 425 426 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { 427 EXPECT_NE(0UL, ns[i]); 428 } 429 430 alloc_statistics(&buf, &len); 431 432 bool collected_statistics = !!buf; 433 EXPECT_EQ(true, collected_statistics); 434 435 ASSERT_TRUE(NULL != buf); 436 437 char *benchmark_statistics_found = find_benchmark_spam(buf); 438 ASSERT_TRUE(benchmark_statistics_found != NULL); 439 440 // Check how effective the SPAM filter is, parse out Now size. 441 // 0 root 54164 147569 442 // ^-- benchmark_statistics_found 443 444 unsigned long nowSpamSize = atol(benchmark_statistics_found); 445 446 delete [] buf; 447 448 ASSERT_NE(0UL, nowSpamSize); 449 450 // Determine if we have the spam filter enabled 451 int sock = socket_local_client("logd", 452 ANDROID_SOCKET_NAMESPACE_RESERVED, 453 SOCK_STREAM); 454 455 ASSERT_TRUE(sock >= 0); 456 457 static const char getPruneList[] = "getPruneList"; 458 if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { 459 char buffer[80]; 460 memset(buffer, 0, sizeof(buffer)); 461 read(sock, buffer, sizeof(buffer)); 462 char *cp = strchr(buffer, '\n'); 463 if (!cp || (cp[1] != '~') || (cp[2] != '!')) { 464 close(sock); 465 fprintf(stderr, 466 "WARNING: " 467 "Logger has SPAM filtration turned off \"%s\"\n", buffer); 468 return; 469 } 470 } else { 471 int save_errno = errno; 472 close(sock); 473 FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno); 474 } 475 476 static const unsigned long expected_absolute_minimum_log_size = 65536UL; 477 unsigned long totalSize = expected_absolute_minimum_log_size; 478 static const char getSize[] = { 479 'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ', 480 LOG_ID_MAIN + '0', '\0' 481 }; 482 if (write(sock, getSize, sizeof(getSize)) > 0) { 483 char buffer[80]; 484 memset(buffer, 0, sizeof(buffer)); 485 read(sock, buffer, sizeof(buffer)); 486 totalSize = atol(buffer); 487 if (totalSize < expected_absolute_minimum_log_size) { 488 fprintf(stderr, 489 "WARNING: " 490 "Logger had unexpected referenced size \"%s\"\n", buffer); 491 totalSize = expected_absolute_minimum_log_size; 492 } 493 } 494 close(sock); 495 496 // logd allows excursions to 110% of total size 497 totalSize = (totalSize * 11 ) / 10; 498 499 // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) 500 ASSERT_GT(totalSize, nowSpamSize * 2); 501} 502