Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 1 | /* |
| 2 | * Copyright (C) 2013-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 | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 17 | #include <ctype.h> |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 18 | #include <dirent.h> |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 19 | #include <signal.h> |
| 20 | #include <stdio.h> |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 21 | #include <stdlib.h> |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 22 | #include <string.h> |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 23 | #include <sys/types.h> |
Mark Salyzyn | c18c213 | 2016-04-01 07:52:20 -0700 | [diff] [blame] | 24 | #include <sys/wait.h> |
| 25 | |
James Hawkins | 588a2ca | 2016-02-18 14:52:46 -0800 | [diff] [blame] | 26 | #include <memory> |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 27 | |
Mark Salyzyn | 33c2625 | 2016-04-12 09:11:46 -0700 | [diff] [blame] | 28 | #include <cutils/properties.h> |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 29 | #include <gtest/gtest.h> |
| 30 | #include <log/log.h> |
| 31 | #include <log/logger.h> |
| 32 | #include <log/log_read.h> |
| 33 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 34 | #define BIG_BUFFER (5 * 1024) |
| 35 | |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 36 | // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and |
| 37 | // non-syscall libs. Since we are only using this in the emergency of |
| 38 | // a signal to stuff a terminating code into the logs, we will spin rather |
| 39 | // than try a usleep. |
| 40 | #define LOG_FAILURE_RETRY(exp) ({ \ |
| 41 | typeof (exp) _rc; \ |
| 42 | do { \ |
| 43 | _rc = (exp); \ |
| 44 | } while (((_rc == -1) \ |
| 45 | && ((errno == EINTR) \ |
| 46 | || (errno == EAGAIN))) \ |
| 47 | || (_rc == -EINTR) \ |
| 48 | || (_rc == -EAGAIN)); \ |
| 49 | _rc; }) |
| 50 | |
| 51 | static const char begin[] = "--------- beginning of "; |
| 52 | |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 53 | TEST(logcat, buckets) { |
| 54 | FILE *fp; |
| 55 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 56 | ASSERT_TRUE(NULL != (fp = popen( |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 57 | "logcat -b radio -b events -b system -b main -d 2>/dev/null", |
| 58 | "r"))); |
| 59 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 60 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 61 | |
| 62 | int ids = 0; |
| 63 | int count = 0; |
| 64 | |
| 65 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 66 | if (!strncmp(begin, buffer, sizeof(begin) - 1)) { |
| 67 | while (char *cp = strrchr(buffer, '\n')) { |
| 68 | *cp = '\0'; |
| 69 | } |
| 70 | log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1); |
| 71 | ids |= 1 << id; |
| 72 | ++count; |
| 73 | } |
| 74 | } |
| 75 | |
| 76 | pclose(fp); |
| 77 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 78 | EXPECT_EQ(15, ids); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 79 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 80 | EXPECT_EQ(4, count); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 81 | } |
| 82 | |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 83 | TEST(logcat, year) { |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 84 | |
Mark Salyzyn | ba7a9a0 | 2015-12-01 15:57:25 -0800 | [diff] [blame] | 85 | if (android_log_clockid() == CLOCK_MONOTONIC) { |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 86 | fprintf(stderr, "Skipping test, logd is monotonic time\n"); |
| 87 | return; |
| 88 | } |
| 89 | |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 90 | FILE *fp; |
| 91 | |
| 92 | char needle[32]; |
| 93 | time_t now; |
| 94 | time(&now); |
| 95 | struct tm *ptm; |
| 96 | #if !defined(_WIN32) |
| 97 | struct tm tmBuf; |
| 98 | ptm = localtime_r(&now, &tmBuf); |
| 99 | #else |
| 100 | ptm = localtime(&&now); |
| 101 | #endif |
| 102 | strftime(needle, sizeof(needle), "[ %Y-", ptm); |
| 103 | |
| 104 | ASSERT_TRUE(NULL != (fp = popen( |
| 105 | "logcat -v long -v year -b all -t 3 2>/dev/null", |
| 106 | "r"))); |
| 107 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 108 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 109 | |
| 110 | int count = 0; |
| 111 | |
| 112 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 113 | if (!strncmp(buffer, needle, strlen(needle))) { |
| 114 | ++count; |
| 115 | } |
| 116 | } |
| 117 | |
| 118 | pclose(fp); |
| 119 | |
| 120 | ASSERT_EQ(3, count); |
| 121 | } |
| 122 | |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 123 | // Return a pointer to each null terminated -v long time field. |
| 124 | char *fgetLongTime(char *buffer, size_t buflen, FILE *fp) { |
| 125 | while (fgets(buffer, buflen, fp)) { |
| 126 | char *cp = buffer; |
| 127 | if (*cp != '[') { |
| 128 | continue; |
| 129 | } |
| 130 | while (*++cp == ' ') { |
| 131 | ; |
| 132 | } |
| 133 | char *ep = cp; |
| 134 | while (isdigit(*ep)) { |
| 135 | ++ep; |
| 136 | } |
| 137 | if ((*ep != '-') && (*ep != '.')) { |
| 138 | continue; |
| 139 | } |
| 140 | // Find PID field |
| 141 | while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) { |
| 142 | ; |
| 143 | } |
| 144 | if (!ep) { |
| 145 | continue; |
| 146 | } |
| 147 | ep -= 7; |
| 148 | *ep = '\0'; |
| 149 | return cp; |
| 150 | } |
| 151 | return NULL; |
| 152 | } |
| 153 | |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 154 | TEST(logcat, tz) { |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 155 | |
Mark Salyzyn | ba7a9a0 | 2015-12-01 15:57:25 -0800 | [diff] [blame] | 156 | if (android_log_clockid() == CLOCK_MONOTONIC) { |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 157 | fprintf(stderr, "Skipping test, logd is monotonic time\n"); |
| 158 | return; |
| 159 | } |
| 160 | |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 161 | int tries = 3; // in case run too soon after system start or buffer clear |
| 162 | int count; |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 163 | |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 164 | do { |
| 165 | FILE *fp; |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 166 | |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 167 | ASSERT_TRUE(NULL != (fp = popen( |
| 168 | "logcat -v long -v America/Los_Angeles -b all -t 3 2>/dev/null", |
| 169 | "r"))); |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 170 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 171 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 172 | |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 173 | count = 0; |
| 174 | |
| 175 | while (fgetLongTime(buffer, sizeof(buffer), fp)) { |
| 176 | if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) { |
| 177 | ++count; |
| 178 | } |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 179 | } |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 180 | |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 181 | pclose(fp); |
| 182 | |
| 183 | } while ((count < 3) && --tries && (sleep(1), true)); |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 184 | |
| 185 | ASSERT_EQ(3, count); |
| 186 | } |
| 187 | |
| 188 | TEST(logcat, ntz) { |
| 189 | FILE *fp; |
| 190 | |
| 191 | ASSERT_TRUE(NULL != (fp = popen( |
| 192 | "logcat -v long -v America/Los_Angeles -v zone -b all -t 3 2>/dev/null", |
| 193 | "r"))); |
| 194 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 195 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 196 | |
| 197 | int count = 0; |
| 198 | |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 199 | while (fgetLongTime(buffer, sizeof(buffer), fp)) { |
| 200 | if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) { |
Mark Salyzyn | f28f6a9 | 2015-08-31 08:01:33 -0700 | [diff] [blame] | 201 | ++count; |
| 202 | } |
| 203 | } |
| 204 | |
| 205 | pclose(fp); |
| 206 | |
| 207 | ASSERT_EQ(0, count); |
| 208 | } |
| 209 | |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 210 | void do_tail(int num) { |
| 211 | int tries = 3; // in case run too soon after system start or buffer clear |
| 212 | int count; |
| 213 | |
| 214 | do { |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 215 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 216 | |
| 217 | snprintf(buffer, sizeof(buffer), |
| 218 | "logcat -v long -b radio -b events -b system -b main -t %d 2>/dev/null", |
| 219 | num); |
| 220 | |
| 221 | FILE *fp; |
| 222 | ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); |
| 223 | |
| 224 | count = 0; |
| 225 | |
| 226 | while (fgetLongTime(buffer, sizeof(buffer), fp)) { |
| 227 | ++count; |
| 228 | } |
| 229 | |
| 230 | pclose(fp); |
| 231 | |
| 232 | } while ((count < num) && --tries && (sleep(1), true)); |
| 233 | |
| 234 | ASSERT_EQ(num, count); |
| 235 | } |
| 236 | |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 237 | TEST(logcat, tail_3) { |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 238 | do_tail(3); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 239 | } |
| 240 | |
| 241 | TEST(logcat, tail_10) { |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 242 | do_tail(10); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 243 | } |
| 244 | |
| 245 | TEST(logcat, tail_100) { |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 246 | do_tail(100); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 247 | } |
| 248 | |
| 249 | TEST(logcat, tail_1000) { |
Mark Salyzyn | 3842b1a | 2016-04-12 11:07:26 -0700 | [diff] [blame] | 250 | do_tail(1000); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 251 | } |
| 252 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 253 | TEST(logcat, tail_time) { |
| 254 | FILE *fp; |
| 255 | |
| 256 | ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r"))); |
| 257 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 258 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 259 | char *last_timestamp = NULL; |
| 260 | char *first_timestamp = NULL; |
| 261 | int count = 0; |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 262 | |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 263 | char *cp; |
| 264 | while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) { |
| 265 | ++count; |
| 266 | if (!first_timestamp) { |
| 267 | first_timestamp = strdup(cp); |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 268 | } |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 269 | free(last_timestamp); |
| 270 | last_timestamp = strdup(cp); |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 271 | } |
| 272 | pclose(fp); |
| 273 | |
| 274 | EXPECT_EQ(10, count); |
| 275 | EXPECT_TRUE(last_timestamp != NULL); |
| 276 | EXPECT_TRUE(first_timestamp != NULL); |
| 277 | |
| 278 | snprintf(buffer, sizeof(buffer), "logcat -v long -b all -t '%s' 2>&1", |
| 279 | first_timestamp); |
| 280 | ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); |
| 281 | |
| 282 | int second_count = 0; |
| 283 | int last_timestamp_count = -1; |
| 284 | |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 285 | while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) { |
| 286 | ++second_count; |
| 287 | if (first_timestamp) { |
| 288 | // we can get a transitory *extremely* rare failure if hidden |
| 289 | // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000 |
| 290 | EXPECT_STREQ(cp, first_timestamp); |
| 291 | free(first_timestamp); |
| 292 | first_timestamp = NULL; |
| 293 | } |
| 294 | if (!strcmp(cp, last_timestamp)) { |
| 295 | last_timestamp_count = second_count; |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 296 | } |
| 297 | } |
| 298 | pclose(fp); |
| 299 | |
| 300 | free(last_timestamp); |
| 301 | last_timestamp = NULL; |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 302 | free(first_timestamp); |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 303 | |
| 304 | EXPECT_TRUE(first_timestamp == NULL); |
| 305 | EXPECT_LE(count, second_count); |
| 306 | EXPECT_LE(count, last_timestamp_count); |
| 307 | } |
| 308 | |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 309 | TEST(logcat, End_to_End) { |
| 310 | pid_t pid = getpid(); |
| 311 | |
| 312 | log_time ts(CLOCK_MONOTONIC); |
| 313 | |
| 314 | ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); |
| 315 | |
| 316 | FILE *fp; |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 317 | ASSERT_TRUE(NULL != (fp = popen( |
Mark Salyzyn | a5e2429 | 2014-09-18 10:25:38 -0700 | [diff] [blame] | 318 | "logcat -v brief -b events -t 100 2>/dev/null", |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 319 | "r"))); |
| 320 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 321 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 322 | |
| 323 | int count = 0; |
| 324 | |
| 325 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 326 | int p; |
| 327 | unsigned long long t; |
| 328 | |
| 329 | if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) |
| 330 | || (p != pid)) { |
| 331 | continue; |
| 332 | } |
| 333 | |
| 334 | log_time tx((const char *) &t); |
| 335 | if (ts == tx) { |
| 336 | ++count; |
| 337 | } |
| 338 | } |
| 339 | |
| 340 | pclose(fp); |
| 341 | |
| 342 | ASSERT_EQ(1, count); |
| 343 | } |
| 344 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 345 | int get_groups(const char *cmd) { |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 346 | FILE *fp; |
| 347 | |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 348 | // NB: crash log only available in user space |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 349 | EXPECT_TRUE(NULL != (fp = popen(cmd, "r"))); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 350 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 351 | if (fp == NULL) { |
| 352 | return 0; |
| 353 | } |
| 354 | |
| 355 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 356 | |
| 357 | int count = 0; |
| 358 | |
| 359 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 360 | int size, consumed, max, payload; |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 361 | char size_mult[3], consumed_mult[3]; |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 362 | long full_size, full_consumed; |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 363 | |
| 364 | size = consumed = max = payload = 0; |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 365 | // NB: crash log can be very small, not hit a Kb of consumed space |
| 366 | // doubly lucky we are not including it. |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 367 | if (6 != sscanf(buffer, "%*s ring buffer is %d%2s (%d%2s consumed)," |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 368 | " max entry is %db, max payload is %db", |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 369 | &size, size_mult, &consumed, consumed_mult, |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 370 | &max, &payload)) { |
| 371 | fprintf(stderr, "WARNING: Parse error: %s", buffer); |
| 372 | continue; |
| 373 | } |
| 374 | full_size = size; |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 375 | switch(size_mult[0]) { |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 376 | case 'G': |
| 377 | full_size *= 1024; |
| 378 | /* FALLTHRU */ |
| 379 | case 'M': |
| 380 | full_size *= 1024; |
| 381 | /* FALLTHRU */ |
| 382 | case 'K': |
| 383 | full_size *= 1024; |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 384 | /* FALLTHRU */ |
| 385 | case 'b': |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 386 | break; |
| 387 | } |
| 388 | full_consumed = consumed; |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 389 | switch(consumed_mult[0]) { |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 390 | case 'G': |
| 391 | full_consumed *= 1024; |
| 392 | /* FALLTHRU */ |
| 393 | case 'M': |
| 394 | full_consumed *= 1024; |
| 395 | /* FALLTHRU */ |
| 396 | case 'K': |
| 397 | full_consumed *= 1024; |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 398 | /* FALLTHRU */ |
| 399 | case 'b': |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 400 | break; |
| 401 | } |
| 402 | EXPECT_GT((full_size * 9) / 4, full_consumed); |
| 403 | EXPECT_GT(full_size, max); |
| 404 | EXPECT_GT(max, payload); |
| 405 | |
| 406 | if ((((full_size * 9) / 4) >= full_consumed) |
| 407 | && (full_size > max) |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 408 | && (max > payload)) { |
| 409 | ++count; |
| 410 | } |
| 411 | } |
| 412 | |
| 413 | pclose(fp); |
| 414 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 415 | return count; |
| 416 | } |
| 417 | |
| 418 | TEST(logcat, get_size) { |
| 419 | ASSERT_EQ(4, get_groups( |
| 420 | "logcat -v brief -b radio -b events -b system -b main -g 2>/dev/null")); |
| 421 | } |
| 422 | |
| 423 | // duplicate test for get_size, but use comma-separated list of buffers |
| 424 | TEST(logcat, multiple_buffer) { |
| 425 | ASSERT_EQ(4, get_groups( |
| 426 | "logcat -v brief -b radio,events,system,main -g 2>/dev/null")); |
| 427 | } |
| 428 | |
Mark Salyzyn | 33c2625 | 2016-04-12 09:11:46 -0700 | [diff] [blame] | 429 | // duplicate test for get_size, but use test.logcat.buffer property |
| 430 | TEST(logcat, property_expand) { |
| 431 | property_set("test.logcat.buffer", "radio,events"); |
| 432 | EXPECT_EQ(4, get_groups( |
| 433 | "logcat -v brief -b 'system,${test.logcat.buffer:-bogo},main' -g 2>/dev/null")); |
| 434 | property_set("test.logcat.buffer", ""); |
| 435 | } |
| 436 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 437 | TEST(logcat, bad_buffer) { |
| 438 | ASSERT_EQ(0, get_groups( |
| 439 | "logcat -v brief -b radio,events,bogo,system,main -g 2>/dev/null")); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 440 | } |
| 441 | |
Mark Salyzyn | b149e24 | 2014-04-30 09:39:09 -0700 | [diff] [blame] | 442 | static void caught_blocking(int /*signum*/) |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 443 | { |
| 444 | unsigned long long v = 0xDEADBEEFA55A0000ULL; |
| 445 | |
| 446 | v += getpid() & 0xFFFF; |
| 447 | |
| 448 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 449 | } |
| 450 | |
| 451 | TEST(logcat, blocking) { |
| 452 | FILE *fp; |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 453 | unsigned long long v = 0xDEADBEEFA55F0000ULL; |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 454 | |
| 455 | pid_t pid = getpid(); |
| 456 | |
| 457 | v += pid & 0xFFFF; |
| 458 | |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 459 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 460 | |
| 461 | v &= 0xFFFFFFFFFFFAFFFFULL; |
| 462 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 463 | ASSERT_TRUE(NULL != (fp = popen( |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 464 | "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" |
Mark Salyzyn | a5e2429 | 2014-09-18 10:25:38 -0700 | [diff] [blame] | 465 | " logcat -v brief -b events 2>&1", |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 466 | "r"))); |
| 467 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 468 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 469 | |
| 470 | int count = 0; |
| 471 | |
| 472 | int signals = 0; |
| 473 | |
| 474 | signal(SIGALRM, caught_blocking); |
| 475 | alarm(2); |
| 476 | while (fgets(buffer, sizeof(buffer), fp)) { |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 477 | |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 478 | if (!strncmp(buffer, "DONE", 4)) { |
| 479 | break; |
| 480 | } |
| 481 | |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 482 | ++count; |
| 483 | |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 484 | int p; |
| 485 | unsigned long long l; |
| 486 | |
| 487 | if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) |
| 488 | || (p != pid)) { |
| 489 | continue; |
| 490 | } |
| 491 | |
| 492 | if (l == v) { |
| 493 | ++signals; |
| 494 | break; |
| 495 | } |
| 496 | } |
| 497 | alarm(0); |
| 498 | signal(SIGALRM, SIG_DFL); |
| 499 | |
| 500 | // Generate SIGPIPE |
| 501 | fclose(fp); |
| 502 | caught_blocking(0); |
| 503 | |
| 504 | pclose(fp); |
| 505 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 506 | EXPECT_LE(2, count); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 507 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 508 | EXPECT_EQ(1, signals); |
Mark Salyzyn | 65772ca | 2013-12-13 11:10:11 -0800 | [diff] [blame] | 509 | } |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 510 | |
Mark Salyzyn | b149e24 | 2014-04-30 09:39:09 -0700 | [diff] [blame] | 511 | static void caught_blocking_tail(int /*signum*/) |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 512 | { |
| 513 | unsigned long long v = 0xA55ADEADBEEF0000ULL; |
| 514 | |
| 515 | v += getpid() & 0xFFFF; |
| 516 | |
| 517 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 518 | } |
| 519 | |
| 520 | TEST(logcat, blocking_tail) { |
| 521 | FILE *fp; |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 522 | unsigned long long v = 0xA55FDEADBEEF0000ULL; |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 523 | |
| 524 | pid_t pid = getpid(); |
| 525 | |
| 526 | v += pid & 0xFFFF; |
| 527 | |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 528 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 529 | |
| 530 | v &= 0xFFFAFFFFFFFFFFFFULL; |
| 531 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 532 | ASSERT_TRUE(NULL != (fp = popen( |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 533 | "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" |
Mark Salyzyn | a5e2429 | 2014-09-18 10:25:38 -0700 | [diff] [blame] | 534 | " logcat -v brief -b events -T 5 2>&1", |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 535 | "r"))); |
| 536 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 537 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 538 | |
| 539 | int count = 0; |
| 540 | |
| 541 | int signals = 0; |
| 542 | |
| 543 | signal(SIGALRM, caught_blocking_tail); |
| 544 | alarm(2); |
| 545 | while (fgets(buffer, sizeof(buffer), fp)) { |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 546 | |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 547 | if (!strncmp(buffer, "DONE", 4)) { |
| 548 | break; |
| 549 | } |
| 550 | |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 551 | ++count; |
| 552 | |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 553 | int p; |
| 554 | unsigned long long l; |
| 555 | |
| 556 | if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) |
| 557 | || (p != pid)) { |
| 558 | continue; |
| 559 | } |
| 560 | |
| 561 | if (l == v) { |
| 562 | if (count >= 5) { |
| 563 | ++signals; |
| 564 | } |
| 565 | break; |
| 566 | } |
| 567 | } |
| 568 | alarm(0); |
| 569 | signal(SIGALRM, SIG_DFL); |
| 570 | |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 571 | // Generate SIGPIPE |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 572 | fclose(fp); |
| 573 | caught_blocking_tail(0); |
| 574 | |
| 575 | pclose(fp); |
| 576 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 577 | EXPECT_LE(2, count); |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 578 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 579 | EXPECT_EQ(1, signals); |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 580 | } |
| 581 | |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 582 | TEST(logcat, logrotate) { |
| 583 | static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; |
| 584 | char buf[sizeof(form)]; |
| 585 | ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form))); |
| 586 | |
| 587 | static const char comm[] = "logcat -b radio -b events -b system -b main" |
| 588 | " -d -f %s/log.txt -n 7 -r 1"; |
| 589 | char command[sizeof(buf) + sizeof(comm)]; |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 590 | snprintf(command, sizeof(command), comm, buf); |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 591 | |
| 592 | int ret; |
| 593 | EXPECT_FALSE((ret = system(command))); |
| 594 | if (!ret) { |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 595 | snprintf(command, sizeof(command), "ls -s %s 2>/dev/null", buf); |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 596 | |
| 597 | FILE *fp; |
| 598 | EXPECT_TRUE(NULL != (fp = popen(command, "r"))); |
| 599 | if (fp) { |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 600 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 601 | int count = 0; |
| 602 | |
| 603 | while (fgets(buffer, sizeof(buffer), fp)) { |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 604 | static const char total[] = "total "; |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 605 | int num; |
| 606 | char c; |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 607 | |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 608 | if ((2 == sscanf(buffer, "%d log.tx%c", &num, &c)) && |
Mark Salyzyn | 8beb0d3 | 2015-12-15 10:39:07 -0800 | [diff] [blame] | 609 | (num <= 40)) { |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 610 | ++count; |
| 611 | } else if (strncmp(buffer, total, sizeof(total) - 1)) { |
| 612 | fprintf(stderr, "WARNING: Parse error: %s", buffer); |
| 613 | } |
| 614 | } |
| 615 | pclose(fp); |
Mark Salyzyn | b6bee33 | 2015-09-08 08:56:32 -0700 | [diff] [blame] | 616 | if ((count != 7) && (count != 8)) { |
| 617 | fprintf(stderr, "count=%d\n", count); |
| 618 | } |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 619 | EXPECT_TRUE(count == 7 || count == 8); |
| 620 | } |
| 621 | } |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 622 | snprintf(command, sizeof(command), "rm -rf %s", buf); |
Mark Salyzyn | d03caa2 | 2014-07-10 14:07:39 -0700 | [diff] [blame] | 623 | EXPECT_FALSE(system(command)); |
| 624 | } |
| 625 | |
Aristidis Papaioannou | eba7344 | 2014-10-16 22:19:55 -0700 | [diff] [blame] | 626 | TEST(logcat, logrotate_suffix) { |
| 627 | static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; |
| 628 | char tmp_out_dir[sizeof(tmp_out_dir_form)]; |
| 629 | ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); |
| 630 | |
| 631 | static const char logcat_cmd[] = "logcat -b radio -b events -b system -b main" |
| 632 | " -d -f %s/log.txt -n 10 -r 1"; |
| 633 | char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)]; |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 634 | snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir); |
Aristidis Papaioannou | eba7344 | 2014-10-16 22:19:55 -0700 | [diff] [blame] | 635 | |
| 636 | int ret; |
| 637 | EXPECT_FALSE((ret = system(command))); |
| 638 | if (!ret) { |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 639 | snprintf(command, sizeof(command), "ls %s 2>/dev/null", tmp_out_dir); |
Aristidis Papaioannou | eba7344 | 2014-10-16 22:19:55 -0700 | [diff] [blame] | 640 | |
| 641 | FILE *fp; |
| 642 | EXPECT_TRUE(NULL != (fp = popen(command, "r"))); |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 643 | char buffer[BIG_BUFFER]; |
Aristidis Papaioannou | eba7344 | 2014-10-16 22:19:55 -0700 | [diff] [blame] | 644 | int log_file_count = 0; |
| 645 | |
| 646 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 647 | static const char rotated_log_filename_prefix[] = "log.txt."; |
| 648 | static const size_t rotated_log_filename_prefix_len = |
| 649 | strlen(rotated_log_filename_prefix); |
Aristidis Papaioannou | eba7344 | 2014-10-16 22:19:55 -0700 | [diff] [blame] | 650 | static const char log_filename[] = "log.txt"; |
| 651 | |
| 652 | if (!strncmp(buffer, rotated_log_filename_prefix, rotated_log_filename_prefix_len)) { |
| 653 | // Rotated file should have form log.txt.## |
| 654 | char* rotated_log_filename_suffix = buffer + rotated_log_filename_prefix_len; |
| 655 | char* endptr; |
| 656 | const long int suffix_value = strtol(rotated_log_filename_suffix, &endptr, 10); |
| 657 | EXPECT_EQ(rotated_log_filename_suffix + 2, endptr); |
| 658 | EXPECT_LE(suffix_value, 10); |
| 659 | EXPECT_GT(suffix_value, 0); |
| 660 | ++log_file_count; |
| 661 | continue; |
| 662 | } |
| 663 | |
| 664 | if (!strncmp(buffer, log_filename, strlen(log_filename))) { |
| 665 | ++log_file_count; |
| 666 | continue; |
| 667 | } |
| 668 | |
| 669 | fprintf(stderr, "ERROR: Unexpected file: %s", buffer); |
| 670 | ADD_FAILURE(); |
| 671 | } |
| 672 | pclose(fp); |
| 673 | EXPECT_EQ(11, log_file_count); |
| 674 | } |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 675 | snprintf(command, sizeof(command), "rm -rf %s", tmp_out_dir); |
| 676 | EXPECT_FALSE(system(command)); |
| 677 | } |
| 678 | |
| 679 | TEST(logcat, logrotate_continue) { |
| 680 | static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; |
| 681 | char tmp_out_dir[sizeof(tmp_out_dir_form)]; |
| 682 | ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); |
| 683 | |
| 684 | static const char log_filename[] = "log.txt"; |
| 685 | static const char logcat_cmd[] = "logcat -b all -d -f %s/%s -n 256 -r 1024"; |
| 686 | static const char cleanup_cmd[] = "rm -rf %s"; |
| 687 | char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)]; |
| 688 | snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); |
| 689 | |
| 690 | int ret; |
| 691 | EXPECT_FALSE((ret = system(command))); |
| 692 | if (ret) { |
| 693 | snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); |
| 694 | EXPECT_FALSE(system(command)); |
| 695 | return; |
| 696 | } |
| 697 | FILE *fp; |
| 698 | snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, log_filename); |
| 699 | EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); |
| 700 | if (!fp) { |
| 701 | snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); |
| 702 | EXPECT_FALSE(system(command)); |
| 703 | return; |
| 704 | } |
| 705 | char *line = NULL; |
| 706 | char *last_line = NULL; // this line is allowed to stutter, one-line overlap |
| 707 | char *second_last_line = NULL; |
| 708 | size_t len = 0; |
| 709 | while (getline(&line, &len, fp) != -1) { |
| 710 | free(second_last_line); |
| 711 | second_last_line = last_line; |
| 712 | last_line = line; |
| 713 | line = NULL; |
| 714 | } |
| 715 | fclose(fp); |
| 716 | free(line); |
| 717 | if (second_last_line == NULL) { |
| 718 | fprintf(stderr, "No second to last line, using last, test may fail\n"); |
| 719 | second_last_line = last_line; |
| 720 | last_line = NULL; |
| 721 | } |
| 722 | free(last_line); |
| 723 | EXPECT_TRUE(NULL != second_last_line); |
| 724 | if (!second_last_line) { |
| 725 | snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); |
| 726 | EXPECT_FALSE(system(command)); |
| 727 | return; |
| 728 | } |
| 729 | // re-run the command, it should only add a few lines more content if it |
| 730 | // continues where it left off. |
| 731 | snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); |
| 732 | EXPECT_FALSE((ret = system(command))); |
| 733 | if (ret) { |
| 734 | snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); |
| 735 | EXPECT_FALSE(system(command)); |
| 736 | return; |
| 737 | } |
James Hawkins | 588a2ca | 2016-02-18 14:52:46 -0800 | [diff] [blame] | 738 | std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir), closedir); |
| 739 | EXPECT_NE(nullptr, dir); |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 740 | if (!dir) { |
| 741 | snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); |
| 742 | EXPECT_FALSE(system(command)); |
| 743 | return; |
| 744 | } |
| 745 | struct dirent *entry; |
| 746 | unsigned count = 0; |
James Hawkins | 588a2ca | 2016-02-18 14:52:46 -0800 | [diff] [blame] | 747 | while ((entry = readdir(dir.get()))) { |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 748 | if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { |
| 749 | continue; |
| 750 | } |
| 751 | snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, entry->d_name); |
| 752 | EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); |
| 753 | if (!fp) { |
| 754 | fprintf(stderr, "%s ?\n", command); |
| 755 | continue; |
| 756 | } |
| 757 | line = NULL; |
| 758 | size_t number = 0; |
| 759 | while (getline(&line, &len, fp) != -1) { |
| 760 | ++number; |
| 761 | if (!strcmp(line, second_last_line)) { |
| 762 | EXPECT_TRUE(++count <= 1); |
| 763 | fprintf(stderr, "%s(%zu):\n", entry->d_name, number); |
| 764 | } |
| 765 | } |
| 766 | fclose(fp); |
| 767 | free(line); |
| 768 | unlink(command); |
| 769 | } |
Mark Salyzyn | 9812fc4 | 2015-10-06 08:59:02 -0700 | [diff] [blame] | 770 | if (count > 1) { |
| 771 | char *brk = strpbrk(second_last_line, "\r\n"); |
| 772 | if (!brk) { |
| 773 | brk = second_last_line + strlen(second_last_line); |
| 774 | } |
| 775 | fprintf(stderr, "\"%.*s\" occured %u times\n", |
| 776 | (int)(brk - second_last_line), second_last_line, count); |
| 777 | } |
| 778 | free(second_last_line); |
| 779 | |
| 780 | snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); |
Aristidis Papaioannou | eba7344 | 2014-10-16 22:19:55 -0700 | [diff] [blame] | 781 | EXPECT_FALSE(system(command)); |
| 782 | } |
| 783 | |
Mark Salyzyn | c18c213 | 2016-04-01 07:52:20 -0700 | [diff] [blame] | 784 | TEST(logcat, logrotate_nodir) { |
| 785 | // expect logcat to error out on writing content and exit(1) for nodir |
| 786 | EXPECT_EQ(W_EXITCODE(1, 0), |
| 787 | system("logcat -b all -d" |
| 788 | " -f /das/nein/gerfingerpoken/logcat/log.txt" |
| 789 | " -n 256 -r 1024")); |
| 790 | } |
| 791 | |
| 792 | static void caught_blocking_clear(int /*signum*/) { |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 793 | unsigned long long v = 0xDEADBEEFA55C0000ULL; |
| 794 | |
| 795 | v += getpid() & 0xFFFF; |
| 796 | |
| 797 | LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); |
| 798 | } |
| 799 | |
| 800 | TEST(logcat, blocking_clear) { |
| 801 | FILE *fp; |
| 802 | unsigned long long v = 0xDEADBEEFA55C0000ULL; |
| 803 | |
| 804 | pid_t pid = getpid(); |
| 805 | |
| 806 | v += pid & 0xFFFF; |
| 807 | |
| 808 | // This test is racey; an event occurs between clear and dump. |
| 809 | // We accept that we will get a false positive, but never a false negative. |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 810 | ASSERT_TRUE(NULL != (fp = popen( |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 811 | "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&" |
| 812 | " logcat -b events -c 2>&1 ;" |
Mark Salyzyn | e7e5f1b | 2016-04-29 11:28:03 -0700 | [diff] [blame] | 813 | " logcat -b events -g 2>&1 ;" |
Mark Salyzyn | a5e2429 | 2014-09-18 10:25:38 -0700 | [diff] [blame] | 814 | " logcat -v brief -b events 2>&1", |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 815 | "r"))); |
| 816 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 817 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 818 | |
| 819 | int count = 0; |
Mark Salyzyn | e7e5f1b | 2016-04-29 11:28:03 -0700 | [diff] [blame] | 820 | int minus_g = 0; |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 821 | |
| 822 | int signals = 0; |
| 823 | |
| 824 | signal(SIGALRM, caught_blocking_clear); |
| 825 | alarm(2); |
| 826 | while (fgets(buffer, sizeof(buffer), fp)) { |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 827 | |
| 828 | if (!strncmp(buffer, "clearLog: ", 10)) { |
| 829 | fprintf(stderr, "WARNING: Test lacks permission to run :-(\n"); |
| 830 | count = signals = 1; |
| 831 | break; |
| 832 | } |
| 833 | |
| 834 | if (!strncmp(buffer, "DONE", 4)) { |
| 835 | break; |
| 836 | } |
| 837 | |
Mark Salyzyn | e7e5f1b | 2016-04-29 11:28:03 -0700 | [diff] [blame] | 838 | int size, consumed, max, payload; |
| 839 | char size_mult[3], consumed_mult[3]; |
| 840 | size = consumed = max = payload = 0; |
| 841 | if (6 == sscanf(buffer, "events: ring buffer is %d%2s (%d%2s consumed)," |
| 842 | " max entry is %db, max payload is %db", |
| 843 | &size, size_mult, &consumed, consumed_mult, |
| 844 | &max, &payload)) { |
| 845 | long full_size = size, full_consumed = consumed; |
| 846 | |
| 847 | switch(size_mult[0]) { |
| 848 | case 'G': |
| 849 | full_size *= 1024; |
| 850 | /* FALLTHRU */ |
| 851 | case 'M': |
| 852 | full_size *= 1024; |
| 853 | /* FALLTHRU */ |
| 854 | case 'K': |
| 855 | full_size *= 1024; |
| 856 | /* FALLTHRU */ |
| 857 | case 'b': |
| 858 | break; |
| 859 | } |
| 860 | switch(consumed_mult[0]) { |
| 861 | case 'G': |
| 862 | full_consumed *= 1024; |
| 863 | /* FALLTHRU */ |
| 864 | case 'M': |
| 865 | full_consumed *= 1024; |
| 866 | /* FALLTHRU */ |
| 867 | case 'K': |
| 868 | full_consumed *= 1024; |
| 869 | /* FALLTHRU */ |
| 870 | case 'b': |
| 871 | break; |
| 872 | } |
| 873 | EXPECT_GT(full_size, full_consumed); |
| 874 | EXPECT_GT(full_size, max); |
| 875 | EXPECT_GT(max, payload); |
| 876 | EXPECT_GT(max, full_consumed); |
| 877 | |
| 878 | ++minus_g; |
| 879 | continue; |
| 880 | } |
| 881 | |
Mark Salyzyn | 9b98649 | 2014-01-22 10:30:09 -0800 | [diff] [blame] | 882 | ++count; |
| 883 | |
| 884 | int p; |
| 885 | unsigned long long l; |
| 886 | |
| 887 | if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) |
| 888 | || (p != pid)) { |
| 889 | continue; |
| 890 | } |
| 891 | |
| 892 | if (l == v) { |
| 893 | if (count > 1) { |
| 894 | fprintf(stderr, "WARNING: Possible false positive\n"); |
| 895 | } |
| 896 | ++signals; |
| 897 | break; |
| 898 | } |
| 899 | } |
| 900 | alarm(0); |
| 901 | signal(SIGALRM, SIG_DFL); |
| 902 | |
| 903 | // Generate SIGPIPE |
| 904 | fclose(fp); |
| 905 | caught_blocking_clear(0); |
| 906 | |
| 907 | pclose(fp); |
| 908 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 909 | EXPECT_LE(1, count); |
Mark Salyzyn | e7e5f1b | 2016-04-29 11:28:03 -0700 | [diff] [blame] | 910 | EXPECT_EQ(1, minus_g); |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 911 | |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 912 | EXPECT_EQ(1, signals); |
Mark Salyzyn | 5d3d1f1 | 2013-12-09 13:47:00 -0800 | [diff] [blame] | 913 | } |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 914 | |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 915 | static bool get_white_black(char **list) { |
| 916 | FILE *fp; |
| 917 | |
| 918 | fp = popen("logcat -p 2>/dev/null", "r"); |
| 919 | if (fp == NULL) { |
| 920 | fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n"); |
| 921 | return false; |
| 922 | } |
| 923 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 924 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 925 | |
| 926 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 927 | char *hold = *list; |
| 928 | char *buf = buffer; |
| 929 | while (isspace(*buf)) { |
| 930 | ++buf; |
| 931 | } |
| 932 | char *end = buf + strlen(buf); |
| 933 | while (isspace(*--end) && (end >= buf)) { |
| 934 | *end = '\0'; |
| 935 | } |
| 936 | if (end < buf) { |
| 937 | continue; |
| 938 | } |
| 939 | if (hold) { |
| 940 | asprintf(list, "%s %s", hold, buf); |
| 941 | free(hold); |
| 942 | } else { |
| 943 | asprintf(list, "%s", buf); |
| 944 | } |
| 945 | } |
| 946 | pclose(fp); |
| 947 | return *list != NULL; |
| 948 | } |
| 949 | |
| 950 | static bool set_white_black(const char *list) { |
| 951 | FILE *fp; |
| 952 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 953 | char buffer[BIG_BUFFER]; |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 954 | |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 955 | snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list ? list : ""); |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 956 | fp = popen(buffer, "r"); |
| 957 | if (fp == NULL) { |
| 958 | fprintf(stderr, "ERROR: %s\n", buffer); |
| 959 | return false; |
| 960 | } |
| 961 | |
| 962 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 963 | char *buf = buffer; |
| 964 | while (isspace(*buf)) { |
| 965 | ++buf; |
| 966 | } |
| 967 | char *end = buf + strlen(buf); |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 968 | while ((end > buf) && isspace(*--end)) { |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 969 | *end = '\0'; |
| 970 | } |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 971 | if (end <= buf) { |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 972 | continue; |
| 973 | } |
| 974 | fprintf(stderr, "%s\n", buf); |
| 975 | pclose(fp); |
| 976 | return false; |
| 977 | } |
| 978 | return pclose(fp) == 0; |
| 979 | } |
| 980 | |
| 981 | TEST(logcat, white_black_adjust) { |
| 982 | char *list = NULL; |
| 983 | char *adjust = NULL; |
| 984 | |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 985 | get_white_black(&list); |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 986 | |
Mark Salyzyn | 22e287d | 2014-03-21 13:12:16 -0700 | [diff] [blame] | 987 | static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30"; |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 988 | ASSERT_EQ(true, set_white_black(adjustment)); |
| 989 | ASSERT_EQ(true, get_white_black(&adjust)); |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 990 | EXPECT_STREQ(adjustment, adjust); |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 991 | free(adjust); |
| 992 | adjust = NULL; |
| 993 | |
Mark Salyzyn | 22e287d | 2014-03-21 13:12:16 -0700 | [diff] [blame] | 994 | static const char adjustment2[] = "300/20 300/21 2000 ~1000"; |
| 995 | ASSERT_EQ(true, set_white_black(adjustment2)); |
| 996 | ASSERT_EQ(true, get_white_black(&adjust)); |
Mark Salyzyn | ef7c411 | 2014-03-11 10:35:58 -0700 | [diff] [blame] | 997 | EXPECT_STREQ(adjustment2, adjust); |
Mark Salyzyn | 22e287d | 2014-03-21 13:12:16 -0700 | [diff] [blame] | 998 | free(adjust); |
| 999 | adjust = NULL; |
| 1000 | |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 1001 | ASSERT_EQ(true, set_white_black(list)); |
Mark Salyzyn | 9879ac8 | 2014-06-03 11:24:34 -0700 | [diff] [blame] | 1002 | get_white_black(&adjust); |
| 1003 | EXPECT_STREQ(list ? list : "", adjust ? adjust : ""); |
Mark Salyzyn | 95cfc7b | 2014-03-11 11:20:56 -0700 | [diff] [blame] | 1004 | free(adjust); |
| 1005 | adjust = NULL; |
| 1006 | |
| 1007 | free(list); |
| 1008 | list = NULL; |
| 1009 | } |
Casey Dahlin | dc42a87 | 2016-03-17 16:18:55 -0700 | [diff] [blame] | 1010 | |
| 1011 | TEST(logcat, regex) { |
| 1012 | FILE *fp; |
| 1013 | int count = 0; |
| 1014 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 1015 | char buffer[BIG_BUFFER]; |
Casey Dahlin | dc42a87 | 2016-03-17 16:18:55 -0700 | [diff] [blame] | 1016 | |
| 1017 | snprintf(buffer, sizeof(buffer), "logcat --pid %d -d -e logcat_test_a+b", getpid()); |
| 1018 | |
| 1019 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_ab")); |
| 1020 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_b")); |
| 1021 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_aaaab")); |
| 1022 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_aaaa")); |
| 1023 | |
| 1024 | // Let the logs settle |
| 1025 | sleep(1); |
| 1026 | |
| 1027 | ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); |
| 1028 | |
| 1029 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 1030 | if (!strncmp(begin, buffer, sizeof(begin) - 1)) { |
| 1031 | continue; |
| 1032 | } |
| 1033 | |
| 1034 | EXPECT_TRUE(strstr(buffer, "logcat_test_") != NULL); |
| 1035 | |
| 1036 | count++; |
| 1037 | } |
| 1038 | |
| 1039 | pclose(fp); |
| 1040 | |
| 1041 | ASSERT_EQ(2, count); |
| 1042 | } |
Casey Dahlin | 6ac498d | 2016-03-17 14:04:52 -0700 | [diff] [blame] | 1043 | |
| 1044 | TEST(logcat, maxcount) { |
| 1045 | FILE *fp; |
| 1046 | int count = 0; |
| 1047 | |
Mark Salyzyn | 4517773 | 2016-04-11 14:03:48 -0700 | [diff] [blame] | 1048 | char buffer[BIG_BUFFER]; |
Casey Dahlin | 6ac498d | 2016-03-17 14:04:52 -0700 | [diff] [blame] | 1049 | |
| 1050 | snprintf(buffer, sizeof(buffer), "logcat --pid %d -d --max-count 3", getpid()); |
| 1051 | |
| 1052 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); |
| 1053 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); |
| 1054 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); |
| 1055 | LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test")); |
| 1056 | |
| 1057 | // Let the logs settle |
| 1058 | sleep(1); |
| 1059 | |
| 1060 | ASSERT_TRUE(NULL != (fp = popen(buffer, "r"))); |
| 1061 | |
| 1062 | while (fgets(buffer, sizeof(buffer), fp)) { |
| 1063 | if (!strncmp(begin, buffer, sizeof(begin) - 1)) { |
| 1064 | continue; |
| 1065 | } |
| 1066 | |
| 1067 | count++; |
| 1068 | } |
| 1069 | |
| 1070 | pclose(fp); |
| 1071 | |
| 1072 | ASSERT_EQ(3, count); |
| 1073 | } |