Mark Salyzyn | fee2b00 | 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 | |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 17 | #include <ctype.h> |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 18 | #include <fcntl.h> |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 19 | #include <inttypes.h> |
Mark Salyzyn | c05baf0 | 2014-04-18 14:49:28 -0700 | [diff] [blame] | 20 | #include <poll.h> |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 21 | #include <signal.h> |
| 22 | #include <stdio.h> |
| 23 | #include <string.h> |
Mark Salyzyn | ec9b9ad | 2017-01-03 14:00:19 -0800 | [diff] [blame] | 24 | #include <sys/stat.h> |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 25 | #include <sys/types.h> |
Mark Salyzyn | ec9b9ad | 2017-01-03 14:00:19 -0800 | [diff] [blame] | 26 | #include <unistd.h> |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 27 | |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 28 | #include <string> |
| 29 | |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 30 | #include <android-base/file.h> |
Mark Salyzyn | 071f469 | 2016-11-03 10:29:23 -0700 | [diff] [blame] | 31 | #include <android-base/macros.h> |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 32 | #include <android-base/stringprintf.h> |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 33 | #include <android-base/unique_fd.h> |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 34 | #include <cutils/sockets.h> |
Tom Cherry | 5fe06cb | 2020-05-01 15:34:47 -0700 | [diff] [blame] | 35 | #include <gtest/gtest-death-test.h> |
Mark Salyzyn | 224b86f | 2016-09-28 15:54:45 -0700 | [diff] [blame] | 36 | #include <gtest/gtest.h> |
Tom Cherry | 1e2ebe3 | 2020-04-17 09:38:55 -0700 | [diff] [blame] | 37 | #include <log/log_read.h> |
Mark Salyzyn | ec9b9ad | 2017-01-03 14:00:19 -0800 | [diff] [blame] | 38 | #include <private/android_filesystem_config.h> |
Mark Salyzyn | d4a4e42 | 2017-05-04 10:25:13 -0700 | [diff] [blame] | 39 | #include <private/android_logger.h> |
Mark Salyzyn | ec9b9ad | 2017-01-03 14:00:19 -0800 | [diff] [blame] | 40 | #ifdef __ANDROID__ |
| 41 | #include <selinux/selinux.h> |
| 42 | #endif |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 43 | |
Elliott Hughes | f74e39e | 2020-08-20 15:40:57 -0700 | [diff] [blame] | 44 | #include "LogUtils.h" // For LOGD_SNDTIMEO. |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 45 | |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 46 | using android::base::unique_fd; |
| 47 | |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 48 | #ifdef __ANDROID__ |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 49 | static void send_to_control(char* buf, size_t len) { |
| 50 | int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 51 | SOCK_STREAM); |
| 52 | if (sock >= 0) { |
| 53 | if (write(sock, buf, strlen(buf) + 1) > 0) { |
Mark Salyzyn | c05baf0 | 2014-04-18 14:49:28 -0700 | [diff] [blame] | 54 | ssize_t ret; |
| 55 | while ((ret = read(sock, buf, len)) > 0) { |
Mark Salyzyn | 777ea34 | 2016-09-21 09:24:13 -0700 | [diff] [blame] | 56 | if (((size_t)ret == len) || (len < PAGE_SIZE)) { |
Mark Salyzyn | c05baf0 | 2014-04-18 14:49:28 -0700 | [diff] [blame] | 57 | break; |
| 58 | } |
| 59 | len -= ret; |
| 60 | buf += ret; |
| 61 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 62 | struct pollfd p = {.fd = sock, .events = POLLIN, .revents = 0 }; |
Mark Salyzyn | c05baf0 | 2014-04-18 14:49:28 -0700 | [diff] [blame] | 63 | |
| 64 | ret = poll(&p, 1, 20); |
| 65 | if ((ret <= 0) || !(p.revents & POLLIN)) { |
| 66 | break; |
| 67 | } |
| 68 | } |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 69 | } |
| 70 | close(sock); |
| 71 | } |
| 72 | } |
| 73 | |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 74 | /* |
| 75 | * returns statistics |
| 76 | */ |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 77 | static void my_android_logger_get_statistics(char* buf, size_t len) { |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 78 | snprintf(buf, len, "getStatistics 0 1 2 3 4"); |
| 79 | send_to_control(buf, len); |
| 80 | } |
| 81 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 82 | static void alloc_statistics(char** buffer, size_t* length) { |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 83 | size_t len = 8192; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 84 | char* buf; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 85 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 86 | for (int retry = 32; (retry >= 0); delete[] buf, --retry) { |
| 87 | buf = new char[len]; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 88 | my_android_logger_get_statistics(buf, len); |
| 89 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 90 | buf[len - 1] = '\0'; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 91 | size_t ret = atol(buf) + 1; |
| 92 | if (ret < 4) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 93 | delete[] buf; |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 94 | buf = nullptr; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 95 | break; |
| 96 | } |
| 97 | bool check = ret <= len; |
| 98 | len = ret; |
| 99 | if (check) { |
| 100 | break; |
| 101 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 102 | len += len / 8; // allow for some slop |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 103 | } |
| 104 | *buffer = buf; |
| 105 | *length = len; |
| 106 | } |
| 107 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 108 | static char* find_benchmark_spam(char* cp) { |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 109 | // liblog_benchmarks has been run designed to SPAM. The signature of |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 110 | // a noisiest UID statistics is: |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 111 | // |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 112 | // Chattiest UIDs in main log buffer: Size Pruned |
| 113 | // UID PACKAGE BYTES LINES |
| 114 | // 0 root 54164 147569 |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 115 | // |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 116 | char* benchmark = nullptr; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 117 | do { |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 118 | static const char signature[] = "\n0 root "; |
| 119 | |
| 120 | benchmark = strstr(cp, signature); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 121 | if (!benchmark) { |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 122 | break; |
| 123 | } |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 124 | cp = benchmark + sizeof(signature); |
| 125 | while (isspace(*cp)) { |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 126 | ++cp; |
| 127 | } |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 128 | benchmark = cp; |
Mark Salyzyn | 0f2c76d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 129 | #ifdef DEBUG |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 130 | char* end = strstr(benchmark, "\n"); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 131 | if (end == nullptr) { |
Mark Salyzyn | 0f2c76d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 132 | end = benchmark + strlen(benchmark); |
| 133 | } |
| 134 | fprintf(stderr, "parse for spam counter in \"%.*s\"\n", |
| 135 | (int)(end - benchmark), benchmark); |
| 136 | #endif |
| 137 | // content |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 138 | while (isdigit(*cp)) { |
| 139 | ++cp; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 140 | } |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 141 | while (isspace(*cp)) { |
| 142 | ++cp; |
| 143 | } |
Mark Salyzyn | 0f2c76d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 144 | // optional +/- field? |
| 145 | if ((*cp == '-') || (*cp == '+')) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 146 | while (isdigit(*++cp) || (*cp == '.') || (*cp == '%') || |
| 147 | (*cp == 'X')) { |
Mark Salyzyn | 0f2c76d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 148 | ; |
| 149 | } |
| 150 | while (isspace(*cp)) { |
| 151 | ++cp; |
| 152 | } |
| 153 | } |
| 154 | // number of entries pruned |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 155 | unsigned long value = 0; |
| 156 | while (isdigit(*cp)) { |
| 157 | value = value * 10ULL + *cp - '0'; |
| 158 | ++cp; |
| 159 | } |
Mark Salyzyn | 0f2c76d | 2015-12-01 11:13:20 -0800 | [diff] [blame] | 160 | if (value > 10UL) { |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 161 | break; |
| 162 | } |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 163 | benchmark = nullptr; |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 164 | } while (*cp); |
| 165 | return benchmark; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 166 | } |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 167 | #endif |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 168 | |
Tom Cherry | 96a2a40 | 2020-07-31 11:48:33 -0700 | [diff] [blame] | 169 | #ifdef LOGD_ENABLE_FLAKY_TESTS |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 170 | TEST(logd, statistics) { |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 171 | #ifdef __ANDROID__ |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 172 | size_t len; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 173 | char* buf; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 174 | |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 175 | // Drop cache so that any access problems can be discovered. |
| 176 | if (!android::base::WriteStringToFile("3\n", "/proc/sys/vm/drop_caches")) { |
| 177 | GTEST_LOG_(INFO) << "Could not open trigger dropping inode cache"; |
| 178 | } |
| 179 | |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 180 | alloc_statistics(&buf, &len); |
| 181 | |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 182 | ASSERT_TRUE(nullptr != buf); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 183 | |
| 184 | // remove trailing FF |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 185 | char* cp = buf + len - 1; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 186 | *cp = '\0'; |
| 187 | bool truncated = *--cp != '\f'; |
| 188 | if (!truncated) { |
| 189 | *cp = '\0'; |
| 190 | } |
| 191 | |
| 192 | // squash out the byte count |
| 193 | cp = buf; |
| 194 | if (!truncated) { |
| 195 | while (isdigit(*cp) || (*cp == '\n')) { |
| 196 | ++cp; |
| 197 | } |
| 198 | } |
| 199 | |
| 200 | fprintf(stderr, "%s", cp); |
| 201 | |
| 202 | EXPECT_LT((size_t)64, strlen(cp)); |
| 203 | |
| 204 | EXPECT_EQ(0, truncated); |
| 205 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 206 | char* main_logs = strstr(cp, "\nChattiest UIDs in main "); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 207 | EXPECT_TRUE(nullptr != main_logs); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 208 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 209 | char* radio_logs = strstr(cp, "\nChattiest UIDs in radio "); |
| 210 | if (!radio_logs) |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 211 | GTEST_LOG_(INFO) << "Value of: nullptr != radio_logs\n" |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 212 | "Actual: false\n" |
| 213 | "Expected: false\n"; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 214 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 215 | char* system_logs = strstr(cp, "\nChattiest UIDs in system "); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 216 | EXPECT_TRUE(nullptr != system_logs); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 217 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 218 | char* events_logs = strstr(cp, "\nChattiest UIDs in events "); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 219 | EXPECT_TRUE(nullptr != events_logs); |
| 220 | |
| 221 | // Check if there is any " u0_a#### " as this means packagelistparser broken |
| 222 | char* used_getpwuid = nullptr; |
| 223 | int used_getpwuid_len; |
| 224 | char* uid_name = cp; |
| 225 | static const char getpwuid_prefix[] = " u0_a"; |
| 226 | while ((uid_name = strstr(uid_name, getpwuid_prefix)) != nullptr) { |
| 227 | used_getpwuid = uid_name + 1; |
| 228 | uid_name += strlen(getpwuid_prefix); |
| 229 | while (isdigit(*uid_name)) ++uid_name; |
| 230 | used_getpwuid_len = uid_name - used_getpwuid; |
| 231 | if (isspace(*uid_name)) break; |
| 232 | used_getpwuid = nullptr; |
| 233 | } |
| 234 | EXPECT_TRUE(nullptr == used_getpwuid); |
| 235 | if (used_getpwuid) { |
| 236 | fprintf(stderr, "libpackagelistparser failed to pick up %.*s\n", |
| 237 | used_getpwuid_len, used_getpwuid); |
| 238 | } |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 239 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 240 | delete[] buf; |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 241 | #else |
| 242 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 243 | #endif |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 244 | } |
Tom Cherry | 96a2a40 | 2020-07-31 11:48:33 -0700 | [diff] [blame] | 245 | #endif |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 246 | |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 247 | #ifdef __ANDROID__ |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 248 | static void caught_signal(int /* signum */) { |
| 249 | } |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 250 | |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 251 | static void dump_log_msg(const char* prefix, log_msg* msg, int lid) { |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 252 | std::cout << std::flush; |
| 253 | std::cerr << std::flush; |
| 254 | fflush(stdout); |
| 255 | fflush(stderr); |
Tom Cherry | c41fea9 | 2020-04-09 14:53:55 -0700 | [diff] [blame] | 256 | EXPECT_GE(msg->entry.hdr_size, sizeof(logger_entry)); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 257 | |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 258 | fprintf(stderr, "%s: [%u] ", prefix, msg->len()); |
| 259 | fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size); |
| 260 | fprintf(stderr, "pid=%u tid=%u %u.%09u ", msg->entry.pid, msg->entry.tid, msg->entry.sec, |
| 261 | msg->entry.nsec); |
| 262 | lid = msg->entry.lid; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 263 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 264 | switch (lid) { |
| 265 | case 0: |
| 266 | fprintf(stderr, "lid=main "); |
| 267 | break; |
| 268 | case 1: |
| 269 | fprintf(stderr, "lid=radio "); |
| 270 | break; |
| 271 | case 2: |
| 272 | fprintf(stderr, "lid=events "); |
| 273 | break; |
| 274 | case 3: |
| 275 | fprintf(stderr, "lid=system "); |
| 276 | break; |
| 277 | case 4: |
| 278 | fprintf(stderr, "lid=crash "); |
| 279 | break; |
| 280 | case 5: |
| 281 | fprintf(stderr, "lid=security "); |
| 282 | break; |
| 283 | case 6: |
| 284 | fprintf(stderr, "lid=kernel "); |
| 285 | break; |
| 286 | default: |
| 287 | if (lid >= 0) { |
| 288 | fprintf(stderr, "lid=%d ", lid); |
| 289 | } |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 290 | } |
| 291 | |
| 292 | unsigned int len = msg->entry.len; |
| 293 | fprintf(stderr, "msg[%u]={", len); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 294 | unsigned char* cp = reinterpret_cast<unsigned char*>(msg->msg()); |
Mark Salyzyn | bb60548 | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 295 | if (!cp) { |
| 296 | static const unsigned char garbage[] = "<INVALID>"; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 297 | cp = const_cast<unsigned char*>(garbage); |
| 298 | len = strlen(reinterpret_cast<const char*>(garbage)); |
Mark Salyzyn | bb60548 | 2016-08-18 14:59:41 -0700 | [diff] [blame] | 299 | } |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 300 | while (len) { |
| 301 | unsigned char* p = cp; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 302 | while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) { |
| 303 | ++p; |
| 304 | } |
| 305 | if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { |
| 306 | fprintf(stderr, "\""); |
| 307 | while (*cp) { |
Chih-Hung Hsieh | 788dd4f | 2014-09-12 16:02:28 -0700 | [diff] [blame] | 308 | if (*cp != '\n') { |
| 309 | fprintf(stderr, "%c", *cp); |
| 310 | } else { |
| 311 | fprintf(stderr, "\\n"); |
| 312 | } |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 313 | ++cp; |
| 314 | --len; |
| 315 | } |
| 316 | fprintf(stderr, "\""); |
| 317 | } else { |
| 318 | fprintf(stderr, "%02x", *cp); |
| 319 | } |
| 320 | ++cp; |
| 321 | if (--len) { |
| 322 | fprintf(stderr, ", "); |
| 323 | } |
| 324 | } |
| 325 | fprintf(stderr, "}\n"); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 326 | fflush(stderr); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 327 | } |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 328 | #endif |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 329 | |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 330 | #ifdef __ANDROID__ |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 331 | // BAD ROBOT |
| 332 | // Benchmark threshold are generally considered bad form unless there is |
| 333 | // is some human love applied to the continued maintenance and whether the |
| 334 | // thresholds are tuned on a per-target basis. Here we check if the values |
| 335 | // are more than double what is expected. Doubling will not prevent failure |
| 336 | // on busy or low-end systems that could have a tendency to stretch values. |
| 337 | // |
| 338 | // The primary goal of this test is to simulate a spammy app (benchmark |
| 339 | // being the worst) and check to make sure the logger can deal with it |
| 340 | // appropriately by checking all the statistics are in an expected range. |
| 341 | // |
| 342 | TEST(logd, benchmark) { |
| 343 | size_t len; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 344 | char* buf; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 345 | |
| 346 | alloc_statistics(&buf, &len); |
| 347 | bool benchmark_already_run = buf && find_benchmark_spam(buf); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 348 | delete[] buf; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 349 | |
| 350 | if (benchmark_already_run) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 351 | fprintf(stderr, |
| 352 | "WARNING: spam already present and too much history\n" |
| 353 | " false OK for prune by worst UID check\n"); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 354 | } |
| 355 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 356 | FILE* fp; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 357 | |
| 358 | // Introduce some extreme spam for the worst UID filter |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 359 | ASSERT_TRUE( |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 360 | nullptr != |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 361 | (fp = popen("/data/nativetest/liblog-benchmarks/liblog-benchmarks" |
| 362 | " BM_log_maximum_retry" |
| 363 | " BM_log_maximum" |
| 364 | " BM_clock_overhead" |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 365 | " BM_log_print_overhead" |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 366 | " BM_log_latency" |
| 367 | " BM_log_delay", |
| 368 | "r"))); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 369 | |
| 370 | char buffer[5120]; |
| 371 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 372 | static const char* benchmarks[] = { |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 373 | "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ", |
| 374 | "BM_log_print_overhead ", "BM_log_latency ", "BM_log_delay " |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 375 | }; |
| 376 | static const unsigned int log_maximum_retry = 0; |
| 377 | static const unsigned int log_maximum = 1; |
| 378 | static const unsigned int clock_overhead = 2; |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 379 | static const unsigned int log_print_overhead = 3; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 380 | static const unsigned int log_latency = 4; |
| 381 | static const unsigned int log_delay = 5; |
| 382 | |
Mark Salyzyn | 071f469 | 2016-11-03 10:29:23 -0700 | [diff] [blame] | 383 | unsigned long ns[arraysize(benchmarks)]; |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 384 | |
| 385 | memset(ns, 0, sizeof(ns)); |
| 386 | |
| 387 | while (fgets(buffer, sizeof(buffer), fp)) { |
Mark Salyzyn | 071f469 | 2016-11-03 10:29:23 -0700 | [diff] [blame] | 388 | for (unsigned i = 0; i < arraysize(ns); ++i) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 389 | char* cp = strstr(buffer, benchmarks[i]); |
Mark Salyzyn | 5d7984a | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 390 | if (!cp) { |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 391 | continue; |
| 392 | } |
Mark Salyzyn | 5d7984a | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 393 | sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 394 | fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]); |
| 395 | } |
| 396 | } |
| 397 | int ret = pclose(fp); |
| 398 | |
| 399 | if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) { |
| 400 | fprintf(stderr, |
| 401 | "WARNING: " |
| 402 | "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n" |
| 403 | " can not perform test\n"); |
| 404 | return; |
| 405 | } |
| 406 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 407 | EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 408 | EXPECT_NE(0UL, ns[log_maximum_retry]); // failure to parse |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 409 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 410 | EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 411 | EXPECT_NE(0UL, ns[log_maximum]); // failure to parse |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 412 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 413 | EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 414 | EXPECT_NE(0UL, ns[clock_overhead]); // failure to parse |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 415 | |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 416 | EXPECT_GE(250000UL, ns[log_print_overhead]); // 126886 user |
| 417 | EXPECT_NE(0UL, ns[log_print_overhead]); // failure to parse |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 418 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 419 | EXPECT_GE(10000000UL, |
| 420 | ns[log_latency]); // 1453559 user space (background cgroup) |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 421 | EXPECT_NE(0UL, ns[log_latency]); // failure to parse |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 422 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 423 | EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user |
Mark Salyzyn | 1491032 | 2017-03-29 09:11:19 -0700 | [diff] [blame] | 424 | EXPECT_NE(0UL, ns[log_delay]); // failure to parse |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 425 | |
| 426 | alloc_statistics(&buf, &len); |
| 427 | |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 428 | bool collected_statistics = !!buf; |
| 429 | EXPECT_EQ(true, collected_statistics); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 430 | |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 431 | ASSERT_TRUE(nullptr != buf); |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 432 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 433 | char* benchmark_statistics_found = find_benchmark_spam(buf); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 434 | ASSERT_TRUE(benchmark_statistics_found != nullptr); |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 435 | |
| 436 | // Check how effective the SPAM filter is, parse out Now size. |
Mark Salyzyn | 50d2859 | 2015-05-26 11:00:45 -0700 | [diff] [blame] | 437 | // 0 root 54164 147569 |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 438 | // ^-- benchmark_statistics_found |
| 439 | |
Mark Salyzyn | 5d7984a | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 440 | unsigned long nowSpamSize = atol(benchmark_statistics_found); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 441 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 442 | delete[] buf; |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 443 | |
Mark Salyzyn | 5d7984a | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 444 | ASSERT_NE(0UL, nowSpamSize); |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 445 | |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 446 | // Determine if we have the spam filter enabled |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 447 | int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 448 | SOCK_STREAM); |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 449 | |
| 450 | ASSERT_TRUE(sock >= 0); |
| 451 | |
| 452 | static const char getPruneList[] = "getPruneList"; |
| 453 | if (write(sock, getPruneList, sizeof(getPruneList)) > 0) { |
| 454 | char buffer[80]; |
| 455 | memset(buffer, 0, sizeof(buffer)); |
| 456 | read(sock, buffer, sizeof(buffer)); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 457 | char* cp = strchr(buffer, '\n'); |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 458 | if (!cp || (cp[1] != '~') || (cp[2] != '!')) { |
| 459 | close(sock); |
| 460 | fprintf(stderr, |
| 461 | "WARNING: " |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 462 | "Logger has SPAM filtration turned off \"%s\"\n", |
| 463 | buffer); |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 464 | return; |
| 465 | } |
| 466 | } else { |
| 467 | int save_errno = errno; |
| 468 | close(sock); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 469 | FAIL() << "Can not send " << getPruneList << " to logger -- " |
| 470 | << strerror(save_errno); |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 471 | } |
| 472 | |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 473 | static const unsigned long expected_absolute_minimum_log_size = 65536UL; |
| 474 | unsigned long totalSize = expected_absolute_minimum_log_size; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 475 | static const char getSize[] = { 'g', 'e', 't', 'L', 'o', 'g', |
| 476 | 'S', 'i', 'z', 'e', ' ', LOG_ID_MAIN + '0', |
| 477 | '\0' }; |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 478 | if (write(sock, getSize, sizeof(getSize)) > 0) { |
| 479 | char buffer[80]; |
| 480 | memset(buffer, 0, sizeof(buffer)); |
| 481 | read(sock, buffer, sizeof(buffer)); |
| 482 | totalSize = atol(buffer); |
| 483 | if (totalSize < expected_absolute_minimum_log_size) { |
| 484 | fprintf(stderr, |
| 485 | "WARNING: " |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 486 | "Logger had unexpected referenced size \"%s\"\n", |
| 487 | buffer); |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 488 | totalSize = expected_absolute_minimum_log_size; |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 489 | } |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 490 | } |
Mark Salyzyn | 2f6216a | 2014-06-13 10:09:55 -0700 | [diff] [blame] | 491 | close(sock); |
| 492 | |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 493 | // logd allows excursions to 110% of total size |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 494 | totalSize = (totalSize * 11) / 10; |
Mark Salyzyn | 0f50456 | 2014-04-09 10:02:23 -0700 | [diff] [blame] | 495 | |
| 496 | // 50% threshold for SPAM filter (<20% typical, lots of engineering margin) |
Mark Salyzyn | 5d7984a | 2014-06-06 13:38:42 -0700 | [diff] [blame] | 497 | ASSERT_GT(totalSize, nowSpamSize * 2); |
Mark Salyzyn | fee2b00 | 2014-02-28 13:44:12 -0800 | [diff] [blame] | 498 | } |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 499 | #endif |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 500 | |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 501 | // b/26447386 confirm fixed |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 502 | void timeout_negative(const char* command) { |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 503 | #ifdef __ANDROID__ |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 504 | log_msg msg_wrap, msg_timeout; |
| 505 | bool content_wrap = false, content_timeout = false, written = false; |
| 506 | unsigned int alarm_wrap = 0, alarm_timeout = 0; |
| 507 | // A few tries to get it right just in case wrap kicks in due to |
| 508 | // content providers being active during the test. |
| 509 | int i = 3; |
| 510 | |
| 511 | while (--i) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 512 | int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 513 | SOCK_SEQPACKET); |
| 514 | ASSERT_LT(0, fd); |
| 515 | |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 516 | std::string ask(command); |
| 517 | |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 518 | struct sigaction ignore, old_sigaction; |
| 519 | memset(&ignore, 0, sizeof(ignore)); |
| 520 | ignore.sa_handler = caught_signal; |
| 521 | sigemptyset(&ignore.sa_mask); |
| 522 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 523 | unsigned int old_alarm = alarm(3); |
| 524 | |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 525 | size_t len = ask.length() + 1; |
| 526 | written = write(fd, ask.c_str(), len) == (ssize_t)len; |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 527 | if (!written) { |
| 528 | alarm(old_alarm); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 529 | sigaction(SIGALRM, &old_sigaction, nullptr); |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 530 | close(fd); |
| 531 | continue; |
| 532 | } |
| 533 | |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 534 | // alarm triggers at 50% of the --wrap time out |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 535 | content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; |
| 536 | |
| 537 | alarm_wrap = alarm(5); |
| 538 | |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 539 | // alarm triggers at 133% of the --wrap time out |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 540 | content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 541 | if (!content_timeout) { // make sure we hit dumpAndClose |
| 542 | content_timeout = |
| 543 | recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 544 | } |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 545 | |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 546 | if (old_alarm > 0) { |
| 547 | unsigned int time_spent = 3 - alarm_wrap; |
| 548 | if (old_alarm > time_spent + 1) { |
| 549 | old_alarm -= time_spent; |
| 550 | } else { |
| 551 | old_alarm = 2; |
| 552 | } |
| 553 | } |
| 554 | alarm_timeout = alarm(old_alarm); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 555 | sigaction(SIGALRM, &old_sigaction, nullptr); |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 556 | |
| 557 | close(fd); |
| 558 | |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 559 | if (content_wrap && alarm_wrap && content_timeout && alarm_timeout) { |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 560 | break; |
| 561 | } |
| 562 | } |
| 563 | |
| 564 | if (content_wrap) { |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 565 | dump_log_msg("wrap", &msg_wrap, -1); |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 566 | } |
| 567 | |
| 568 | if (content_timeout) { |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 569 | dump_log_msg("timeout", &msg_timeout, -1); |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 570 | } |
| 571 | |
| 572 | EXPECT_TRUE(written); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 573 | EXPECT_TRUE(content_wrap); |
| 574 | EXPECT_NE(0U, alarm_wrap); |
| 575 | EXPECT_TRUE(content_timeout); |
| 576 | EXPECT_NE(0U, alarm_timeout); |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 577 | #else |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 578 | command = nullptr; |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 579 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 580 | #endif |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 581 | } |
| 582 | |
| 583 | TEST(logd, timeout_no_start) { |
| 584 | timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6"); |
| 585 | } |
| 586 | |
| 587 | TEST(logd, timeout_start_epoch) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 588 | timeout_negative( |
| 589 | "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000"); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 590 | } |
| 591 | |
Tom Cherry | 29ddef8 | 2020-04-29 10:15:15 -0700 | [diff] [blame] | 592 | #ifdef ENABLE_FLAKY_TESTS |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 593 | // b/26447386 refined behavior |
| 594 | TEST(logd, timeout) { |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 595 | #ifdef __ANDROID__ |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 596 | // b/33962045 This test interferes with other log reader tests that |
| 597 | // follow because of file descriptor socket persistence in the same |
| 598 | // process. So let's fork it to isolate it from giving us pain. |
| 599 | |
| 600 | pid_t pid = fork(); |
| 601 | |
| 602 | if (pid) { |
| 603 | siginfo_t info = {}; |
| 604 | ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))); |
| 605 | ASSERT_EQ(0, info.si_status); |
| 606 | return; |
| 607 | } |
| 608 | |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 609 | log_msg msg_wrap, msg_timeout; |
| 610 | bool content_wrap = false, content_timeout = false, written = false; |
| 611 | unsigned int alarm_wrap = 0, alarm_timeout = 0; |
| 612 | // A few tries to get it right just in case wrap kicks in due to |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 613 | // content providers being active during the test. |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 614 | int i = 5; |
Tom Cherry | a5ff7ae | 2020-04-08 14:36:05 -0700 | [diff] [blame] | 615 | log_time start(CLOCK_REALTIME); |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 616 | start.tv_sec -= 30; // reach back a moderate period of time |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 617 | |
| 618 | while (--i) { |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 619 | int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 620 | SOCK_SEQPACKET); |
Mark Salyzyn | 1d23fea | 2017-04-17 12:39:13 -0700 | [diff] [blame] | 621 | int save_errno = errno; |
| 622 | if (fd < 0) { |
| 623 | fprintf(stderr, "failed to open /dev/socket/logdr %s\n", |
| 624 | strerror(save_errno)); |
| 625 | _exit(fd); |
| 626 | } |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 627 | |
| 628 | std::string ask = android::base::StringPrintf( |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 629 | "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32 |
| 630 | ".%09" PRIu32, |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 631 | start.tv_sec, start.tv_nsec); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 632 | |
| 633 | struct sigaction ignore, old_sigaction; |
| 634 | memset(&ignore, 0, sizeof(ignore)); |
| 635 | ignore.sa_handler = caught_signal; |
| 636 | sigemptyset(&ignore.sa_mask); |
| 637 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 638 | unsigned int old_alarm = alarm(3); |
| 639 | |
| 640 | size_t len = ask.length() + 1; |
| 641 | written = write(fd, ask.c_str(), len) == (ssize_t)len; |
| 642 | if (!written) { |
| 643 | alarm(old_alarm); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 644 | sigaction(SIGALRM, &old_sigaction, nullptr); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 645 | close(fd); |
| 646 | continue; |
| 647 | } |
| 648 | |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 649 | // alarm triggers at 50% of the --wrap time out |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 650 | content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0; |
| 651 | |
| 652 | alarm_wrap = alarm(5); |
| 653 | |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 654 | // alarm triggers at 133% of the --wrap time out |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 655 | content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 656 | if (!content_timeout) { // make sure we hit dumpAndClose |
| 657 | content_timeout = |
| 658 | recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0; |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 659 | } |
| 660 | |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 661 | if (old_alarm > 0) { |
| 662 | unsigned int time_spent = 3 - alarm_wrap; |
| 663 | if (old_alarm > time_spent + 1) { |
| 664 | old_alarm -= time_spent; |
| 665 | } else { |
| 666 | old_alarm = 2; |
| 667 | } |
| 668 | } |
| 669 | alarm_timeout = alarm(old_alarm); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 670 | sigaction(SIGALRM, &old_sigaction, nullptr); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 671 | |
| 672 | close(fd); |
| 673 | |
| 674 | if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) { |
| 675 | break; |
| 676 | } |
| 677 | |
| 678 | // modify start time in case content providers are relatively |
| 679 | // active _or_ inactive during the test. |
| 680 | if (content_timeout) { |
| 681 | log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 682 | if (msg < start) { |
Mark Salyzyn | 1d23fea | 2017-04-17 12:39:13 -0700 | [diff] [blame] | 683 | fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec, |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 684 | msg_timeout.entry.nsec, (unsigned)start.tv_sec, |
| 685 | (unsigned)start.tv_nsec); |
Mark Salyzyn | 1d23fea | 2017-04-17 12:39:13 -0700 | [diff] [blame] | 686 | _exit(-1); |
| 687 | } |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 688 | if (msg > start) { |
| 689 | start = msg; |
| 690 | start.tv_sec += 30; |
Tom Cherry | a5ff7ae | 2020-04-08 14:36:05 -0700 | [diff] [blame] | 691 | log_time now = log_time(CLOCK_REALTIME); |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 692 | if (start > now) { |
| 693 | start = now; |
| 694 | --start.tv_sec; |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 695 | } |
| 696 | } |
| 697 | } else { |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 698 | start.tv_sec -= 120; // inactive, reach further back! |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 699 | } |
| 700 | } |
| 701 | |
| 702 | if (content_wrap) { |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 703 | dump_log_msg("wrap", &msg_wrap, -1); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 704 | } |
| 705 | |
| 706 | if (content_timeout) { |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 707 | dump_log_msg("timeout", &msg_timeout, -1); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 708 | } |
| 709 | |
| 710 | if (content_wrap || !content_timeout) { |
Alan Stokes | eae60e4 | 2017-08-25 14:13:06 +0100 | [diff] [blame] | 711 | fprintf(stderr, "start=%" PRIu32 ".%09" PRIu32 "\n", start.tv_sec, |
| 712 | start.tv_nsec); |
Mark Salyzyn | b1c45ec | 2016-01-21 10:59:25 -0800 | [diff] [blame] | 713 | } |
| 714 | |
| 715 | EXPECT_TRUE(written); |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 716 | EXPECT_FALSE(content_wrap); |
| 717 | EXPECT_EQ(0U, alarm_wrap); |
| 718 | EXPECT_TRUE(content_timeout); |
| 719 | EXPECT_NE(0U, alarm_timeout); |
Mark Salyzyn | cd1f5c8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 720 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 721 | _exit(!written + content_wrap + alarm_wrap + !content_timeout + |
| 722 | !alarm_timeout); |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 723 | #else |
| 724 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 725 | #endif |
Mark Salyzyn | f1d6f90 | 2015-12-01 08:57:53 -0800 | [diff] [blame] | 726 | } |
Tom Cherry | 29ddef8 | 2020-04-29 10:15:15 -0700 | [diff] [blame] | 727 | #endif |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 728 | |
Tom Cherry | 96a2a40 | 2020-07-31 11:48:33 -0700 | [diff] [blame] | 729 | #ifdef LOGD_ENABLE_FLAKY_TESTS |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 730 | // b/27242723 confirmed fixed |
| 731 | TEST(logd, SNDTIMEO) { |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 732 | #ifdef __ANDROID__ |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 733 | static const unsigned sndtimeo = |
| 734 | LOGD_SNDTIMEO; // <sigh> it has to be done! |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 735 | static const unsigned sleep_time = sndtimeo + 3; |
| 736 | static const unsigned alarm_time = sleep_time + 5; |
| 737 | |
| 738 | int fd; |
| 739 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 740 | ASSERT_TRUE( |
| 741 | (fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, |
| 742 | SOCK_SEQPACKET)) > 0); |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 743 | |
| 744 | struct sigaction ignore, old_sigaction; |
| 745 | memset(&ignore, 0, sizeof(ignore)); |
| 746 | ignore.sa_handler = caught_signal; |
| 747 | sigemptyset(&ignore.sa_mask); |
| 748 | sigaction(SIGALRM, &ignore, &old_sigaction); |
| 749 | unsigned int old_alarm = alarm(alarm_time); |
| 750 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 751 | static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 752 | bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask); |
| 753 | EXPECT_TRUE(reader_requested); |
| 754 | |
| 755 | log_msg msg; |
| 756 | bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0; |
| 757 | |
| 758 | EXPECT_TRUE(read_one); |
| 759 | if (read_one) { |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 760 | dump_log_msg("user", &msg, -1); |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 761 | } |
| 762 | |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 763 | fprintf(stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo); |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 764 | sleep(sleep_time); |
| 765 | |
| 766 | // flush will block if we did not trigger. if it did, last entry returns 0 |
| 767 | int recv_ret; |
| 768 | do { |
| 769 | recv_ret = recv(fd, msg.buf, sizeof(msg), 0); |
| 770 | } while (recv_ret > 0); |
| 771 | int save_errno = (recv_ret < 0) ? errno : 0; |
| 772 | |
| 773 | EXPECT_NE(0U, alarm(old_alarm)); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 774 | sigaction(SIGALRM, &old_sigaction, nullptr); |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 775 | |
| 776 | EXPECT_EQ(0, recv_ret); |
| 777 | if (recv_ret > 0) { |
Tom Cherry | 47856dd | 2019-10-15 16:53:11 -0700 | [diff] [blame] | 778 | dump_log_msg("user", &msg, -1); |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 779 | } |
| 780 | EXPECT_EQ(0, save_errno); |
| 781 | |
| 782 | close(fd); |
Mark Salyzyn | 8799bd8 | 2016-12-27 13:30:03 -0800 | [diff] [blame] | 783 | #else |
| 784 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 785 | #endif |
Mark Salyzyn | 2296d33 | 2016-02-23 08:55:43 -0800 | [diff] [blame] | 786 | } |
Tom Cherry | 96a2a40 | 2020-07-31 11:48:33 -0700 | [diff] [blame] | 787 | #endif |
Mark Salyzyn | 24a57dc | 2016-12-13 10:31:29 -0800 | [diff] [blame] | 788 | |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 789 | TEST(logd, getEventTag_list) { |
| 790 | #ifdef __ANDROID__ |
| 791 | char buffer[256]; |
| 792 | memset(buffer, 0, sizeof(buffer)); |
| 793 | snprintf(buffer, sizeof(buffer), "getEventTag name=*"); |
| 794 | send_to_control(buffer, sizeof(buffer)); |
| 795 | buffer[sizeof(buffer) - 1] = '\0'; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 796 | char* cp; |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 797 | long ret = strtol(buffer, &cp, 10); |
| 798 | EXPECT_GT(ret, 4096); |
| 799 | #else |
| 800 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 801 | #endif |
| 802 | } |
| 803 | |
Mark Salyzyn | 32f6d4b | 2017-02-21 16:19:08 -0800 | [diff] [blame] | 804 | TEST(logd, getEventTag_42) { |
| 805 | #ifdef __ANDROID__ |
| 806 | char buffer[256]; |
| 807 | memset(buffer, 0, sizeof(buffer)); |
| 808 | snprintf(buffer, sizeof(buffer), "getEventTag id=42"); |
| 809 | send_to_control(buffer, sizeof(buffer)); |
| 810 | buffer[sizeof(buffer) - 1] = '\0'; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 811 | char* cp; |
Mark Salyzyn | 32f6d4b | 2017-02-21 16:19:08 -0800 | [diff] [blame] | 812 | long ret = strtol(buffer, &cp, 10); |
| 813 | EXPECT_GT(ret, 16); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 814 | EXPECT_TRUE(strstr(buffer, "\t(to life the universe etc|3)") != nullptr); |
| 815 | EXPECT_TRUE(strstr(buffer, "answer") != nullptr); |
Mark Salyzyn | 32f6d4b | 2017-02-21 16:19:08 -0800 | [diff] [blame] | 816 | #else |
| 817 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 818 | #endif |
| 819 | } |
| 820 | |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 821 | TEST(logd, getEventTag_newentry) { |
| 822 | #ifdef __ANDROID__ |
| 823 | char buffer[256]; |
| 824 | memset(buffer, 0, sizeof(buffer)); |
| 825 | log_time now(CLOCK_MONOTONIC); |
| 826 | char name[64]; |
| 827 | snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 828 | snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", |
| 829 | name); |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 830 | send_to_control(buffer, sizeof(buffer)); |
| 831 | buffer[sizeof(buffer) - 1] = '\0'; |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 832 | char* cp; |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 833 | long ret = strtol(buffer, &cp, 10); |
| 834 | EXPECT_GT(ret, 16); |
Mark Salyzyn | 9b9ee4e | 2017-04-27 14:46:31 -0700 | [diff] [blame] | 835 | EXPECT_TRUE(strstr(buffer, "\t(new|1)") != nullptr); |
| 836 | EXPECT_TRUE(strstr(buffer, name) != nullptr); |
Mark Salyzyn | 6505953 | 2017-03-10 14:31:54 -0800 | [diff] [blame] | 837 | // ToDo: also look for this in /data/misc/logd/event-log-tags and |
| 838 | // /dev/event-log-tags. |
Mark Salyzyn | 9472b4d | 2016-09-12 14:51:54 -0700 | [diff] [blame] | 839 | #else |
| 840 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 841 | #endif |
| 842 | } |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 843 | |
| 844 | TEST(logd, no_epipe) { |
| 845 | #ifdef __ANDROID__ |
| 846 | // Actually generating SIGPIPE in logd is racy, since we need to close the socket quicker than |
Tom Cherry | 3be635a | 2020-11-03 10:01:24 -0800 | [diff] [blame] | 847 | // logd finishes writing the data to it, so we try 5 times, which should be enough to trigger |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 848 | // SIGPIPE if logd isn't ignoring SIGPIPE |
Tom Cherry | 3be635a | 2020-11-03 10:01:24 -0800 | [diff] [blame] | 849 | for (int i = 0; i < 5; ++i) { |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 850 | unique_fd sock1( |
| 851 | socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM)); |
| 852 | ASSERT_GT(sock1, 0); |
| 853 | unique_fd sock2( |
| 854 | socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM)); |
| 855 | ASSERT_GT(sock2, 0); |
| 856 | |
| 857 | std::string message = "getStatistics 0 1 2 3 4 5 6 7"; |
| 858 | |
Xiaobing Shi | 2bb97ec | 2021-08-06 11:00:45 +0800 | [diff] [blame] | 859 | ASSERT_GT(write(sock1, message.c_str(), message.length() + 1), 0); |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 860 | sock1.reset(); |
Xiaobing Shi | 2bb97ec | 2021-08-06 11:00:45 +0800 | [diff] [blame] | 861 | ASSERT_GT(write(sock2, message.c_str(), message.length() + 1), 0); |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 862 | |
| 863 | struct pollfd p = {.fd = sock2, .events = POLLIN, .revents = 0}; |
| 864 | |
Tom Cherry | 3be635a | 2020-11-03 10:01:24 -0800 | [diff] [blame] | 865 | int ret = poll(&p, 1, 1000); |
Tom Cherry | f224808 | 2020-08-07 10:27:37 -0700 | [diff] [blame] | 866 | EXPECT_EQ(ret, 1); |
| 867 | EXPECT_TRUE(p.revents & POLLIN); |
| 868 | EXPECT_FALSE(p.revents & POLL_ERR); |
| 869 | } |
| 870 | #else |
| 871 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 872 | #endif |
| 873 | } |
Tom Cherry | 5fe06cb | 2020-05-01 15:34:47 -0700 | [diff] [blame] | 874 | |
| 875 | // Only AID_ROOT, AID_SYSTEM, and AID_LOG can set log sizes. Ensure that a different user, AID_BIN, |
| 876 | // cannot set the log size. |
| 877 | TEST(logd, logging_permissions) { |
| 878 | #ifdef __ANDROID__ |
| 879 | if (getuid() != 0) { |
| 880 | GTEST_SKIP() << "This test requires root"; |
| 881 | } |
| 882 | |
| 883 | auto child_main = [] { |
| 884 | setgroups(0, nullptr); |
| 885 | setgid(AID_BIN); |
| 886 | setuid(AID_BIN); |
| 887 | |
| 888 | std::unique_ptr<logger_list, decltype(&android_logger_list_free)> logger_list{ |
| 889 | android_logger_list_alloc(0, 0, 0), &android_logger_list_free}; |
| 890 | if (!logger_list) { |
| 891 | _exit(1); |
| 892 | } |
| 893 | auto logger = android_logger_open(logger_list.get(), LOG_ID_MAIN); |
| 894 | if (!logger) { |
| 895 | _exit(2); |
| 896 | } |
| 897 | // This line should fail, so if it returns 0, we exit with an error. |
| 898 | if (android_logger_set_log_size(logger, 2 * 1024 * 1024) == 0) { |
| 899 | _exit(3); |
| 900 | } |
| 901 | _exit(EXIT_SUCCESS); |
| 902 | }; |
| 903 | |
| 904 | ASSERT_EXIT(child_main(), testing::ExitedWithCode(0), ""); |
| 905 | |
| 906 | #else |
| 907 | GTEST_LOG_(INFO) << "This test does nothing.\n"; |
| 908 | #endif |
| 909 | } |