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