| /* |
| * Copyright (C) 2014 The Android Open Source Project |
| * |
| * Licensed under the Apache License, Version 2.0 (the "License"); |
| * you may not use this file except in compliance with the License. |
| * You may obtain a copy of the License at |
| * |
| * http://www.apache.org/licenses/LICENSE-2.0 |
| * |
| * Unless required by applicable law or agreed to in writing, software |
| * distributed under the License is distributed on an "AS IS" BASIS, |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| * See the License for the specific language governing permissions and |
| * limitations under the License. |
| */ |
| |
| #include <fcntl.h> |
| #include <poll.h> |
| #include <signal.h> |
| #include <stdio.h> |
| #include <string.h> |
| |
| #include <gtest/gtest.h> |
| |
| #include "cutils/sockets.h" |
| #include "log/log.h" |
| #include "log/logger.h" |
| |
| #define __unused __attribute__((__unused__)) |
| |
| /* |
| * returns statistics |
| */ |
| static void my_android_logger_get_statistics(char *buf, size_t len) |
| { |
| snprintf(buf, len, "getStatistics 0 1 2 3 4"); |
| int sock = socket_local_client("logd", |
| ANDROID_SOCKET_NAMESPACE_RESERVED, |
| SOCK_STREAM); |
| if (sock >= 0) { |
| if (write(sock, buf, strlen(buf) + 1) > 0) { |
| ssize_t ret; |
| while ((ret = read(sock, buf, len)) > 0) { |
| if ((size_t)ret == len) { |
| break; |
| } |
| len -= ret; |
| buf += ret; |
| |
| struct pollfd p = { |
| .fd = sock, |
| .events = POLLIN, |
| .revents = 0 |
| }; |
| |
| ret = poll(&p, 1, 20); |
| if ((ret <= 0) || !(p.revents & POLLIN)) { |
| break; |
| } |
| } |
| } |
| close(sock); |
| } |
| } |
| |
| static void alloc_statistics(char **buffer, size_t *length) |
| { |
| size_t len = 8192; |
| char *buf; |
| |
| for(int retry = 32; (retry >= 0); delete [] buf, --retry) { |
| buf = new char [len]; |
| my_android_logger_get_statistics(buf, len); |
| |
| buf[len-1] = '\0'; |
| size_t ret = atol(buf) + 1; |
| if (ret < 4) { |
| delete [] buf; |
| buf = NULL; |
| break; |
| } |
| bool check = ret <= len; |
| len = ret; |
| if (check) { |
| break; |
| } |
| len += len / 8; // allow for some slop |
| } |
| *buffer = buf; |
| *length = len; |
| } |
| |
| static char *find_benchmark_spam(char *cp) |
| { |
| // liblog_benchmarks has been run designed to SPAM. The signature of |
| // a noisiest UID statistics is one of the following: |
| // |
| // main: UID/PID Total size/num Now UID/PID[?] Total |
| // 0 7500306/304207 71608/3183 0/4225? 7454388/303656 |
| // <wrap> 93432/1012 |
| // -or- |
| // 0/gone 7454388/303656 93432/1012 |
| // |
| // basically if we see a *large* number of 0/????? entries |
| unsigned long value; |
| do { |
| char *benchmark = strstr(cp, " 0/"); |
| char *benchmark_newline = strstr(cp, "\n0/"); |
| if (!benchmark) { |
| benchmark = benchmark_newline; |
| } |
| if (benchmark_newline && (benchmark > benchmark_newline)) { |
| benchmark = benchmark_newline; |
| } |
| cp = benchmark; |
| if (!cp) { |
| break; |
| } |
| cp += 3; |
| while (isdigit(*cp) || (*cp == 'g') || (*cp == 'o') || (*cp == 'n')) { |
| ++cp; |
| } |
| value = 0; |
| // ###? or gone |
| if ((*cp == '?') || (*cp == 'e')) { |
| while (*++cp == ' '); |
| while (isdigit(*cp)) { |
| value = value * 10ULL + *cp - '0'; |
| ++cp; |
| } |
| if (*cp != '/') { |
| value = 0; |
| continue; |
| } |
| while (isdigit(*++cp)); |
| while (*cp == ' ') ++cp; |
| if (!isdigit(*cp)) { |
| value = 0; |
| } |
| } |
| } while ((value < 900000ULL) && *cp); |
| return cp; |
| } |
| |
| TEST(logd, statistics) { |
| size_t len; |
| char *buf; |
| |
| alloc_statistics(&buf, &len); |
| |
| #ifdef TARGET_USES_LOGD |
| ASSERT_TRUE(NULL != buf); |
| #else |
| if (!buf) { |
| return; |
| } |
| #endif |
| |
| // remove trailing FF |
| char *cp = buf + len - 1; |
| *cp = '\0'; |
| bool truncated = *--cp != '\f'; |
| if (!truncated) { |
| *cp = '\0'; |
| } |
| |
| // squash out the byte count |
| cp = buf; |
| if (!truncated) { |
| while (isdigit(*cp) || (*cp == '\n')) { |
| ++cp; |
| } |
| } |
| |
| fprintf(stderr, "%s", cp); |
| |
| EXPECT_LT((size_t)64, strlen(cp)); |
| |
| EXPECT_EQ(0, truncated); |
| |
| #ifdef TARGET_USES_LOGD |
| char *main_logs = strstr(cp, "\nmain:"); |
| EXPECT_TRUE(NULL != main_logs); |
| |
| char *radio_logs = strstr(cp, "\nradio:"); |
| EXPECT_TRUE(NULL != radio_logs); |
| |
| char *system_logs = strstr(cp, "\nsystem:"); |
| EXPECT_TRUE(NULL != system_logs); |
| |
| char *events_logs = strstr(cp, "\nevents:"); |
| EXPECT_TRUE(NULL != events_logs); |
| #endif |
| |
| // Parse timing stats |
| |
| cp = strstr(cp, "Minimum time between log events per dgram_qlen:"); |
| |
| char *log_events_per_span = cp; |
| |
| if (cp) { |
| while (*cp && (*cp != '\n')) { |
| ++cp; |
| } |
| if (*cp == '\n') { |
| ++cp; |
| } |
| |
| char *list_of_spans = cp; |
| EXPECT_NE('\0', *list_of_spans); |
| |
| unsigned short number_of_buckets = 0; |
| unsigned short *dgram_qlen = NULL; |
| unsigned short bucket = 0; |
| while (*cp && (*cp != '\n')) { |
| bucket = 0; |
| while (isdigit(*cp)) { |
| bucket = bucket * 10 + *cp - '0'; |
| ++cp; |
| } |
| while (*cp == ' ') { |
| ++cp; |
| } |
| if (!bucket) { |
| break; |
| } |
| unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1]; |
| EXPECT_TRUE(new_dgram_qlen != NULL); |
| if (dgram_qlen) { |
| memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets); |
| delete [] dgram_qlen; |
| } |
| |
| dgram_qlen = new_dgram_qlen; |
| dgram_qlen[number_of_buckets++] = bucket; |
| } |
| |
| char *end_of_spans = cp; |
| EXPECT_NE('\0', *end_of_spans); |
| |
| EXPECT_LT(5, number_of_buckets); |
| |
| unsigned long long *times = new unsigned long long [number_of_buckets]; |
| ASSERT_TRUE(times != NULL); |
| |
| memset(times, 0, sizeof(*times) * number_of_buckets); |
| |
| while (*cp == '\n') { |
| ++cp; |
| } |
| |
| unsigned short number_of_values = 0; |
| unsigned long long value; |
| while (*cp && (*cp != '\n')) { |
| EXPECT_GE(number_of_buckets, number_of_values); |
| |
| value = 0; |
| while (isdigit(*cp)) { |
| value = value * 10ULL + *cp - '0'; |
| ++cp; |
| } |
| |
| switch(*cp) { |
| case ' ': |
| case '\n': |
| value *= 1000ULL; |
| /* FALLTHRU */ |
| case 'm': |
| value *= 1000ULL; |
| /* FALLTHRU */ |
| case 'u': |
| value *= 1000ULL; |
| /* FALLTHRU */ |
| case 'n': |
| default: |
| break; |
| } |
| while (*++cp == ' '); |
| |
| if (!value) { |
| break; |
| } |
| |
| times[number_of_values] = value; |
| ++number_of_values; |
| } |
| |
| #ifdef TARGET_USES_LOGD |
| EXPECT_EQ(number_of_values, number_of_buckets); |
| #endif |
| |
| FILE *fp; |
| ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r"))); |
| |
| unsigned max_dgram_qlen = 0; |
| fscanf(fp, "%u", &max_dgram_qlen); |
| |
| fclose(fp); |
| |
| // Find launch point |
| unsigned short launch = 0; |
| unsigned long long total = 0; |
| do { |
| total += times[launch]; |
| } while (((++launch < number_of_buckets) |
| && ((total / launch) >= (times[launch] / 8ULL))) |
| || (launch == 1)); // too soon |
| |
| bool failure = number_of_buckets <= launch; |
| if (!failure) { |
| unsigned short l = launch; |
| if (l >= number_of_buckets) { |
| l = number_of_buckets - 1; |
| } |
| failure = max_dgram_qlen < dgram_qlen[l]; |
| } |
| |
| // We can get failure if at any time liblog_benchmarks has been run |
| // because designed to overload /proc/sys/net/unix/max_dgram_qlen even |
| // at excessive values like 20000. It does so to measure the raw processing |
| // performance of logd. |
| if (failure) { |
| cp = find_benchmark_spam(cp); |
| } |
| |
| if (cp) { |
| // Fake a failure, but without the failure code |
| if (number_of_buckets <= launch) { |
| printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n", |
| number_of_buckets, launch); |
| } |
| if (launch >= number_of_buckets) { |
| launch = number_of_buckets - 1; |
| } |
| if (max_dgram_qlen < dgram_qlen[launch]) { |
| printf ("Expected: max_dgram_qlen >= dgram_qlen[%d]," |
| " actual: %u vs %u\n", |
| launch, max_dgram_qlen, dgram_qlen[launch]); |
| } |
| } else |
| #ifndef TARGET_USES_LOGD |
| if (total) |
| #endif |
| { |
| EXPECT_GT(number_of_buckets, launch); |
| if (launch >= number_of_buckets) { |
| launch = number_of_buckets - 1; |
| } |
| EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]); |
| } |
| |
| delete [] dgram_qlen; |
| delete [] times; |
| } |
| delete [] buf; |
| } |
| |
| static void caught_signal(int signum __unused) { } |
| |
| static void dump_log_msg(const char *prefix, |
| log_msg *msg, unsigned int version, int lid) { |
| switch(msg->entry.hdr_size) { |
| case 0: |
| version = 1; |
| break; |
| |
| case sizeof(msg->entry_v2): |
| if (version == 0) { |
| version = 2; |
| } |
| break; |
| } |
| |
| fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len()); |
| if (version != 1) { |
| fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); |
| } |
| fprintf(stderr, "pid=%u tid=%u %u.%09u ", |
| msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec); |
| switch(version) { |
| case 1: |
| break; |
| case 2: |
| fprintf(stderr, "euid=%u ", msg->entry_v2.euid); |
| break; |
| case 3: |
| default: |
| lid = msg->entry.lid; |
| break; |
| } |
| |
| switch(lid) { |
| case 0: |
| fprintf(stderr, "lid=main "); |
| break; |
| case 1: |
| fprintf(stderr, "lid=radio "); |
| break; |
| case 2: |
| fprintf(stderr, "lid=events "); |
| break; |
| case 3: |
| fprintf(stderr, "lid=system "); |
| break; |
| default: |
| if (lid >= 0) { |
| fprintf(stderr, "lid=%d ", lid); |
| } |
| } |
| |
| unsigned int len = msg->entry.len; |
| fprintf(stderr, "msg[%u]={", len); |
| unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg()); |
| while(len) { |
| unsigned char *p = cp; |
| while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { |
| ++p; |
| } |
| if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { |
| fprintf(stderr, "\""); |
| while (*cp) { |
| fprintf(stderr, (*cp != '\n') ? "%c" : "\\n", *cp); |
| ++cp; |
| --len; |
| } |
| fprintf(stderr, "\""); |
| } else { |
| fprintf(stderr, "%02x", *cp); |
| } |
| ++cp; |
| if (--len) { |
| fprintf(stderr, ", "); |
| } |
| } |
| fprintf(stderr, "}\n"); |
| } |
| |
| TEST(logd, both) { |
| log_msg msg; |
| |
| // check if we can read any logs from logd |
| bool user_logger_available = false; |
| bool user_logger_content = false; |
| |
| int fd = socket_local_client("logdr", |
| ANDROID_SOCKET_NAMESPACE_RESERVED, |
| SOCK_SEQPACKET); |
| if (fd >= 0) { |
| struct sigaction ignore, old_sigaction; |
| memset(&ignore, 0, sizeof(ignore)); |
| ignore.sa_handler = caught_signal; |
| sigemptyset(&ignore.sa_mask); |
| sigaction(SIGALRM, &ignore, &old_sigaction); |
| unsigned int old_alarm = alarm(10); |
| |
| static const char ask[] = "dumpAndClose lids=0,1,2,3"; |
| user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask); |
| |
| user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0; |
| |
| if (user_logger_content) { |
| dump_log_msg("user", &msg, 3, -1); |
| } |
| |
| alarm(0); |
| sigaction(SIGALRM, &old_sigaction, NULL); |
| |
| close(fd); |
| } |
| |
| // check if we can read any logs from kernel logger |
| bool kernel_logger_available = false; |
| bool kernel_logger_content = false; |
| |
| static const char *loggers[] = { |
| "/dev/log/main", "/dev/log_main", |
| "/dev/log/radio", "/dev/log_radio", |
| "/dev/log/events", "/dev/log_events", |
| "/dev/log/system", "/dev/log_system", |
| }; |
| |
| for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) { |
| fd = open(loggers[i], O_RDONLY); |
| if (fd < 0) { |
| continue; |
| } |
| kernel_logger_available = true; |
| fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK); |
| int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg))); |
| if (result > 0) { |
| kernel_logger_content = true; |
| dump_log_msg("kernel", &msg, 0, i / 2); |
| } |
| close(fd); |
| } |
| |
| static const char yes[] = "\xE2\x9C\x93"; |
| static const char no[] = "\xE2\x9c\x98"; |
| fprintf(stderr, |
| "LOGGER Available Content\n" |
| "user %-13s%s\n" |
| "kernel %-13s%s\n" |
| " status %-11s%s\n", |
| (user_logger_available) ? yes : no, |
| (user_logger_content) ? yes : no, |
| (kernel_logger_available) ? yes : no, |
| (kernel_logger_content) ? yes : no, |
| (user_logger_available && kernel_logger_available) ? "WARNING" : "ok", |
| (user_logger_content && kernel_logger_content) ? "ERROR" : "ok"); |
| |
| if (user_logger_available && kernel_logger_available) { |
| printf("WARNING: kernel & user logger; both consuming resources!!!\n"); |
| } |
| |
| EXPECT_EQ(0, user_logger_content && kernel_logger_content); |
| EXPECT_EQ(0, !user_logger_content && !kernel_logger_content); |
| } |
| |
| // BAD ROBOT |
| // Benchmark threshold are generally considered bad form unless there is |
| // is some human love applied to the continued maintenance and whether the |
| // thresholds are tuned on a per-target basis. Here we check if the values |
| // are more than double what is expected. Doubling will not prevent failure |
| // on busy or low-end systems that could have a tendency to stretch values. |
| // |
| // The primary goal of this test is to simulate a spammy app (benchmark |
| // being the worst) and check to make sure the logger can deal with it |
| // appropriately by checking all the statistics are in an expected range. |
| // |
| TEST(logd, benchmark) { |
| size_t len; |
| char *buf; |
| |
| alloc_statistics(&buf, &len); |
| bool benchmark_already_run = buf && find_benchmark_spam(buf); |
| delete [] buf; |
| |
| if (benchmark_already_run) { |
| fprintf(stderr, "WARNING: spam already present and too much history\n" |
| " false OK for prune by worst UID check\n"); |
| } |
| |
| FILE *fp; |
| |
| // Introduce some extreme spam for the worst UID filter |
| ASSERT_TRUE(NULL != (fp = popen( |
| "/data/nativetest/liblog-benchmarks/liblog-benchmarks", |
| "r"))); |
| |
| char buffer[5120]; |
| |
| static const char *benchmarks[] = { |
| "BM_log_maximum_retry ", |
| "BM_log_maximum ", |
| "BM_clock_overhead ", |
| "BM_log_overhead ", |
| "BM_log_latency ", |
| "BM_log_delay " |
| }; |
| static const unsigned int log_maximum_retry = 0; |
| static const unsigned int log_maximum = 1; |
| static const unsigned int clock_overhead = 2; |
| static const unsigned int log_overhead = 3; |
| static const unsigned int log_latency = 4; |
| static const unsigned int log_delay = 5; |
| |
| unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])]; |
| |
| memset(ns, 0, sizeof(ns)); |
| |
| while (fgets(buffer, sizeof(buffer), fp)) { |
| for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { |
| if (strncmp(benchmarks[i], buffer, strlen(benchmarks[i]))) { |
| continue; |
| } |
| sscanf(buffer, "%*s %lu %lu", &ns[i], &ns[i]); |
| fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); |
| } |
| } |
| int ret = pclose(fp); |
| |
| if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { |
| fprintf(stderr, |
| "WARNING: " |
| "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" |
| " can not perform test\n"); |
| return; |
| } |
| |
| #ifdef TARGET_USES_LOGD |
| EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user |
| #else |
| EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel |
| #endif |
| |
| #ifdef TARGET_USES_LOGD |
| EXPECT_GE(25000UL, ns[log_maximum]); // 14055 user |
| #else |
| EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel |
| #endif |
| |
| EXPECT_GE(4000UL, ns[clock_overhead]); // 2008 |
| |
| #ifdef TARGET_USES_LOGD |
| EXPECT_GE(250000UL, ns[log_overhead]); // 113219 user |
| #else |
| EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel |
| #endif |
| |
| #ifdef TARGET_USES_LOGD |
| EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space |
| #else |
| EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel |
| #endif |
| |
| #ifdef TARGET_USES_LOGD |
| EXPECT_GE(20000000UL, ns[log_delay]); // 9542541 user |
| #else |
| EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel |
| #endif |
| |
| for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) { |
| EXPECT_NE(0UL, ns[i]); |
| } |
| |
| alloc_statistics(&buf, &len); |
| |
| #ifdef TARGET_USES_LOGD |
| bool collected_statistics = !!buf; |
| EXPECT_EQ(true, collected_statistics); |
| #else |
| if (!buf) { |
| return; |
| } |
| #endif |
| |
| ASSERT_TRUE(NULL != buf); |
| |
| char *benchmark_statistics_found = find_benchmark_spam(buf); |
| ASSERT_TRUE(benchmark_statistics_found != NULL); |
| |
| // Check how effective the SPAM filter is, parse out Now size. |
| // Total Now |
| // 0/4225? 7454388/303656 31488/755 |
| // ^-- benchmark_statistics_found |
| |
| unsigned long nowSize = atol(benchmark_statistics_found); |
| |
| delete [] buf; |
| |
| ASSERT_NE(0UL, nowSize); |
| |
| int sock = socket_local_client("logd", |
| ANDROID_SOCKET_NAMESPACE_RESERVED, |
| SOCK_STREAM); |
| static const unsigned long expected_absolute_minimum_log_size = 65536UL; |
| unsigned long totalSize = expected_absolute_minimum_log_size; |
| if (sock >= 0) { |
| static const char getSize[] = { |
| 'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ', |
| LOG_ID_MAIN + '0', '\0' |
| }; |
| if (write(sock, getSize, sizeof(getSize)) > 0) { |
| char buffer[80]; |
| memset(buffer, 0, sizeof(buffer)); |
| read(sock, buffer, sizeof(buffer)); |
| totalSize = atol(buffer); |
| if (totalSize < expected_absolute_minimum_log_size) { |
| totalSize = expected_absolute_minimum_log_size; |
| } |
| } |
| close(sock); |
| } |
| // logd allows excursions to 110% of total size |
| totalSize = (totalSize * 11 ) / 10; |
| |
| // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) |
| ASSERT_GT(totalSize, nowSize * 2); |
| } |