Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 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> |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 18 | #include <inttypes.h> |
Mark Salyzyn | 696817d | 2014-04-18 14:49:28 -0700 | [diff] [blame] | 19 | #include <poll.h> |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 20 | #include <signal.h> |
| 21 | #include <stdio.h> |
| 22 | #include <string.h> |
| 23 | |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 24 | #include <string> |
| 25 | |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 26 | #include <gtest/gtest.h> |
| 27 | |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 28 | #include <android-base/stringprintf.h> |
| 29 | #include <cutils/sockets.h> |
| 30 | #include <log/log.h> |
| 31 | #include <log/logger.h> |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 32 | |
Mark Salyzyn | 5c77ad5 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 33 | #include "../LogReader.h" // pickup LOGD_SNDTIMEO |
| 34 | |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 35 | /* |
| 36 | * returns statistics |
| 37 | */ |
| 38 | static void my_android_logger_get_statistics(char *buf, size_t len) |
| 39 | { |
Mark Salyzyn | 99f47a9 | 2014-04-07 14:58:08 -0700 | [diff] [blame] | 40 | snprintf(buf, len, "getStatistics 0 1 2 3 4"); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 41 | int sock = socket_local_client("logd", |
| 42 | ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 43 | SOCK_STREAM); |
| 44 | if (sock >= 0) { |
| 45 | if (write(sock, buf, strlen(buf) + 1) > 0) { |
Mark Salyzyn | 696817d | 2014-04-18 14:49:28 -0700 | [diff] [blame] | 46 | ssize_t ret; |
| 47 | while ((ret = read(sock, buf, len)) > 0) { |
| 48 | if ((size_t)ret == len) { |
| 49 | break; |
| 50 | } |
| 51 | len -= ret; |
| 52 | buf += ret; |
| 53 | |
| 54 | struct pollfd p = { |
| 55 | .fd = sock, |
| 56 | .events = POLLIN, |
| 57 | .revents = 0 |
| 58 | }; |
| 59 | |
| 60 | ret = poll(&p, 1, 20); |
| 61 | if ((ret <= 0) || !(p.revents & POLLIN)) { |
| 62 | break; |
| 63 | } |
| 64 | } |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 65 | } |
| 66 | close(sock); |
| 67 | } |
| 68 | } |
| 69 | |
| 70 | static void alloc_statistics(char **buffer, size_t *length) |
| 71 | { |
| 72 | size_t len = 8192; |
| 73 | char *buf; |
| 74 | |
| 75 | for(int retry = 32; (retry >= 0); delete [] buf, --retry) { |
| 76 | buf = new char [len]; |
| 77 | my_android_logger_get_statistics(buf, len); |
| 78 | |
| 79 | buf[len-1] = '\0'; |
| 80 | size_t ret = atol(buf) + 1; |
| 81 | if (ret < 4) { |
| 82 | delete [] buf; |
| 83 | buf = NULL; |
| 84 | break; |
| 85 | } |
| 86 | bool check = ret <= len; |
| 87 | len = ret; |
| 88 | if (check) { |
| 89 | break; |
| 90 | } |
| 91 | len += len / 8; // allow for some slop |
| 92 | } |
| 93 | *buffer = buf; |
| 94 | *length = len; |
| 95 | } |
| 96 | |
| 97 | static char *find_benchmark_spam(char *cp) |
| 98 | { |
| 99 | // liblog_benchmarks has been run designed to SPAM. The signature of |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 100 | // a noisiest UID statistics is: |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 101 | // |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 102 | // Chattiest UIDs in main log buffer: Size Pruned |
| 103 | // UID PACKAGE BYTES LINES |
| 104 | // 0 root 54164 147569 |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 105 | // |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 106 | char *benchmark = NULL; |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 107 | do { |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 108 | static const char signature[] = "\n0 root "; |
| 109 | |
| 110 | benchmark = strstr(cp, signature); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 111 | if (!benchmark) { |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 112 | break; |
| 113 | } |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 114 | cp = benchmark + sizeof(signature); |
| 115 | while (isspace(*cp)) { |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 116 | ++cp; |
| 117 | } |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 118 | benchmark = cp; |
Mark Salyzyn | f33657d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 119 | #ifdef DEBUG |
| 120 | char *end = strstr(benchmark, "\n"); |
| 121 | if (end == NULL) { |
| 122 | end = benchmark + strlen(benchmark); |
| 123 | } |
| 124 | fprintf(stderr, "parse for spam counter in \"%.*s\"\n", |
| 125 | (int)(end - benchmark), benchmark); |
| 126 | #endif |
| 127 | // content |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 128 | while (isdigit(*cp)) { |
| 129 | ++cp; |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 130 | } |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 131 | while (isspace(*cp)) { |
| 132 | ++cp; |
| 133 | } |
Mark Salyzyn | f33657d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 134 | // optional +/- field? |
| 135 | if ((*cp == '-') || (*cp == '+')) { |
| 136 | while (isdigit(*++cp) || |
| 137 | (*cp == '.') || (*cp == '%') || (*cp == 'X')) { |
| 138 | ; |
| 139 | } |
| 140 | while (isspace(*cp)) { |
| 141 | ++cp; |
| 142 | } |
| 143 | } |
| 144 | // number of entries pruned |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 145 | unsigned long value = 0; |
| 146 | while (isdigit(*cp)) { |
| 147 | value = value * 10ULL + *cp - '0'; |
| 148 | ++cp; |
| 149 | } |
Mark Salyzyn | f33657d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 150 | if (value > 10UL) { |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 151 | break; |
| 152 | } |
| 153 | benchmark = NULL; |
| 154 | } while (*cp); |
| 155 | return benchmark; |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 156 | } |
| 157 | |
| 158 | TEST(logd, statistics) { |
| 159 | size_t len; |
| 160 | char *buf; |
| 161 | |
| 162 | alloc_statistics(&buf, &len); |
| 163 | |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 164 | ASSERT_TRUE(NULL != buf); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 165 | |
| 166 | // remove trailing FF |
| 167 | char *cp = buf + len - 1; |
| 168 | *cp = '\0'; |
| 169 | bool truncated = *--cp != '\f'; |
| 170 | if (!truncated) { |
| 171 | *cp = '\0'; |
| 172 | } |
| 173 | |
| 174 | // squash out the byte count |
| 175 | cp = buf; |
| 176 | if (!truncated) { |
| 177 | while (isdigit(*cp) || (*cp == '\n')) { |
| 178 | ++cp; |
| 179 | } |
| 180 | } |
| 181 | |
| 182 | fprintf(stderr, "%s", cp); |
| 183 | |
| 184 | EXPECT_LT((size_t)64, strlen(cp)); |
| 185 | |
| 186 | EXPECT_EQ(0, truncated); |
| 187 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 188 | char *main_logs = strstr(cp, "\nChattiest UIDs in main "); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 189 | EXPECT_TRUE(NULL != main_logs); |
| 190 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 191 | char *radio_logs = strstr(cp, "\nChattiest UIDs in radio "); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 192 | EXPECT_TRUE(NULL != radio_logs); |
| 193 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 194 | char *system_logs = strstr(cp, "\nChattiest UIDs in system "); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 195 | EXPECT_TRUE(NULL != system_logs); |
| 196 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 197 | char *events_logs = strstr(cp, "\nChattiest UIDs in events "); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 198 | EXPECT_TRUE(NULL != events_logs); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 199 | |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 200 | delete [] buf; |
| 201 | } |
| 202 | |
Mark Salyzyn | 7b4a204 | 2015-12-07 12:27:06 -0800 | [diff] [blame] | 203 | static void caught_signal(int /* signum */) { } |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 204 | |
| 205 | static void dump_log_msg(const char *prefix, |
| 206 | log_msg *msg, unsigned int version, int lid) { |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 207 | std::cout << std::flush; |
| 208 | std::cerr << std::flush; |
| 209 | fflush(stdout); |
| 210 | fflush(stderr); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 211 | switch(msg->entry.hdr_size) { |
| 212 | case 0: |
| 213 | version = 1; |
| 214 | break; |
| 215 | |
Mark Salyzyn | 305374c | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 216 | case sizeof(msg->entry_v2): /* PLUS case sizeof(msg->entry_v3): */ |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 217 | if (version == 0) { |
Mark Salyzyn | 305374c | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 218 | version = (msg->entry_v3.lid < LOG_ID_MAX) ? 3 : 2; |
| 219 | } |
| 220 | break; |
| 221 | |
| 222 | case sizeof(msg->entry_v4): |
| 223 | if (version == 0) { |
| 224 | version = 4; |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 225 | } |
| 226 | break; |
| 227 | } |
| 228 | |
| 229 | fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len()); |
| 230 | if (version != 1) { |
| 231 | fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); |
| 232 | } |
| 233 | fprintf(stderr, "pid=%u tid=%u %u.%09u ", |
| 234 | msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec); |
| 235 | switch(version) { |
| 236 | case 1: |
| 237 | break; |
| 238 | case 2: |
| 239 | fprintf(stderr, "euid=%u ", msg->entry_v2.euid); |
| 240 | break; |
| 241 | case 3: |
| 242 | default: |
| 243 | lid = msg->entry.lid; |
| 244 | break; |
| 245 | } |
| 246 | |
| 247 | switch(lid) { |
| 248 | case 0: |
| 249 | fprintf(stderr, "lid=main "); |
| 250 | break; |
| 251 | case 1: |
| 252 | fprintf(stderr, "lid=radio "); |
| 253 | break; |
| 254 | case 2: |
| 255 | fprintf(stderr, "lid=events "); |
| 256 | break; |
| 257 | case 3: |
| 258 | fprintf(stderr, "lid=system "); |
| 259 | break; |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 260 | case 4: |
| 261 | fprintf(stderr, "lid=crash "); |
| 262 | break; |
| 263 | case 5: |
Mark Salyzyn | 5c77ad5 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 264 | fprintf(stderr, "lid=security "); |
| 265 | break; |
| 266 | case 6: |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 267 | fprintf(stderr, "lid=kernel "); |
| 268 | break; |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 269 | default: |
| 270 | if (lid >= 0) { |
| 271 | fprintf(stderr, "lid=%d ", lid); |
| 272 | } |
| 273 | } |
| 274 | |
| 275 | unsigned int len = msg->entry.len; |
| 276 | fprintf(stderr, "msg[%u]={", len); |
| 277 | unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg()); |
Mark Salyzyn | 305374c | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 278 | if (!cp) { |
| 279 | static const unsigned char garbage[] = "<INVALID>"; |
| 280 | cp = const_cast<unsigned char *>(garbage); |
| 281 | len = strlen(reinterpret_cast<const char *>(garbage)); |
| 282 | } |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 283 | while(len) { |
| 284 | unsigned char *p = cp; |
| 285 | while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { |
| 286 | ++p; |
| 287 | } |
| 288 | if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { |
| 289 | fprintf(stderr, "\""); |
| 290 | while (*cp) { |
Chih-Hung Hsieh | 634118e | 2014-09-12 16:02:28 -0700 | [diff] [blame] | 291 | if (*cp != '\n') { |
| 292 | fprintf(stderr, "%c", *cp); |
| 293 | } else { |
| 294 | fprintf(stderr, "\\n"); |
| 295 | } |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 296 | ++cp; |
| 297 | --len; |
| 298 | } |
| 299 | fprintf(stderr, "\""); |
| 300 | } else { |
| 301 | fprintf(stderr, "%02x", *cp); |
| 302 | } |
| 303 | ++cp; |
| 304 | if (--len) { |
| 305 | fprintf(stderr, ", "); |
| 306 | } |
| 307 | } |
| 308 | fprintf(stderr, "}\n"); |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 309 | fflush(stderr); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 310 | } |
| 311 | |
| 312 | TEST(logd, both) { |
| 313 | log_msg msg; |
| 314 | |
| 315 | // check if we can read any logs from logd |
| 316 | bool user_logger_available = false; |
| 317 | bool user_logger_content = false; |
| 318 | |
| 319 | int fd = socket_local_client("logdr", |
| 320 | ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 321 | SOCK_SEQPACKET); |
| 322 | if (fd >= 0) { |
| 323 | struct sigaction ignore, old_sigaction; |
| 324 | memset(&ignore, 0, sizeof(ignore)); |
| 325 | ignore.sa_handler = caught_signal; |
| 326 | sigemptyset(&ignore.sa_mask); |
| 327 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 328 | unsigned int old_alarm = alarm(10); |
| 329 | |
| 330 | static const char ask[] = "dumpAndClose lids=0,1,2,3"; |
| 331 | user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask); |
| 332 | |
| 333 | user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0; |
| 334 | |
| 335 | if (user_logger_content) { |
| 336 | dump_log_msg("user", &msg, 3, -1); |
| 337 | } |
| 338 | |
Mark Salyzyn | c61895a | 2014-04-30 09:21:54 -0700 | [diff] [blame] | 339 | alarm(old_alarm); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 340 | sigaction(SIGALRM, &old_sigaction, NULL); |
| 341 | |
| 342 | close(fd); |
| 343 | } |
| 344 | |
| 345 | // check if we can read any logs from kernel logger |
| 346 | bool kernel_logger_available = false; |
| 347 | bool kernel_logger_content = false; |
| 348 | |
| 349 | static const char *loggers[] = { |
| 350 | "/dev/log/main", "/dev/log_main", |
| 351 | "/dev/log/radio", "/dev/log_radio", |
| 352 | "/dev/log/events", "/dev/log_events", |
| 353 | "/dev/log/system", "/dev/log_system", |
| 354 | }; |
| 355 | |
| 356 | for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) { |
| 357 | fd = open(loggers[i], O_RDONLY); |
| 358 | if (fd < 0) { |
| 359 | continue; |
| 360 | } |
| 361 | kernel_logger_available = true; |
| 362 | fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK); |
| 363 | int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg))); |
| 364 | if (result > 0) { |
| 365 | kernel_logger_content = true; |
| 366 | dump_log_msg("kernel", &msg, 0, i / 2); |
| 367 | } |
| 368 | close(fd); |
| 369 | } |
| 370 | |
| 371 | static const char yes[] = "\xE2\x9C\x93"; |
| 372 | static const char no[] = "\xE2\x9c\x98"; |
| 373 | fprintf(stderr, |
| 374 | "LOGGER Available Content\n" |
| 375 | "user %-13s%s\n" |
| 376 | "kernel %-13s%s\n" |
| 377 | " status %-11s%s\n", |
| 378 | (user_logger_available) ? yes : no, |
| 379 | (user_logger_content) ? yes : no, |
| 380 | (kernel_logger_available) ? yes : no, |
| 381 | (kernel_logger_content) ? yes : no, |
Mark Salyzyn | 89472df | 2014-07-10 13:31:57 -0700 | [diff] [blame] | 382 | (user_logger_available && kernel_logger_available) ? "ERROR" : "ok", |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 383 | (user_logger_content && kernel_logger_content) ? "ERROR" : "ok"); |
| 384 | |
Mark Salyzyn | 89472df | 2014-07-10 13:31:57 -0700 | [diff] [blame] | 385 | EXPECT_EQ(0, user_logger_available && kernel_logger_available); |
| 386 | EXPECT_EQ(0, !user_logger_available && !kernel_logger_available); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 387 | EXPECT_EQ(0, user_logger_content && kernel_logger_content); |
| 388 | EXPECT_EQ(0, !user_logger_content && !kernel_logger_content); |
| 389 | } |
| 390 | |
| 391 | // BAD ROBOT |
| 392 | // Benchmark threshold are generally considered bad form unless there is |
| 393 | // is some human love applied to the continued maintenance and whether the |
| 394 | // thresholds are tuned on a per-target basis. Here we check if the values |
| 395 | // are more than double what is expected. Doubling will not prevent failure |
| 396 | // on busy or low-end systems that could have a tendency to stretch values. |
| 397 | // |
| 398 | // The primary goal of this test is to simulate a spammy app (benchmark |
| 399 | // being the worst) and check to make sure the logger can deal with it |
| 400 | // appropriately by checking all the statistics are in an expected range. |
| 401 | // |
| 402 | TEST(logd, benchmark) { |
| 403 | size_t len; |
| 404 | char *buf; |
| 405 | |
| 406 | alloc_statistics(&buf, &len); |
| 407 | bool benchmark_already_run = buf && find_benchmark_spam(buf); |
| 408 | delete [] buf; |
| 409 | |
| 410 | if (benchmark_already_run) { |
| 411 | fprintf(stderr, "WARNING: spam already present and too much history\n" |
| 412 | " false OK for prune by worst UID check\n"); |
| 413 | } |
| 414 | |
| 415 | FILE *fp; |
| 416 | |
| 417 | // Introduce some extreme spam for the worst UID filter |
| 418 | ASSERT_TRUE(NULL != (fp = popen( |
| 419 | "/data/nativetest/liblog-benchmarks/liblog-benchmarks", |
| 420 | "r"))); |
| 421 | |
| 422 | char buffer[5120]; |
| 423 | |
| 424 | static const char *benchmarks[] = { |
| 425 | "BM_log_maximum_retry ", |
| 426 | "BM_log_maximum ", |
| 427 | "BM_clock_overhead ", |
| 428 | "BM_log_overhead ", |
| 429 | "BM_log_latency ", |
| 430 | "BM_log_delay " |
| 431 | }; |
| 432 | static const unsigned int log_maximum_retry = 0; |
| 433 | static const unsigned int log_maximum = 1; |
| 434 | static const unsigned int clock_overhead = 2; |
| 435 | static const unsigned int log_overhead = 3; |
| 436 | static const unsigned int log_latency = 4; |
| 437 | static const unsigned int log_delay = 5; |
| 438 | |
| 439 | unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])]; |
| 440 | |
| 441 | memset(ns, 0, sizeof(ns)); |
| 442 | |
| 443 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 444 | for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 445 | char *cp = strstr(buffer, benchmarks[i]); |
| 446 | if (!cp) { |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 447 | continue; |
| 448 | } |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 449 | sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 450 | fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); |
| 451 | } |
| 452 | } |
| 453 | int ret = pclose(fp); |
| 454 | |
| 455 | if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { |
| 456 | fprintf(stderr, |
| 457 | "WARNING: " |
| 458 | "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" |
| 459 | " can not perform test\n"); |
| 460 | return; |
| 461 | } |
| 462 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 463 | EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 464 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 465 | EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 466 | |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 467 | EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 468 | |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 469 | EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 470 | |
Mark Salyzyn | 074f542 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 471 | EXPECT_GE(10000000UL, ns[log_latency]); // 1453559 user space (background cgroup) |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 472 | |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 473 | EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 474 | |
| 475 | for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { |
| 476 | EXPECT_NE(0UL, ns[i]); |
| 477 | } |
| 478 | |
| 479 | alloc_statistics(&buf, &len); |
| 480 | |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 481 | bool collected_statistics = !!buf; |
| 482 | EXPECT_EQ(true, collected_statistics); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 483 | |
| 484 | ASSERT_TRUE(NULL != buf); |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 485 | |
| 486 | char *benchmark_statistics_found = find_benchmark_spam(buf); |
| 487 | ASSERT_TRUE(benchmark_statistics_found != NULL); |
| 488 | |
| 489 | // Check how effective the SPAM filter is, parse out Now size. |
Mark Salyzyn | 62d6a2a | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 490 | // 0 root 54164 147569 |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 491 | // ^-- benchmark_statistics_found |
| 492 | |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 493 | unsigned long nowSpamSize = atol(benchmark_statistics_found); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 494 | |
| 495 | delete [] buf; |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 496 | |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 497 | ASSERT_NE(0UL, nowSpamSize); |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 498 | |
Mark Salyzyn | 6e9aaae | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 499 | // Determine if we have the spam filter enabled |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 500 | int sock = socket_local_client("logd", |
| 501 | ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 502 | SOCK_STREAM); |
Mark Salyzyn | 6e9aaae | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 503 | |
| 504 | ASSERT_TRUE(sock >= 0); |
| 505 | |
| 506 | static const char getPruneList[] = "getPruneList"; |
| 507 | if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { |
| 508 | char buffer[80]; |
| 509 | memset(buffer, 0, sizeof(buffer)); |
| 510 | read(sock, buffer, sizeof(buffer)); |
| 511 | char *cp = strchr(buffer, '\n'); |
| 512 | if (!cp || (cp[1] != '~') || (cp[2] != '!')) { |
| 513 | close(sock); |
| 514 | fprintf(stderr, |
| 515 | "WARNING: " |
| 516 | "Logger has SPAM filtration turned off \"%s\"\n", buffer); |
| 517 | return; |
| 518 | } |
| 519 | } else { |
| 520 | int save_errno = errno; |
| 521 | close(sock); |
| 522 | FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno); |
| 523 | } |
| 524 | |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 525 | static const unsigned long expected_absolute_minimum_log_size = 65536UL; |
| 526 | unsigned long totalSize = expected_absolute_minimum_log_size; |
Mark Salyzyn | 6e9aaae | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 527 | static const char getSize[] = { |
| 528 | 'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ', |
| 529 | LOG_ID_MAIN + '0', '\0' |
| 530 | }; |
| 531 | if (write(sock, getSize, sizeof(getSize)) > 0) { |
| 532 | char buffer[80]; |
| 533 | memset(buffer, 0, sizeof(buffer)); |
| 534 | read(sock, buffer, sizeof(buffer)); |
| 535 | totalSize = atol(buffer); |
| 536 | if (totalSize < expected_absolute_minimum_log_size) { |
| 537 | fprintf(stderr, |
| 538 | "WARNING: " |
| 539 | "Logger had unexpected referenced size \"%s\"\n", buffer); |
| 540 | totalSize = expected_absolute_minimum_log_size; |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 541 | } |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 542 | } |
Mark Salyzyn | 6e9aaae | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 543 | close(sock); |
| 544 | |
Mark Salyzyn | e821dac | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 545 | // logd allows excursions to 110% of total size |
| 546 | totalSize = (totalSize * 11 ) / 10; |
| 547 | |
| 548 | // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) |
Mark Salyzyn | 0c57bd8 | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 549 | ASSERT_GT(totalSize, nowSpamSize * 2); |
Mark Salyzyn | d3ba665 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 550 | } |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 551 | |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 552 | // b/26447386 confirm fixed |
| 553 | void timeout_negative(const char *command) { |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 554 | log_msg msg_wrap, msg_timeout; |
| 555 | bool content_wrap = false, content_timeout = false, written = false; |
| 556 | unsigned int alarm_wrap = 0, alarm_timeout = 0; |
| 557 | // A few tries to get it right just in case wrap kicks in due to |
| 558 | // content providers being active during the test. |
| 559 | int i = 3; |
| 560 | |
| 561 | while (--i) { |
| 562 | int fd = socket_local_client("logdr", |
| 563 | ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 564 | SOCK_SEQPACKET); |
| 565 | ASSERT_LT(0, fd); |
| 566 | |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 567 | std::string ask(command); |
| 568 | |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 569 | struct sigaction ignore, old_sigaction; |
| 570 | memset(&ignore, 0, sizeof(ignore)); |
| 571 | ignore.sa_handler = caught_signal; |
| 572 | sigemptyset(&ignore.sa_mask); |
| 573 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 574 | unsigned int old_alarm = alarm(3); |
| 575 | |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 576 | size_t len = ask.length() + 1; |
| 577 | written = write(fd, ask.c_str(), len) == (ssize_t)len; |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 578 | if (!written) { |
| 579 | alarm(old_alarm); |
| 580 | sigaction(SIGALRM, &old_sigaction, NULL); |
| 581 | close(fd); |
| 582 | continue; |
| 583 | } |
| 584 | |
| 585 | content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; |
| 586 | |
| 587 | alarm_wrap = alarm(5); |
| 588 | |
| 589 | content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 590 | if (!content_timeout) { // make sure we hit dumpAndClose |
| 591 | content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
| 592 | } |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 593 | |
| 594 | alarm_timeout = alarm((old_alarm <= 0) |
| 595 | ? old_alarm |
| 596 | : (old_alarm > (1 + 3 - alarm_wrap)) |
| 597 | ? old_alarm - 3 + alarm_wrap |
| 598 | : 2); |
| 599 | sigaction(SIGALRM, &old_sigaction, NULL); |
| 600 | |
| 601 | close(fd); |
| 602 | |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 603 | if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 604 | break; |
| 605 | } |
| 606 | } |
| 607 | |
| 608 | if (content_wrap) { |
| 609 | dump_log_msg("wrap", &msg_wrap, 3, -1); |
| 610 | } |
| 611 | |
| 612 | if (content_timeout) { |
| 613 | dump_log_msg("timeout", &msg_timeout, 3, -1); |
| 614 | } |
| 615 | |
| 616 | EXPECT_TRUE(written); |
Mark Salyzyn | ef4e4f3 | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 617 | EXPECT_TRUE(content_wrap); |
| 618 | EXPECT_NE(0U, alarm_wrap); |
| 619 | EXPECT_TRUE(content_timeout); |
| 620 | EXPECT_NE(0U, alarm_timeout); |
| 621 | } |
| 622 | |
| 623 | TEST(logd, timeout_no_start) { |
| 624 | timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6"); |
| 625 | } |
| 626 | |
| 627 | TEST(logd, timeout_start_epoch) { |
| 628 | timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000"); |
| 629 | } |
| 630 | |
| 631 | // b/26447386 refined behavior |
| 632 | TEST(logd, timeout) { |
| 633 | log_msg msg_wrap, msg_timeout; |
| 634 | bool content_wrap = false, content_timeout = false, written = false; |
| 635 | unsigned int alarm_wrap = 0, alarm_timeout = 0; |
| 636 | // A few tries to get it right just in case wrap kicks in due to |
| 637 | // content providers being active during the test |
| 638 | int i = 5; |
| 639 | log_time now(android_log_clockid()); |
| 640 | now.tv_sec -= 30; // reach back a moderate period of time |
| 641 | |
| 642 | while (--i) { |
| 643 | int fd = socket_local_client("logdr", |
| 644 | ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 645 | SOCK_SEQPACKET); |
| 646 | ASSERT_LT(0, fd); |
| 647 | |
| 648 | std::string ask = android::base::StringPrintf( |
| 649 | "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" |
| 650 | PRIu32 ".%09" PRIu32, |
| 651 | now.tv_sec, now.tv_nsec); |
| 652 | |
| 653 | struct sigaction ignore, old_sigaction; |
| 654 | memset(&ignore, 0, sizeof(ignore)); |
| 655 | ignore.sa_handler = caught_signal; |
| 656 | sigemptyset(&ignore.sa_mask); |
| 657 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 658 | unsigned int old_alarm = alarm(3); |
| 659 | |
| 660 | size_t len = ask.length() + 1; |
| 661 | written = write(fd, ask.c_str(), len) == (ssize_t)len; |
| 662 | if (!written) { |
| 663 | alarm(old_alarm); |
| 664 | sigaction(SIGALRM, &old_sigaction, NULL); |
| 665 | close(fd); |
| 666 | continue; |
| 667 | } |
| 668 | |
| 669 | content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; |
| 670 | |
| 671 | alarm_wrap = alarm(5); |
| 672 | |
| 673 | content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
| 674 | if (!content_timeout) { // make sure we hit dumpAndClose |
| 675 | content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
| 676 | } |
| 677 | |
| 678 | alarm_timeout = alarm((old_alarm <= 0) |
| 679 | ? old_alarm |
| 680 | : (old_alarm > (1 + 3 - alarm_wrap)) |
| 681 | ? old_alarm - 3 + alarm_wrap |
| 682 | : 2); |
| 683 | sigaction(SIGALRM, &old_sigaction, NULL); |
| 684 | |
| 685 | close(fd); |
| 686 | |
| 687 | if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { |
| 688 | break; |
| 689 | } |
| 690 | |
| 691 | // modify start time in case content providers are relatively |
| 692 | // active _or_ inactive during the test. |
| 693 | if (content_timeout) { |
| 694 | log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); |
| 695 | EXPECT_FALSE(msg < now); |
| 696 | if (msg > now) { |
| 697 | now = msg; |
| 698 | now.tv_sec += 30; |
| 699 | msg = log_time(android_log_clockid()); |
| 700 | if (now > msg) { |
| 701 | now = msg; |
| 702 | --now.tv_sec; |
| 703 | } |
| 704 | } |
| 705 | } else { |
| 706 | now.tv_sec -= 120; // inactive, reach further back! |
| 707 | } |
| 708 | } |
| 709 | |
| 710 | if (content_wrap) { |
| 711 | dump_log_msg("wrap", &msg_wrap, 3, -1); |
| 712 | } |
| 713 | |
| 714 | if (content_timeout) { |
| 715 | dump_log_msg("timeout", &msg_timeout, 3, -1); |
| 716 | } |
| 717 | |
| 718 | if (content_wrap || !content_timeout) { |
| 719 | fprintf(stderr, "now=%" PRIu32 ".%09" PRIu32 "\n", |
| 720 | now.tv_sec, now.tv_nsec); |
| 721 | } |
| 722 | |
| 723 | EXPECT_TRUE(written); |
Mark Salyzyn | fc9f5b8 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 724 | EXPECT_FALSE(content_wrap); |
| 725 | EXPECT_EQ(0U, alarm_wrap); |
| 726 | EXPECT_TRUE(content_timeout); |
| 727 | EXPECT_NE(0U, alarm_timeout); |
| 728 | } |
Mark Salyzyn | 5c77ad5 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 729 | |
| 730 | // b/27242723 confirmed fixed |
| 731 | TEST(logd, SNDTIMEO) { |
| 732 | static const unsigned sndtimeo = LOGD_SNDTIMEO; // <sigh> it has to be done! |
| 733 | static const unsigned sleep_time = sndtimeo + 3; |
| 734 | static const unsigned alarm_time = sleep_time + 5; |
| 735 | |
| 736 | int fd; |
| 737 | |
| 738 | ASSERT_TRUE((fd = socket_local_client("logdr", |
| 739 | ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 740 | SOCK_SEQPACKET)) > 0); |
| 741 | |
| 742 | struct sigaction ignore, old_sigaction; |
| 743 | memset(&ignore, 0, sizeof(ignore)); |
| 744 | ignore.sa_handler = caught_signal; |
| 745 | sigemptyset(&ignore.sa_mask); |
| 746 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 747 | unsigned int old_alarm = alarm(alarm_time); |
| 748 | |
| 749 | static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources |
| 750 | bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask); |
| 751 | EXPECT_TRUE(reader_requested); |
| 752 | |
| 753 | log_msg msg; |
| 754 | bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0; |
| 755 | |
| 756 | EXPECT_TRUE(read_one); |
| 757 | if (read_one) { |
| 758 | dump_log_msg("user", &msg, 3, -1); |
| 759 | } |
| 760 | |
| 761 | fprintf (stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo); |
| 762 | sleep(sleep_time); |
| 763 | |
| 764 | // flush will block if we did not trigger. if it did, last entry returns 0 |
| 765 | int recv_ret; |
| 766 | do { |
| 767 | recv_ret = recv(fd, msg.buf, sizeof(msg), 0); |
| 768 | } while (recv_ret > 0); |
| 769 | int save_errno = (recv_ret < 0) ? errno : 0; |
| 770 | |
| 771 | EXPECT_NE(0U, alarm(old_alarm)); |
| 772 | sigaction(SIGALRM, &old_sigaction, NULL); |
| 773 | |
| 774 | EXPECT_EQ(0, recv_ret); |
| 775 | if (recv_ret > 0) { |
| 776 | dump_log_msg("user", &msg, 3, -1); |
| 777 | } |
| 778 | EXPECT_EQ(0, save_errno); |
| 779 | |
| 780 | close(fd); |
| 781 | } |