blob: dfcca123673a3ac3b28e2dcbee211250b106cf7f [file] [log] [blame]
Mark Salyzyn65772ca2013-12-13 11:10:11 -08001/*
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 Salyzynef7c4112014-03-11 10:35:58 -070017#include <ctype.h>
Mark Salyzyn9812fc42015-10-06 08:59:02 -070018#include <dirent.h>
Mark Salyzyn65772ca2013-12-13 11:10:11 -080019#include <signal.h>
20#include <stdio.h>
Mark Salyzyn9879ac82014-06-03 11:24:34 -070021#include <stdlib.h>
Mark Salyzynef7c4112014-03-11 10:35:58 -070022#include <string.h>
Mark Salyzyn9812fc42015-10-06 08:59:02 -070023#include <sys/types.h>
Mark Salyzyn1ab87e72016-04-01 07:52:20 -070024#include <sys/wait.h>
Mark Salyzynef7c4112014-03-11 10:35:58 -070025
Mark Salyzyn65772ca2013-12-13 11:10:11 -080026#include <gtest/gtest.h>
27#include <log/log.h>
28#include <log/logger.h>
29#include <log/log_read.h>
30
31// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
32// non-syscall libs. Since we are only using this in the emergency of
33// a signal to stuff a terminating code into the logs, we will spin rather
34// than try a usleep.
35#define LOG_FAILURE_RETRY(exp) ({ \
36 typeof (exp) _rc; \
37 do { \
38 _rc = (exp); \
39 } while (((_rc == -1) \
40 && ((errno == EINTR) \
41 || (errno == EAGAIN))) \
42 || (_rc == -EINTR) \
43 || (_rc == -EAGAIN)); \
44 _rc; })
45
46static const char begin[] = "--------- beginning of ";
47
Mark Salyzyn65772ca2013-12-13 11:10:11 -080048TEST(logcat, buckets) {
49 FILE *fp;
50
Mark Salyzynef7c4112014-03-11 10:35:58 -070051 ASSERT_TRUE(NULL != (fp = popen(
Mark Salyzyn65772ca2013-12-13 11:10:11 -080052 "logcat -b radio -b events -b system -b main -d 2>/dev/null",
53 "r")));
54
55 char buffer[5120];
56
57 int ids = 0;
58 int count = 0;
59
60 while (fgets(buffer, sizeof(buffer), fp)) {
61 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
62 while (char *cp = strrchr(buffer, '\n')) {
63 *cp = '\0';
64 }
65 log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1);
66 ids |= 1 << id;
67 ++count;
68 }
69 }
70
71 pclose(fp);
72
Mark Salyzynef7c4112014-03-11 10:35:58 -070073 EXPECT_EQ(15, ids);
Mark Salyzyn65772ca2013-12-13 11:10:11 -080074
Mark Salyzynef7c4112014-03-11 10:35:58 -070075 EXPECT_EQ(4, count);
Mark Salyzyn65772ca2013-12-13 11:10:11 -080076}
77
Mark Salyzynf28f6a92015-08-31 08:01:33 -070078TEST(logcat, year) {
Mark Salyzynb6bee332015-09-08 08:56:32 -070079
Mark Salyzynba7a9a02015-12-01 15:57:25 -080080 if (android_log_clockid() == CLOCK_MONOTONIC) {
Mark Salyzynb6bee332015-09-08 08:56:32 -070081 fprintf(stderr, "Skipping test, logd is monotonic time\n");
82 return;
83 }
84
Mark Salyzynf28f6a92015-08-31 08:01:33 -070085 FILE *fp;
86
87 char needle[32];
88 time_t now;
89 time(&now);
90 struct tm *ptm;
91#if !defined(_WIN32)
92 struct tm tmBuf;
93 ptm = localtime_r(&now, &tmBuf);
94#else
95 ptm = localtime(&&now);
96#endif
97 strftime(needle, sizeof(needle), "[ %Y-", ptm);
98
99 ASSERT_TRUE(NULL != (fp = popen(
100 "logcat -v long -v year -b all -t 3 2>/dev/null",
101 "r")));
102
103 char buffer[5120];
104
105 int count = 0;
106
107 while (fgets(buffer, sizeof(buffer), fp)) {
108 if (!strncmp(buffer, needle, strlen(needle))) {
109 ++count;
110 }
111 }
112
113 pclose(fp);
114
115 ASSERT_EQ(3, count);
116}
117
Mark Salyzynb6bee332015-09-08 08:56:32 -0700118// Return a pointer to each null terminated -v long time field.
119char *fgetLongTime(char *buffer, size_t buflen, FILE *fp) {
120 while (fgets(buffer, buflen, fp)) {
121 char *cp = buffer;
122 if (*cp != '[') {
123 continue;
124 }
125 while (*++cp == ' ') {
126 ;
127 }
128 char *ep = cp;
129 while (isdigit(*ep)) {
130 ++ep;
131 }
132 if ((*ep != '-') && (*ep != '.')) {
133 continue;
134 }
135 // Find PID field
136 while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) {
137 ;
138 }
139 if (!ep) {
140 continue;
141 }
142 ep -= 7;
143 *ep = '\0';
144 return cp;
145 }
146 return NULL;
147}
148
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700149TEST(logcat, tz) {
Mark Salyzynb6bee332015-09-08 08:56:32 -0700150
Mark Salyzynba7a9a02015-12-01 15:57:25 -0800151 if (android_log_clockid() == CLOCK_MONOTONIC) {
Mark Salyzynb6bee332015-09-08 08:56:32 -0700152 fprintf(stderr, "Skipping test, logd is monotonic time\n");
153 return;
154 }
155
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700156 int tries = 3; // in case run too soon after system start or buffer clear
157 int count;
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700158
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700159 do {
160 FILE *fp;
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700161
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700162 ASSERT_TRUE(NULL != (fp = popen(
163 "logcat -v long -v America/Los_Angeles -b all -t 3 2>/dev/null",
164 "r")));
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700165
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700166 char buffer[5120];
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700167
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700168 count = 0;
169
170 while (fgetLongTime(buffer, sizeof(buffer), fp)) {
171 if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
172 ++count;
173 }
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700174 }
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700175
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700176 pclose(fp);
177
178 } while ((count < 3) && --tries && (sleep(1), true));
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700179
180 ASSERT_EQ(3, count);
181}
182
183TEST(logcat, ntz) {
184 FILE *fp;
185
186 ASSERT_TRUE(NULL != (fp = popen(
187 "logcat -v long -v America/Los_Angeles -v zone -b all -t 3 2>/dev/null",
188 "r")));
189
190 char buffer[5120];
191
192 int count = 0;
193
Mark Salyzynb6bee332015-09-08 08:56:32 -0700194 while (fgetLongTime(buffer, sizeof(buffer), fp)) {
195 if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
Mark Salyzynf28f6a92015-08-31 08:01:33 -0700196 ++count;
197 }
198 }
199
200 pclose(fp);
201
202 ASSERT_EQ(0, count);
203}
204
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700205void do_tail(int num) {
206 int tries = 3; // in case run too soon after system start or buffer clear
207 int count;
208
209 do {
210 char buffer[5120];
211
212 snprintf(buffer, sizeof(buffer),
213 "logcat -v long -b radio -b events -b system -b main -t %d 2>/dev/null",
214 num);
215
216 FILE *fp;
217 ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
218
219 count = 0;
220
221 while (fgetLongTime(buffer, sizeof(buffer), fp)) {
222 ++count;
223 }
224
225 pclose(fp);
226
227 } while ((count < num) && --tries && (sleep(1), true));
228
229 ASSERT_EQ(num, count);
230}
231
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800232TEST(logcat, tail_3) {
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700233 do_tail(3);
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800234}
235
236TEST(logcat, tail_10) {
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700237 do_tail(10);
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800238}
239
240TEST(logcat, tail_100) {
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700241 do_tail(100);
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800242}
243
244TEST(logcat, tail_1000) {
Mark Salyzyn3c535de2016-04-12 11:07:26 -0700245 do_tail(1000);
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800246}
247
Mark Salyzynef7c4112014-03-11 10:35:58 -0700248TEST(logcat, tail_time) {
249 FILE *fp;
250
251 ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r")));
252
253 char buffer[5120];
254 char *last_timestamp = NULL;
255 char *first_timestamp = NULL;
256 int count = 0;
Mark Salyzynef7c4112014-03-11 10:35:58 -0700257
Mark Salyzynb6bee332015-09-08 08:56:32 -0700258 char *cp;
259 while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
260 ++count;
261 if (!first_timestamp) {
262 first_timestamp = strdup(cp);
Mark Salyzynef7c4112014-03-11 10:35:58 -0700263 }
Mark Salyzynb6bee332015-09-08 08:56:32 -0700264 free(last_timestamp);
265 last_timestamp = strdup(cp);
Mark Salyzynef7c4112014-03-11 10:35:58 -0700266 }
267 pclose(fp);
268
269 EXPECT_EQ(10, count);
270 EXPECT_TRUE(last_timestamp != NULL);
271 EXPECT_TRUE(first_timestamp != NULL);
272
273 snprintf(buffer, sizeof(buffer), "logcat -v long -b all -t '%s' 2>&1",
274 first_timestamp);
275 ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
276
277 int second_count = 0;
278 int last_timestamp_count = -1;
279
Mark Salyzynb6bee332015-09-08 08:56:32 -0700280 while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
281 ++second_count;
282 if (first_timestamp) {
283 // we can get a transitory *extremely* rare failure if hidden
284 // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000
285 EXPECT_STREQ(cp, first_timestamp);
286 free(first_timestamp);
287 first_timestamp = NULL;
288 }
289 if (!strcmp(cp, last_timestamp)) {
290 last_timestamp_count = second_count;
Mark Salyzynef7c4112014-03-11 10:35:58 -0700291 }
292 }
293 pclose(fp);
294
295 free(last_timestamp);
296 last_timestamp = NULL;
Mark Salyzynb6bee332015-09-08 08:56:32 -0700297 free(first_timestamp);
Mark Salyzynef7c4112014-03-11 10:35:58 -0700298
299 EXPECT_TRUE(first_timestamp == NULL);
300 EXPECT_LE(count, second_count);
301 EXPECT_LE(count, last_timestamp_count);
302}
303
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800304TEST(logcat, End_to_End) {
305 pid_t pid = getpid();
306
307 log_time ts(CLOCK_MONOTONIC);
308
309 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
310
311 FILE *fp;
Mark Salyzynef7c4112014-03-11 10:35:58 -0700312 ASSERT_TRUE(NULL != (fp = popen(
Mark Salyzyna5e24292014-09-18 10:25:38 -0700313 "logcat -v brief -b events -t 100 2>/dev/null",
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800314 "r")));
315
316 char buffer[5120];
317
318 int count = 0;
319
320 while (fgets(buffer, sizeof(buffer), fp)) {
321 int p;
322 unsigned long long t;
323
324 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t))
325 || (p != pid)) {
326 continue;
327 }
328
329 log_time tx((const char *) &t);
330 if (ts == tx) {
331 ++count;
332 }
333 }
334
335 pclose(fp);
336
337 ASSERT_EQ(1, count);
338}
339
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700340TEST(logcat, get_size) {
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800341 FILE *fp;
342
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700343 // NB: crash log only available in user space
Mark Salyzynef7c4112014-03-11 10:35:58 -0700344 ASSERT_TRUE(NULL != (fp = popen(
Mark Salyzyna5e24292014-09-18 10:25:38 -0700345 "logcat -v brief -b radio -b events -b system -b main -g 2>/dev/null",
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800346 "r")));
347
348 char buffer[5120];
349
350 int count = 0;
351
352 while (fgets(buffer, sizeof(buffer), fp)) {
353 int size, consumed, max, payload;
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700354 char size_mult[3], consumed_mult[3];
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700355 long full_size, full_consumed;
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800356
357 size = consumed = max = payload = 0;
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700358 // NB: crash log can be very small, not hit a Kb of consumed space
359 // doubly lucky we are not including it.
Mark Salyzynd03caa22014-07-10 14:07:39 -0700360 if (6 != sscanf(buffer, "%*s ring buffer is %d%2s (%d%2s consumed),"
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700361 " max entry is %db, max payload is %db",
Mark Salyzynd03caa22014-07-10 14:07:39 -0700362 &size, size_mult, &consumed, consumed_mult,
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700363 &max, &payload)) {
364 fprintf(stderr, "WARNING: Parse error: %s", buffer);
365 continue;
366 }
367 full_size = size;
Mark Salyzynd03caa22014-07-10 14:07:39 -0700368 switch(size_mult[0]) {
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700369 case 'G':
370 full_size *= 1024;
371 /* FALLTHRU */
372 case 'M':
373 full_size *= 1024;
374 /* FALLTHRU */
375 case 'K':
376 full_size *= 1024;
Mark Salyzynd03caa22014-07-10 14:07:39 -0700377 /* FALLTHRU */
378 case 'b':
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700379 break;
380 }
381 full_consumed = consumed;
Mark Salyzynd03caa22014-07-10 14:07:39 -0700382 switch(consumed_mult[0]) {
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700383 case 'G':
384 full_consumed *= 1024;
385 /* FALLTHRU */
386 case 'M':
387 full_consumed *= 1024;
388 /* FALLTHRU */
389 case 'K':
390 full_consumed *= 1024;
Mark Salyzynd03caa22014-07-10 14:07:39 -0700391 /* FALLTHRU */
392 case 'b':
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700393 break;
394 }
395 EXPECT_GT((full_size * 9) / 4, full_consumed);
396 EXPECT_GT(full_size, max);
397 EXPECT_GT(max, payload);
398
399 if ((((full_size * 9) / 4) >= full_consumed)
400 && (full_size > max)
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800401 && (max > payload)) {
402 ++count;
403 }
404 }
405
406 pclose(fp);
407
408 ASSERT_EQ(4, count);
409}
410
Mark Salyzynb149e242014-04-30 09:39:09 -0700411static void caught_blocking(int /*signum*/)
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800412{
413 unsigned long long v = 0xDEADBEEFA55A0000ULL;
414
415 v += getpid() & 0xFFFF;
416
417 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
418}
419
420TEST(logcat, blocking) {
421 FILE *fp;
Mark Salyzyn9b986492014-01-22 10:30:09 -0800422 unsigned long long v = 0xDEADBEEFA55F0000ULL;
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800423
424 pid_t pid = getpid();
425
426 v += pid & 0xFFFF;
427
Mark Salyzyn9b986492014-01-22 10:30:09 -0800428 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
429
430 v &= 0xFFFFFFFFFFFAFFFFULL;
431
Mark Salyzynef7c4112014-03-11 10:35:58 -0700432 ASSERT_TRUE(NULL != (fp = popen(
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800433 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
Mark Salyzyna5e24292014-09-18 10:25:38 -0700434 " logcat -v brief -b events 2>&1",
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800435 "r")));
436
437 char buffer[5120];
438
439 int count = 0;
440
441 int signals = 0;
442
443 signal(SIGALRM, caught_blocking);
444 alarm(2);
445 while (fgets(buffer, sizeof(buffer), fp)) {
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800446
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800447 if (!strncmp(buffer, "DONE", 4)) {
448 break;
449 }
450
Mark Salyzyn9b986492014-01-22 10:30:09 -0800451 ++count;
452
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800453 int p;
454 unsigned long long l;
455
456 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
457 || (p != pid)) {
458 continue;
459 }
460
461 if (l == v) {
462 ++signals;
463 break;
464 }
465 }
466 alarm(0);
467 signal(SIGALRM, SIG_DFL);
468
469 // Generate SIGPIPE
470 fclose(fp);
471 caught_blocking(0);
472
473 pclose(fp);
474
Mark Salyzynef7c4112014-03-11 10:35:58 -0700475 EXPECT_LE(2, count);
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800476
Mark Salyzynef7c4112014-03-11 10:35:58 -0700477 EXPECT_EQ(1, signals);
Mark Salyzyn65772ca2013-12-13 11:10:11 -0800478}
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800479
Mark Salyzynb149e242014-04-30 09:39:09 -0700480static void caught_blocking_tail(int /*signum*/)
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800481{
482 unsigned long long v = 0xA55ADEADBEEF0000ULL;
483
484 v += getpid() & 0xFFFF;
485
486 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
487}
488
489TEST(logcat, blocking_tail) {
490 FILE *fp;
Mark Salyzyn9b986492014-01-22 10:30:09 -0800491 unsigned long long v = 0xA55FDEADBEEF0000ULL;
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800492
493 pid_t pid = getpid();
494
495 v += pid & 0xFFFF;
496
Mark Salyzyn9b986492014-01-22 10:30:09 -0800497 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
498
499 v &= 0xFFFAFFFFFFFFFFFFULL;
500
Mark Salyzynef7c4112014-03-11 10:35:58 -0700501 ASSERT_TRUE(NULL != (fp = popen(
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800502 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
Mark Salyzyna5e24292014-09-18 10:25:38 -0700503 " logcat -v brief -b events -T 5 2>&1",
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800504 "r")));
505
506 char buffer[5120];
507
508 int count = 0;
509
510 int signals = 0;
511
512 signal(SIGALRM, caught_blocking_tail);
513 alarm(2);
514 while (fgets(buffer, sizeof(buffer), fp)) {
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800515
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800516 if (!strncmp(buffer, "DONE", 4)) {
517 break;
518 }
519
Mark Salyzyn9b986492014-01-22 10:30:09 -0800520 ++count;
521
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800522 int p;
523 unsigned long long l;
524
525 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
526 || (p != pid)) {
527 continue;
528 }
529
530 if (l == v) {
531 if (count >= 5) {
532 ++signals;
533 }
534 break;
535 }
536 }
537 alarm(0);
538 signal(SIGALRM, SIG_DFL);
539
Mark Salyzyn9b986492014-01-22 10:30:09 -0800540 // Generate SIGPIPE
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800541 fclose(fp);
542 caught_blocking_tail(0);
543
544 pclose(fp);
545
Mark Salyzynef7c4112014-03-11 10:35:58 -0700546 EXPECT_LE(2, count);
Mark Salyzyn9b986492014-01-22 10:30:09 -0800547
Mark Salyzynef7c4112014-03-11 10:35:58 -0700548 EXPECT_EQ(1, signals);
Mark Salyzyn9b986492014-01-22 10:30:09 -0800549}
550
Mark Salyzynd03caa22014-07-10 14:07:39 -0700551TEST(logcat, logrotate) {
552 static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX";
553 char buf[sizeof(form)];
554 ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form)));
555
556 static const char comm[] = "logcat -b radio -b events -b system -b main"
557 " -d -f %s/log.txt -n 7 -r 1";
558 char command[sizeof(buf) + sizeof(comm)];
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700559 snprintf(command, sizeof(command), comm, buf);
Mark Salyzynd03caa22014-07-10 14:07:39 -0700560
561 int ret;
562 EXPECT_FALSE((ret = system(command)));
563 if (!ret) {
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700564 snprintf(command, sizeof(command), "ls -s %s 2>/dev/null", buf);
Mark Salyzynd03caa22014-07-10 14:07:39 -0700565
566 FILE *fp;
567 EXPECT_TRUE(NULL != (fp = popen(command, "r")));
568 if (fp) {
569 char buffer[5120];
570 int count = 0;
571
572 while (fgets(buffer, sizeof(buffer), fp)) {
Mark Salyzynd03caa22014-07-10 14:07:39 -0700573 static const char total[] = "total ";
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700574 int num;
575 char c;
Mark Salyzynd03caa22014-07-10 14:07:39 -0700576
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700577 if ((2 == sscanf(buffer, "%d log.tx%c", &num, &c)) &&
Mark Salyzyn8beb0d32015-12-15 10:39:07 -0800578 (num <= 40)) {
Mark Salyzynd03caa22014-07-10 14:07:39 -0700579 ++count;
580 } else if (strncmp(buffer, total, sizeof(total) - 1)) {
581 fprintf(stderr, "WARNING: Parse error: %s", buffer);
582 }
583 }
584 pclose(fp);
Mark Salyzynb6bee332015-09-08 08:56:32 -0700585 if ((count != 7) && (count != 8)) {
586 fprintf(stderr, "count=%d\n", count);
587 }
Mark Salyzynd03caa22014-07-10 14:07:39 -0700588 EXPECT_TRUE(count == 7 || count == 8);
589 }
590 }
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700591 snprintf(command, sizeof(command), "rm -rf %s", buf);
Mark Salyzynd03caa22014-07-10 14:07:39 -0700592 EXPECT_FALSE(system(command));
593}
594
Aristidis Papaioannoueba73442014-10-16 22:19:55 -0700595TEST(logcat, logrotate_suffix) {
596 static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX";
597 char tmp_out_dir[sizeof(tmp_out_dir_form)];
598 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));
599
600 static const char logcat_cmd[] = "logcat -b radio -b events -b system -b main"
601 " -d -f %s/log.txt -n 10 -r 1";
602 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)];
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700603 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir);
Aristidis Papaioannoueba73442014-10-16 22:19:55 -0700604
605 int ret;
606 EXPECT_FALSE((ret = system(command)));
607 if (!ret) {
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700608 snprintf(command, sizeof(command), "ls %s 2>/dev/null", tmp_out_dir);
Aristidis Papaioannoueba73442014-10-16 22:19:55 -0700609
610 FILE *fp;
611 EXPECT_TRUE(NULL != (fp = popen(command, "r")));
612 char buffer[5120];
613 int log_file_count = 0;
614
615 while (fgets(buffer, sizeof(buffer), fp)) {
616 static const char rotated_log_filename_prefix[] = "log.txt.";
617 static const size_t rotated_log_filename_prefix_len =
618 strlen(rotated_log_filename_prefix);
Aristidis Papaioannoueba73442014-10-16 22:19:55 -0700619 static const char log_filename[] = "log.txt";
620
621 if (!strncmp(buffer, rotated_log_filename_prefix, rotated_log_filename_prefix_len)) {
622 // Rotated file should have form log.txt.##
623 char* rotated_log_filename_suffix = buffer + rotated_log_filename_prefix_len;
624 char* endptr;
625 const long int suffix_value = strtol(rotated_log_filename_suffix, &endptr, 10);
626 EXPECT_EQ(rotated_log_filename_suffix + 2, endptr);
627 EXPECT_LE(suffix_value, 10);
628 EXPECT_GT(suffix_value, 0);
629 ++log_file_count;
630 continue;
631 }
632
633 if (!strncmp(buffer, log_filename, strlen(log_filename))) {
634 ++log_file_count;
635 continue;
636 }
637
638 fprintf(stderr, "ERROR: Unexpected file: %s", buffer);
639 ADD_FAILURE();
640 }
641 pclose(fp);
642 EXPECT_EQ(11, log_file_count);
643 }
Mark Salyzyn9812fc42015-10-06 08:59:02 -0700644 snprintf(command, sizeof(command), "rm -rf %s", tmp_out_dir);
645 EXPECT_FALSE(system(command));
646}
647
648TEST(logcat, logrotate_continue) {
649 static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX";
650 char tmp_out_dir[sizeof(tmp_out_dir_form)];
651 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));
652
653 static const char log_filename[] = "log.txt";
654 static const char logcat_cmd[] = "logcat -b all -d -f %s/%s -n 256 -r 1024";
655 static const char cleanup_cmd[] = "rm -rf %s";
656 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)];
657 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);
658
659 int ret;
660 EXPECT_FALSE((ret = system(command)));
661 if (ret) {
662 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
663 EXPECT_FALSE(system(command));
664 return;
665 }
666 FILE *fp;
667 snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, log_filename);
668 EXPECT_TRUE(NULL != ((fp = fopen(command, "r"))));
669 if (!fp) {
670 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
671 EXPECT_FALSE(system(command));
672 return;
673 }
674 char *line = NULL;
675 char *last_line = NULL; // this line is allowed to stutter, one-line overlap
676 char *second_last_line = NULL;
677 size_t len = 0;
678 while (getline(&line, &len, fp) != -1) {
679 free(second_last_line);
680 second_last_line = last_line;
681 last_line = line;
682 line = NULL;
683 }
684 fclose(fp);
685 free(line);
686 if (second_last_line == NULL) {
687 fprintf(stderr, "No second to last line, using last, test may fail\n");
688 second_last_line = last_line;
689 last_line = NULL;
690 }
691 free(last_line);
692 EXPECT_TRUE(NULL != second_last_line);
693 if (!second_last_line) {
694 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
695 EXPECT_FALSE(system(command));
696 return;
697 }
698 // re-run the command, it should only add a few lines more content if it
699 // continues where it left off.
700 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);
701 EXPECT_FALSE((ret = system(command)));
702 if (ret) {
703 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
704 EXPECT_FALSE(system(command));
705 return;
706 }
707 DIR *dir;
708 EXPECT_TRUE(NULL != (dir = opendir(tmp_out_dir)));
709 if (!dir) {
710 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
711 EXPECT_FALSE(system(command));
712 return;
713 }
714 struct dirent *entry;
715 unsigned count = 0;
716 while ((entry = readdir(dir))) {
717 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) {
718 continue;
719 }
720 snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, entry->d_name);
721 EXPECT_TRUE(NULL != ((fp = fopen(command, "r"))));
722 if (!fp) {
723 fprintf(stderr, "%s ?\n", command);
724 continue;
725 }
726 line = NULL;
727 size_t number = 0;
728 while (getline(&line, &len, fp) != -1) {
729 ++number;
730 if (!strcmp(line, second_last_line)) {
731 EXPECT_TRUE(++count <= 1);
732 fprintf(stderr, "%s(%zu):\n", entry->d_name, number);
733 }
734 }
735 fclose(fp);
736 free(line);
737 unlink(command);
738 }
739 closedir(dir);
740 if (count > 1) {
741 char *brk = strpbrk(second_last_line, "\r\n");
742 if (!brk) {
743 brk = second_last_line + strlen(second_last_line);
744 }
745 fprintf(stderr, "\"%.*s\" occured %u times\n",
746 (int)(brk - second_last_line), second_last_line, count);
747 }
748 free(second_last_line);
749
750 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
Aristidis Papaioannoueba73442014-10-16 22:19:55 -0700751 EXPECT_FALSE(system(command));
752}
753
Mark Salyzyn1ab87e72016-04-01 07:52:20 -0700754TEST(logcat, logrotate_nodir) {
755 // expect logcat to error out on writing content and exit(1) for nodir
756 EXPECT_EQ(W_EXITCODE(1, 0),
757 system("logcat -b all -d"
758 " -f /das/nein/gerfingerpoken/logcat/log.txt"
759 " -n 256 -r 1024"));
760}
761
762static void caught_blocking_clear(int /*signum*/) {
Mark Salyzyn9b986492014-01-22 10:30:09 -0800763 unsigned long long v = 0xDEADBEEFA55C0000ULL;
764
765 v += getpid() & 0xFFFF;
766
767 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
768}
769
770TEST(logcat, blocking_clear) {
771 FILE *fp;
772 unsigned long long v = 0xDEADBEEFA55C0000ULL;
773
774 pid_t pid = getpid();
775
776 v += pid & 0xFFFF;
777
778 // This test is racey; an event occurs between clear and dump.
779 // We accept that we will get a false positive, but never a false negative.
Mark Salyzynef7c4112014-03-11 10:35:58 -0700780 ASSERT_TRUE(NULL != (fp = popen(
Mark Salyzyn9b986492014-01-22 10:30:09 -0800781 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
782 " logcat -b events -c 2>&1 ;"
Mark Salyzyna5e24292014-09-18 10:25:38 -0700783 " logcat -v brief -b events 2>&1",
Mark Salyzyn9b986492014-01-22 10:30:09 -0800784 "r")));
785
786 char buffer[5120];
787
788 int count = 0;
789
790 int signals = 0;
791
792 signal(SIGALRM, caught_blocking_clear);
793 alarm(2);
794 while (fgets(buffer, sizeof(buffer), fp)) {
Mark Salyzyn9b986492014-01-22 10:30:09 -0800795
796 if (!strncmp(buffer, "clearLog: ", 10)) {
797 fprintf(stderr, "WARNING: Test lacks permission to run :-(\n");
798 count = signals = 1;
799 break;
800 }
801
802 if (!strncmp(buffer, "DONE", 4)) {
803 break;
804 }
805
806 ++count;
807
808 int p;
809 unsigned long long l;
810
811 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
812 || (p != pid)) {
813 continue;
814 }
815
816 if (l == v) {
817 if (count > 1) {
818 fprintf(stderr, "WARNING: Possible false positive\n");
819 }
820 ++signals;
821 break;
822 }
823 }
824 alarm(0);
825 signal(SIGALRM, SIG_DFL);
826
827 // Generate SIGPIPE
828 fclose(fp);
829 caught_blocking_clear(0);
830
831 pclose(fp);
832
Mark Salyzynef7c4112014-03-11 10:35:58 -0700833 EXPECT_LE(1, count);
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800834
Mark Salyzynef7c4112014-03-11 10:35:58 -0700835 EXPECT_EQ(1, signals);
Mark Salyzyn5d3d1f12013-12-09 13:47:00 -0800836}
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700837
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700838static bool get_white_black(char **list) {
839 FILE *fp;
840
841 fp = popen("logcat -p 2>/dev/null", "r");
842 if (fp == NULL) {
843 fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n");
844 return false;
845 }
846
847 char buffer[5120];
848
849 while (fgets(buffer, sizeof(buffer), fp)) {
850 char *hold = *list;
851 char *buf = buffer;
852 while (isspace(*buf)) {
853 ++buf;
854 }
855 char *end = buf + strlen(buf);
856 while (isspace(*--end) && (end >= buf)) {
857 *end = '\0';
858 }
859 if (end < buf) {
860 continue;
861 }
862 if (hold) {
863 asprintf(list, "%s %s", hold, buf);
864 free(hold);
865 } else {
866 asprintf(list, "%s", buf);
867 }
868 }
869 pclose(fp);
870 return *list != NULL;
871}
872
873static bool set_white_black(const char *list) {
874 FILE *fp;
875
876 char buffer[5120];
877
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700878 snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list ? list : "");
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700879 fp = popen(buffer, "r");
880 if (fp == NULL) {
881 fprintf(stderr, "ERROR: %s\n", buffer);
882 return false;
883 }
884
885 while (fgets(buffer, sizeof(buffer), fp)) {
886 char *buf = buffer;
887 while (isspace(*buf)) {
888 ++buf;
889 }
890 char *end = buf + strlen(buf);
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700891 while ((end > buf) && isspace(*--end)) {
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700892 *end = '\0';
893 }
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700894 if (end <= buf) {
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700895 continue;
896 }
897 fprintf(stderr, "%s\n", buf);
898 pclose(fp);
899 return false;
900 }
901 return pclose(fp) == 0;
902}
903
904TEST(logcat, white_black_adjust) {
905 char *list = NULL;
906 char *adjust = NULL;
907
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700908 get_white_black(&list);
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700909
Mark Salyzyn22e287d2014-03-21 13:12:16 -0700910 static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30";
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700911 ASSERT_EQ(true, set_white_black(adjustment));
912 ASSERT_EQ(true, get_white_black(&adjust));
Mark Salyzynef7c4112014-03-11 10:35:58 -0700913 EXPECT_STREQ(adjustment, adjust);
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700914 free(adjust);
915 adjust = NULL;
916
Mark Salyzyn22e287d2014-03-21 13:12:16 -0700917 static const char adjustment2[] = "300/20 300/21 2000 ~1000";
918 ASSERT_EQ(true, set_white_black(adjustment2));
919 ASSERT_EQ(true, get_white_black(&adjust));
Mark Salyzynef7c4112014-03-11 10:35:58 -0700920 EXPECT_STREQ(adjustment2, adjust);
Mark Salyzyn22e287d2014-03-21 13:12:16 -0700921 free(adjust);
922 adjust = NULL;
923
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700924 ASSERT_EQ(true, set_white_black(list));
Mark Salyzyn9879ac82014-06-03 11:24:34 -0700925 get_white_black(&adjust);
926 EXPECT_STREQ(list ? list : "", adjust ? adjust : "");
Mark Salyzyn95cfc7b2014-03-11 11:20:56 -0700927 free(adjust);
928 adjust = NULL;
929
930 free(list);
931 list = NULL;
932}
Casey Dahlin0f7732d2016-03-17 16:18:55 -0700933
934TEST(logcat, regex) {
935 FILE *fp;
936 int count = 0;
937
938 char buffer[5120];
939
940 snprintf(buffer, sizeof(buffer), "logcat --pid %d -d -e logcat_test_a+b", getpid());
941
942 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_ab"));
943 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_b"));
944 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_aaaab"));
945 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_aaaa"));
946
947 // Let the logs settle
948 sleep(1);
949
950 ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
951
952 while (fgets(buffer, sizeof(buffer), fp)) {
953 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
954 continue;
955 }
956
957 EXPECT_TRUE(strstr(buffer, "logcat_test_") != NULL);
958
959 count++;
960 }
961
962 pclose(fp);
963
964 ASSERT_EQ(2, count);
965}
Casey Dahlin1164ef62016-03-17 14:04:52 -0700966
967TEST(logcat, maxcount) {
968 FILE *fp;
969 int count = 0;
970
971 char buffer[5120];
972
973 snprintf(buffer, sizeof(buffer), "logcat --pid %d -d --max-count 3", getpid());
974
975 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
976 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
977 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
978 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
979
980 // Let the logs settle
981 sleep(1);
982
983 ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
984
985 while (fgets(buffer, sizeof(buffer), fp)) {
986 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
987 continue;
988 }
989
990 count++;
991 }
992
993 pclose(fp);
994
995 ASSERT_EQ(3, count);
996}