diff options
Diffstat (limited to 'logd/tests/logd_test.cpp')
-rw-r--r-- | logd/tests/logd_test.cpp | 959 |
1 files changed, 959 insertions, 0 deletions
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp new file mode 100644 index 000000000..10bac62f3 --- /dev/null +++ b/logd/tests/logd_test.cpp @@ -0,0 +1,959 @@ +/* + * 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 <ctype.h> +#include <fcntl.h> +#include <inttypes.h> +#include <poll.h> +#include <signal.h> +#include <stdio.h> +#include <string.h> +#include <sys/stat.h> +#include <sys/types.h> +#include <unistd.h> + +#include <string> + +#include <android-base/file.h> +#include <android-base/macros.h> +#include <android-base/stringprintf.h> +#include <cutils/sockets.h> +#include <gtest/gtest.h> +#include <private/android_filesystem_config.h> +#include <private/android_logger.h> +#ifdef __ANDROID__ +#include <selinux/selinux.h> +#endif + +#include "../LogReader.h" // pickup LOGD_SNDTIMEO + +#ifdef __ANDROID__ +static void send_to_control(char* buf, size_t len) { + 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) || (len < PAGE_SIZE)) { + 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); + } +} + +/* + * returns statistics + */ +static void my_android_logger_get_statistics(char* buf, size_t len) { + snprintf(buf, len, "getStatistics 0 1 2 3 4"); + send_to_control(buf, len); +} + +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 = nullptr; + 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: + // + // Chattiest UIDs in main log buffer: Size Pruned + // UID PACKAGE BYTES LINES + // 0 root 54164 147569 + // + char* benchmark = nullptr; + do { + static const char signature[] = "\n0 root "; + + benchmark = strstr(cp, signature); + if (!benchmark) { + break; + } + cp = benchmark + sizeof(signature); + while (isspace(*cp)) { + ++cp; + } + benchmark = cp; +#ifdef DEBUG + char* end = strstr(benchmark, "\n"); + if (end == nullptr) { + end = benchmark + strlen(benchmark); + } + fprintf(stderr, "parse for spam counter in \"%.*s\"\n", + (int)(end - benchmark), benchmark); +#endif + // content + while (isdigit(*cp)) { + ++cp; + } + while (isspace(*cp)) { + ++cp; + } + // optional +/- field? + if ((*cp == '-') || (*cp == '+')) { + while (isdigit(*++cp) || (*cp == '.') || (*cp == '%') || + (*cp == 'X')) { + ; + } + while (isspace(*cp)) { + ++cp; + } + } + // number of entries pruned + unsigned long value = 0; + while (isdigit(*cp)) { + value = value * 10ULL + *cp - '0'; + ++cp; + } + if (value > 10UL) { + break; + } + benchmark = nullptr; + } while (*cp); + return benchmark; +} +#endif + +TEST(logd, statistics) { +#ifdef __ANDROID__ + size_t len; + char* buf; + + // Drop cache so that any access problems can be discovered. + if (!android::base::WriteStringToFile("3\n", "/proc/sys/vm/drop_caches")) { + GTEST_LOG_(INFO) << "Could not open trigger dropping inode cache"; + } + + alloc_statistics(&buf, &len); + + ASSERT_TRUE(nullptr != buf); + + // 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); + + char* main_logs = strstr(cp, "\nChattiest UIDs in main "); + EXPECT_TRUE(nullptr != main_logs); + + char* radio_logs = strstr(cp, "\nChattiest UIDs in radio "); + if (!radio_logs) + GTEST_LOG_(INFO) << "Value of: nullptr != radio_logs\n" + "Actual: false\n" + "Expected: false\n"; + + char* system_logs = strstr(cp, "\nChattiest UIDs in system "); + EXPECT_TRUE(nullptr != system_logs); + + char* events_logs = strstr(cp, "\nChattiest UIDs in events "); + EXPECT_TRUE(nullptr != events_logs); + + // Check if there is any " u0_a#### " as this means packagelistparser broken + char* used_getpwuid = nullptr; + int used_getpwuid_len; + char* uid_name = cp; + static const char getpwuid_prefix[] = " u0_a"; + while ((uid_name = strstr(uid_name, getpwuid_prefix)) != nullptr) { + used_getpwuid = uid_name + 1; + uid_name += strlen(getpwuid_prefix); + while (isdigit(*uid_name)) ++uid_name; + used_getpwuid_len = uid_name - used_getpwuid; + if (isspace(*uid_name)) break; + used_getpwuid = nullptr; + } + EXPECT_TRUE(nullptr == used_getpwuid); + if (used_getpwuid) { + fprintf(stderr, "libpackagelistparser failed to pick up %.*s\n", + used_getpwuid_len, used_getpwuid); + } + + delete[] buf; +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +#ifdef __ANDROID__ +static void caught_signal(int /* signum */) { +} + +static void dump_log_msg(const char* prefix, log_msg* msg, int lid) { + std::cout << std::flush; + std::cerr << std::flush; + fflush(stdout); + fflush(stderr); + EXPECT_GE(msg->entry.hdr_size, sizeof(logger_entry)); + + fprintf(stderr, "%s: [%u] ", prefix, msg->len()); + 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); + lid = msg->entry.lid; + + 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; + case 4: + fprintf(stderr, "lid=crash "); + break; + case 5: + fprintf(stderr, "lid=security "); + break; + case 6: + fprintf(stderr, "lid=kernel "); + 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()); + if (!cp) { + static const unsigned char garbage[] = "<INVALID>"; + cp = const_cast<unsigned char*>(garbage); + len = strlen(reinterpret_cast<const char*>(garbage)); + } + 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) { + if (*cp != '\n') { + fprintf(stderr, "%c", *cp); + } else { + fprintf(stderr, "\\n"); + } + ++cp; + --len; + } + fprintf(stderr, "\""); + } else { + fprintf(stderr, "%02x", *cp); + } + ++cp; + if (--len) { + fprintf(stderr, ", "); + } + } + fprintf(stderr, "}\n"); + fflush(stderr); +} +#endif + +#ifdef __ANDROID__ +// 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( + nullptr != + (fp = popen("/data/nativetest/liblog-benchmarks/liblog-benchmarks" + " BM_log_maximum_retry" + " BM_log_maximum" + " BM_clock_overhead" + " BM_log_print_overhead" + " BM_log_latency" + " BM_log_delay", + "r"))); + + char buffer[5120]; + + static const char* benchmarks[] = { + "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ", + "BM_log_print_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_print_overhead = 3; + static const unsigned int log_latency = 4; + static const unsigned int log_delay = 5; + + unsigned long ns[arraysize(benchmarks)]; + + memset(ns, 0, sizeof(ns)); + + while (fgets(buffer, sizeof(buffer), fp)) { + for (unsigned i = 0; i < arraysize(ns); ++i) { + char* cp = strstr(buffer, benchmarks[i]); + if (!cp) { + continue; + } + sscanf(cp, "%*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; + } + + EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user + EXPECT_NE(0UL, ns[log_maximum_retry]); // failure to parse + + EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user + EXPECT_NE(0UL, ns[log_maximum]); // failure to parse + + EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 + EXPECT_NE(0UL, ns[clock_overhead]); // failure to parse + + EXPECT_GE(250000UL, ns[log_print_overhead]); // 126886 user + EXPECT_NE(0UL, ns[log_print_overhead]); // failure to parse + + EXPECT_GE(10000000UL, + ns[log_latency]); // 1453559 user space (background cgroup) + EXPECT_NE(0UL, ns[log_latency]); // failure to parse + + EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user + EXPECT_NE(0UL, ns[log_delay]); // failure to parse + + alloc_statistics(&buf, &len); + + bool collected_statistics = !!buf; + EXPECT_EQ(true, collected_statistics); + + ASSERT_TRUE(nullptr != buf); + + char* benchmark_statistics_found = find_benchmark_spam(buf); + ASSERT_TRUE(benchmark_statistics_found != nullptr); + + // Check how effective the SPAM filter is, parse out Now size. + // 0 root 54164 147569 + // ^-- benchmark_statistics_found + + unsigned long nowSpamSize = atol(benchmark_statistics_found); + + delete[] buf; + + ASSERT_NE(0UL, nowSpamSize); + + // Determine if we have the spam filter enabled + int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_STREAM); + + ASSERT_TRUE(sock >= 0); + + static const char getPruneList[] = "getPruneList"; + if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { + char buffer[80]; + memset(buffer, 0, sizeof(buffer)); + read(sock, buffer, sizeof(buffer)); + char* cp = strchr(buffer, '\n'); + if (!cp || (cp[1] != '~') || (cp[2] != '!')) { + close(sock); + fprintf(stderr, + "WARNING: " + "Logger has SPAM filtration turned off \"%s\"\n", + buffer); + return; + } + } else { + int save_errno = errno; + close(sock); + FAIL() << "Can not send " << getPruneList << " to logger -- " + << strerror(save_errno); + } + + static const unsigned long expected_absolute_minimum_log_size = 65536UL; + unsigned long totalSize = expected_absolute_minimum_log_size; + 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) { + fprintf(stderr, + "WARNING: " + "Logger had unexpected referenced size \"%s\"\n", + buffer); + 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, nowSpamSize * 2); +} +#endif + +// b/26447386 confirm fixed +void timeout_negative(const char* command) { +#ifdef __ANDROID__ + log_msg msg_wrap, msg_timeout; + bool content_wrap = false, content_timeout = false, written = false; + unsigned int alarm_wrap = 0, alarm_timeout = 0; + // A few tries to get it right just in case wrap kicks in due to + // content providers being active during the test. + int i = 3; + + while (--i) { + int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_SEQPACKET); + ASSERT_LT(0, fd); + + std::string ask(command); + + 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(3); + + size_t len = ask.length() + 1; + written = write(fd, ask.c_str(), len) == (ssize_t)len; + if (!written) { + alarm(old_alarm); + sigaction(SIGALRM, &old_sigaction, nullptr); + close(fd); + continue; + } + + // alarm triggers at 50% of the --wrap time out + content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; + + alarm_wrap = alarm(5); + + // alarm triggers at 133% of the --wrap time out + content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; + if (!content_timeout) { // make sure we hit dumpAndClose + content_timeout = + recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; + } + + if (old_alarm > 0) { + unsigned int time_spent = 3 - alarm_wrap; + if (old_alarm > time_spent + 1) { + old_alarm -= time_spent; + } else { + old_alarm = 2; + } + } + alarm_timeout = alarm(old_alarm); + sigaction(SIGALRM, &old_sigaction, nullptr); + + close(fd); + + if (content_wrap && alarm_wrap && content_timeout && alarm_timeout) { + break; + } + } + + if (content_wrap) { + dump_log_msg("wrap", &msg_wrap, -1); + } + + if (content_timeout) { + dump_log_msg("timeout", &msg_timeout, -1); + } + + EXPECT_TRUE(written); + EXPECT_TRUE(content_wrap); + EXPECT_NE(0U, alarm_wrap); + EXPECT_TRUE(content_timeout); + EXPECT_NE(0U, alarm_timeout); +#else + command = nullptr; + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +TEST(logd, timeout_no_start) { + timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6"); +} + +TEST(logd, timeout_start_epoch) { + timeout_negative( + "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000"); +} + +#ifdef ENABLE_FLAKY_TESTS +// b/26447386 refined behavior +TEST(logd, timeout) { +#ifdef __ANDROID__ + // b/33962045 This test interferes with other log reader tests that + // follow because of file descriptor socket persistence in the same + // process. So let's fork it to isolate it from giving us pain. + + pid_t pid = fork(); + + if (pid) { + siginfo_t info = {}; + ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); + ASSERT_EQ(0, info.si_status); + return; + } + + log_msg msg_wrap, msg_timeout; + bool content_wrap = false, content_timeout = false, written = false; + unsigned int alarm_wrap = 0, alarm_timeout = 0; + // A few tries to get it right just in case wrap kicks in due to + // content providers being active during the test. + int i = 5; + log_time start(android_log_clockid()); + start.tv_sec -= 30; // reach back a moderate period of time + + while (--i) { + int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_SEQPACKET); + int save_errno = errno; + if (fd < 0) { + fprintf(stderr, "failed to open /dev/socket/logdr %s\n", + strerror(save_errno)); + _exit(fd); + } + + std::string ask = android::base::StringPrintf( + "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32 + ".%09" PRIu32, + start.tv_sec, start.tv_nsec); + + 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(3); + + size_t len = ask.length() + 1; + written = write(fd, ask.c_str(), len) == (ssize_t)len; + if (!written) { + alarm(old_alarm); + sigaction(SIGALRM, &old_sigaction, nullptr); + close(fd); + continue; + } + + // alarm triggers at 50% of the --wrap time out + content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; + + alarm_wrap = alarm(5); + + // alarm triggers at 133% of the --wrap time out + content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; + if (!content_timeout) { // make sure we hit dumpAndClose + content_timeout = + recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; + } + + if (old_alarm > 0) { + unsigned int time_spent = 3 - alarm_wrap; + if (old_alarm > time_spent + 1) { + old_alarm -= time_spent; + } else { + old_alarm = 2; + } + } + alarm_timeout = alarm(old_alarm); + sigaction(SIGALRM, &old_sigaction, nullptr); + + close(fd); + + if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { + break; + } + + // modify start time in case content providers are relatively + // active _or_ inactive during the test. + if (content_timeout) { + log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); + if (msg < start) { + fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec, + msg_timeout.entry.nsec, (unsigned)start.tv_sec, + (unsigned)start.tv_nsec); + _exit(-1); + } + if (msg > start) { + start = msg; + start.tv_sec += 30; + log_time now = log_time(android_log_clockid()); + if (start > now) { + start = now; + --start.tv_sec; + } + } + } else { + start.tv_sec -= 120; // inactive, reach further back! + } + } + + if (content_wrap) { + dump_log_msg("wrap", &msg_wrap, -1); + } + + if (content_timeout) { + dump_log_msg("timeout", &msg_timeout, -1); + } + + if (content_wrap || !content_timeout) { + fprintf(stderr, "start=%" PRIu32 ".%09" PRIu32 "\n", start.tv_sec, + start.tv_nsec); + } + + EXPECT_TRUE(written); + EXPECT_FALSE(content_wrap); + EXPECT_EQ(0U, alarm_wrap); + EXPECT_TRUE(content_timeout); + EXPECT_NE(0U, alarm_timeout); + + _exit(!written + content_wrap + alarm_wrap + !content_timeout + + !alarm_timeout); +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} +#endif + +// b/27242723 confirmed fixed +TEST(logd, SNDTIMEO) { +#ifdef __ANDROID__ + static const unsigned sndtimeo = + LOGD_SNDTIMEO; // <sigh> it has to be done! + static const unsigned sleep_time = sndtimeo + 3; + static const unsigned alarm_time = sleep_time + 5; + + int fd; + + ASSERT_TRUE( + (fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_SEQPACKET)) > 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(alarm_time); + + static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources + bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask); + EXPECT_TRUE(reader_requested); + + log_msg msg; + bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0; + + EXPECT_TRUE(read_one); + if (read_one) { + dump_log_msg("user", &msg, -1); + } + + fprintf(stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo); + sleep(sleep_time); + + // flush will block if we did not trigger. if it did, last entry returns 0 + int recv_ret; + do { + recv_ret = recv(fd, msg.buf, sizeof(msg), 0); + } while (recv_ret > 0); + int save_errno = (recv_ret < 0) ? errno : 0; + + EXPECT_NE(0U, alarm(old_alarm)); + sigaction(SIGALRM, &old_sigaction, nullptr); + + EXPECT_EQ(0, recv_ret); + if (recv_ret > 0) { + dump_log_msg("user", &msg, -1); + } + EXPECT_EQ(0, save_errno); + + close(fd); +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +TEST(logd, getEventTag_list) { +#ifdef __ANDROID__ + char buffer[256]; + memset(buffer, 0, sizeof(buffer)); + snprintf(buffer, sizeof(buffer), "getEventTag name=*"); + send_to_control(buffer, sizeof(buffer)); + buffer[sizeof(buffer) - 1] = '\0'; + char* cp; + long ret = strtol(buffer, &cp, 10); + EXPECT_GT(ret, 4096); +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +TEST(logd, getEventTag_42) { +#ifdef __ANDROID__ + char buffer[256]; + memset(buffer, 0, sizeof(buffer)); + snprintf(buffer, sizeof(buffer), "getEventTag id=42"); + send_to_control(buffer, sizeof(buffer)); + buffer[sizeof(buffer) - 1] = '\0'; + char* cp; + long ret = strtol(buffer, &cp, 10); + EXPECT_GT(ret, 16); + EXPECT_TRUE(strstr(buffer, "\t(to life the universe etc|3)") != nullptr); + EXPECT_TRUE(strstr(buffer, "answer") != nullptr); +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +TEST(logd, getEventTag_newentry) { +#ifdef __ANDROID__ + char buffer[256]; + memset(buffer, 0, sizeof(buffer)); + log_time now(CLOCK_MONOTONIC); + char name[64]; + snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); + snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", + name); + send_to_control(buffer, sizeof(buffer)); + buffer[sizeof(buffer) - 1] = '\0'; + char* cp; + long ret = strtol(buffer, &cp, 10); + EXPECT_GT(ret, 16); + EXPECT_TRUE(strstr(buffer, "\t(new|1)") != nullptr); + EXPECT_TRUE(strstr(buffer, name) != nullptr); +// ToDo: also look for this in /data/misc/logd/event-log-tags and +// /dev/event-log-tags. +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +#ifdef __ANDROID__ +static inline uint32_t get4LE(const uint8_t* src) { + return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); +} + +static inline uint32_t get4LE(const char* src) { + return get4LE(reinterpret_cast<const uint8_t*>(src)); +} +#endif + +void __android_log_btwrite_multiple__helper(int count) { +#ifdef __ANDROID__ + log_time ts(CLOCK_MONOTONIC); + usleep(100); + log_time ts1(CLOCK_MONOTONIC); + + // We fork to create a unique pid for the submitted log messages + // so that we do not collide with the other _multiple_ tests. + + pid_t pid = fork(); + + if (pid == 0) { + // child + for (int i = count; i; --i) { + ASSERT_LT( + 0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); + usleep(100); + } + ASSERT_LT(0, + __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1))); + usleep(1000000); + + _exit(0); + } + + siginfo_t info = {}; + ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); + ASSERT_EQ(0, info.si_status); + + struct logger_list* logger_list; + ASSERT_TRUE(nullptr != + (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, + 0, pid))); + + int expected_count = (count < 2) ? count : 2; + int expected_chatty_count = (count <= 2) ? 0 : 1; + int expected_identical_count = (count < 2) ? 0 : (count - 2); + static const int expected_expire_count = 0; + + count = 0; + int second_count = 0; + int chatty_count = 0; + int identical_count = 0; + int expire_count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) break; + + if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) || + (log_msg.id() != LOG_ID_EVENTS)) + continue; + + char* eventData = log_msg.msg(); + if (!eventData) continue; + + uint32_t tag = get4LE(eventData); + + if ((eventData[4] == EVENT_TYPE_LONG) && + (log_msg.entry.len == (4 + 1 + 8))) { + if (tag != 0) continue; + + log_time tx(eventData + 4 + 1); + if (ts == tx) { + ++count; + } else if (ts1 == tx) { + ++second_count; + } + } else if (eventData[4] == EVENT_TYPE_STRING) { + if (tag != CHATTY_LOG_TAG) continue; + ++chatty_count; + // int len = get4LE(eventData + 4 + 1); + log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0'; + const char* cp; + if ((cp = strstr(eventData + 4 + 1 + 4, " identical "))) { + unsigned val = 0; + sscanf(cp, " identical %u lines", &val); + identical_count += val; + } else if ((cp = strstr(eventData + 4 + 1 + 4, " expire "))) { + unsigned val = 0; + sscanf(cp, " expire %u lines", &val); + expire_count += val; + } + } + } + + android_logger_list_close(logger_list); + + EXPECT_EQ(expected_count, count); + EXPECT_EQ(1, second_count); + EXPECT_EQ(expected_chatty_count, chatty_count); + EXPECT_EQ(expected_identical_count, identical_count); + EXPECT_EQ(expected_expire_count, expire_count); +#else + count = 0; + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +TEST(logd, multiple_test_1) { + __android_log_btwrite_multiple__helper(1); +} + +TEST(logd, multiple_test_2) { + __android_log_btwrite_multiple__helper(2); +} + +TEST(logd, multiple_test_3) { + __android_log_btwrite_multiple__helper(3); +} + +TEST(logd, multiple_test_10) { + __android_log_btwrite_multiple__helper(10); +} |