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 <stdint.h>
21 #include <stdio.h>
22 #include <stdlib.h>
23 #include <string.h>
24 #include <sys/cdefs.h>
25 #include <sys/stat.h>
26 #include <sys/types.h>
27 #include <sys/wait.h>
28 #include <unistd.h>
29
30 #include <memory>
31 #include <string>
32
33 #include <android-base/file.h>
34 #include <android-base/stringprintf.h>
35 #include <gtest/gtest.h>
36 #include <log/event_tag_map.h>
37 #include <log/log.h>
38 #include <log/log_event_list.h>
39
40 #ifndef logcat_popen
41 #define logcat_define(context)
42 #define logcat_popen(context, command) popen((command), "r")
43 #define logcat_pclose(context, fp) pclose(fp)
44 #define logcat_system(command) system(command)
45 #endif
46 #ifndef logcat_executable
47 #define USING_LOGCAT_EXECUTABLE_DEFAULT
48 #define logcat_executable "logcat"
49 #endif
50
51 #define BIG_BUFFER (5 * 1024)
52
53 // rest(), let the logs settle.
54 //
55 // logd is in a background cgroup and under extreme load can take up to
56 // 3 seconds to land a log entry. Under moderate load we can do with 200ms.
rest()57 static void rest() {
58 static const useconds_t restPeriod = 200000;
59
60 usleep(restPeriod);
61 }
62
63 // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
64 // non-syscall libs. Since we are only using this in the emergency of
65 // a signal to stuff a terminating code into the logs, we will spin rather
66 // than try a usleep.
67 #define LOG_FAILURE_RETRY(exp) \
68 ({ \
69 typeof(exp) _rc; \
70 do { \
71 _rc = (exp); \
72 } while (((_rc == -1) && ((errno == EINTR) || (errno == EAGAIN))) || \
73 (_rc == -EINTR) || (_rc == -EAGAIN)); \
74 _rc; \
75 })
76
77 static const char begin[] = "--------- beginning of ";
78
TEST(logcat,buckets)79 TEST(logcat, buckets) {
80 FILE* fp;
81 logcat_define(ctx);
82
83 #undef LOG_TAG
84 #define LOG_TAG "inject.buckets"
85 // inject messages into radio, system, main and events buffers to
86 // ensure that we see all the begin[] bucket messages.
87 RLOGE(logcat_executable);
88 SLOGE(logcat_executable);
89 ALOGE(logcat_executable);
90 __android_log_bswrite(0, logcat_executable ".inject.buckets");
91 rest();
92
93 ASSERT_TRUE(NULL !=
94 (fp = logcat_popen(
95 ctx, logcat_executable
96 " -b radio -b events -b system -b main -d 2>/dev/null")));
97
98 char buffer[BIG_BUFFER];
99
100 int ids = 0;
101 int count = 0;
102
103 while (fgets(buffer, sizeof(buffer), fp)) {
104 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
105 while (char* cp = strrchr(buffer, '\n')) {
106 *cp = '\0';
107 }
108 log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1);
109 ids |= 1 << id;
110 ++count;
111 }
112 }
113
114 logcat_pclose(ctx, fp);
115
116 EXPECT_EQ(ids, 15);
117
118 EXPECT_EQ(count, 4);
119 }
120
TEST(logcat,event_tag_filter)121 TEST(logcat, event_tag_filter) {
122 FILE* fp;
123 logcat_define(ctx);
124
125 #undef LOG_TAG
126 #define LOG_TAG "inject.filter"
127 // inject messages into radio, system and main buffers
128 // with our unique log tag to test logcat filter.
129 RLOGE(logcat_executable);
130 SLOGE(logcat_executable);
131 ALOGE(logcat_executable);
132 rest();
133
134 std::string command = android::base::StringPrintf(
135 logcat_executable
136 " -b radio -b system -b main --pid=%d -d -s inject.filter 2>/dev/null",
137 getpid());
138 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, command.c_str())));
139
140 char buffer[BIG_BUFFER];
141
142 int count = 0;
143
144 while (fgets(buffer, sizeof(buffer), fp)) {
145 if (strncmp(begin, buffer, sizeof(begin) - 1)) ++count;
146 }
147
148 logcat_pclose(ctx, fp);
149
150 // logcat, liblogcat and logcatd test instances result in the progression
151 // of 3, 6 and 9 for our counts as each round is performed.
152 EXPECT_GE(count, 3);
153 EXPECT_LE(count, 9);
154 EXPECT_EQ(count % 3, 0);
155 }
156
157 // If there is not enough background noise in the logs, then spam the logs to
158 // permit tail checking so that the tests can progress.
inject(ssize_t count)159 static size_t inject(ssize_t count) {
160 if (count <= 0) return 0;
161
162 static const size_t retry = 4;
163 size_t errors = retry;
164 size_t num = 0;
165 for (;;) {
166 log_time ts(CLOCK_MONOTONIC);
167 if (__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) >= 0) {
168 if (++num >= (size_t)count) {
169 // let data settle end-to-end
170 sleep(3);
171 return num;
172 }
173 errors = retry;
174 usleep(100); // ~32 per timer tick, we are a spammer regardless
175 } else if (--errors <= 0) {
176 return num;
177 }
178 }
179 // NOTREACH
180 return num;
181 }
182
TEST(logcat,year)183 TEST(logcat, year) {
184 if (android_log_clockid() == CLOCK_MONOTONIC) {
185 fprintf(stderr, "Skipping test, logd is monotonic time\n");
186 return;
187 }
188
189 int count;
190 int tries = 3; // in case run too soon after system start or buffer clear
191
192 do {
193 FILE* fp;
194 logcat_define(ctx);
195
196 char needle[32];
197 time_t now;
198 time(&now);
199 struct tm* ptm;
200 #if !defined(_WIN32)
201 struct tm tmBuf;
202 ptm = localtime_r(&now, &tmBuf);
203 #else
204 ptm = localtime(&&now);
205 #endif
206 strftime(needle, sizeof(needle), "[ %Y-", ptm);
207
208 ASSERT_TRUE(NULL != (fp = logcat_popen(
209 ctx, logcat_executable
210 " -v long -v year -b all -t 3 2>/dev/null")));
211
212 char buffer[BIG_BUFFER];
213
214 count = 0;
215
216 while (fgets(buffer, sizeof(buffer), fp)) {
217 if (!strncmp(buffer, needle, strlen(needle))) {
218 ++count;
219 }
220 }
221 logcat_pclose(ctx, fp);
222
223 } while ((count < 3) && --tries && inject(3 - count));
224
225 ASSERT_EQ(3, count);
226 }
227
228 // Return a pointer to each null terminated -v long time field.
fgetLongTime(char * buffer,size_t buflen,FILE * fp)229 static char* fgetLongTime(char* buffer, size_t buflen, FILE* fp) {
230 while (fgets(buffer, buflen, fp)) {
231 char* cp = buffer;
232 if (*cp != '[') {
233 continue;
234 }
235 while (*++cp == ' ') {
236 ;
237 }
238 char* ep = cp;
239 while (isdigit(*ep)) {
240 ++ep;
241 }
242 if ((*ep != '-') && (*ep != '.')) {
243 continue;
244 }
245 // Find PID field. Look for ': ' or ':[0-9][0-9][0-9]'
246 while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) {
247 if (isdigit(ep[0]) && isdigit(ep[1]) && isdigit(ep[2])) break;
248 }
249 if (!ep) {
250 continue;
251 }
252 static const size_t pid_field_width = 7;
253 ep -= pid_field_width;
254 *ep = '\0';
255 return cp;
256 }
257 return NULL;
258 }
259
TEST(logcat,tz)260 TEST(logcat, tz) {
261 if (android_log_clockid() == CLOCK_MONOTONIC) {
262 fprintf(stderr, "Skipping test, logd is monotonic time\n");
263 return;
264 }
265
266 int tries = 4; // in case run too soon after system start or buffer clear
267 int count;
268
269 do {
270 FILE* fp;
271 logcat_define(ctx);
272
273 ASSERT_TRUE(NULL !=
274 (fp = logcat_popen(ctx, logcat_executable
275 " -v long -v America/Los_Angeles "
276 "-b all -t 3 2>/dev/null")));
277
278 char buffer[BIG_BUFFER];
279
280 count = 0;
281
282 while (fgetLongTime(buffer, sizeof(buffer), fp)) {
283 if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
284 ++count;
285 } else {
286 fprintf(stderr, "ts=\"%s\"\n", buffer + 2);
287 }
288 }
289
290 logcat_pclose(ctx, fp);
291
292 } while ((count < 3) && --tries && inject(3 - count));
293
294 ASSERT_EQ(3, count);
295 }
296
TEST(logcat,ntz)297 TEST(logcat, ntz) {
298 FILE* fp;
299 logcat_define(ctx);
300
301 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, logcat_executable
302 " -v long -v America/Los_Angeles -v "
303 "zone -b all -t 3 2>/dev/null")));
304
305 char buffer[BIG_BUFFER];
306
307 int count = 0;
308
309 while (fgetLongTime(buffer, sizeof(buffer), fp)) {
310 if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
311 ++count;
312 }
313 }
314
315 logcat_pclose(ctx, fp);
316
317 ASSERT_EQ(0, count);
318 }
319
do_tail(int num)320 static void do_tail(int num) {
321 int tries = 4; // in case run too soon after system start or buffer clear
322 int count;
323
324 if (num > 10) ++tries;
325 if (num > 100) ++tries;
326 do {
327 char buffer[BIG_BUFFER];
328
329 snprintf(buffer, sizeof(buffer),
330 "ANDROID_PRINTF_LOG=long logcat -b all -t %d 2>/dev/null", num);
331
332 FILE* fp;
333 logcat_define(ctx);
334 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer)));
335
336 count = 0;
337
338 while (fgetLongTime(buffer, sizeof(buffer), fp)) {
339 ++count;
340 }
341
342 logcat_pclose(ctx, fp);
343
344 } while ((count < num) && --tries && inject(num - count));
345
346 ASSERT_EQ(num, count);
347 }
348
TEST(logcat,tail_3)349 TEST(logcat, tail_3) {
350 do_tail(3);
351 }
352
TEST(logcat,tail_10)353 TEST(logcat, tail_10) {
354 do_tail(10);
355 }
356
TEST(logcat,tail_100)357 TEST(logcat, tail_100) {
358 do_tail(100);
359 }
360
TEST(logcat,tail_1000)361 TEST(logcat, tail_1000) {
362 do_tail(1000);
363 }
364
do_tail_time(const char * cmd)365 static void do_tail_time(const char* cmd) {
366 FILE* fp;
367 int count;
368 char buffer[BIG_BUFFER];
369 char* last_timestamp = NULL;
370 // Hard to predict 100% if first (overlap) or second line will match.
371 // -v nsec will in a substantial majority be the second line.
372 char* first_timestamp = NULL;
373 char* second_timestamp = NULL;
374 char* input;
375
376 int tries = 4; // in case run too soon after system start or buffer clear
377
378 do {
379 snprintf(buffer, sizeof(buffer), "%s -t 10 2>&1", cmd);
380 logcat_define(ctx);
381 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer)));
382 count = 0;
383
384 while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) {
385 ++count;
386 if (!first_timestamp) {
387 first_timestamp = strdup(input);
388 } else if (!second_timestamp) {
389 second_timestamp = strdup(input);
390 }
391 free(last_timestamp);
392 last_timestamp = strdup(input);
393 }
394 logcat_pclose(ctx, fp);
395
396 } while ((count < 10) && --tries && inject(10 - count));
397
398 EXPECT_EQ(count, 10); // We want _some_ history, too small, falses below
399 EXPECT_TRUE(last_timestamp != NULL);
400 EXPECT_TRUE(first_timestamp != NULL);
401 EXPECT_TRUE(second_timestamp != NULL);
402
403 snprintf(buffer, sizeof(buffer), "%s -t '%s' 2>&1", cmd, first_timestamp);
404 logcat_define(ctx);
405 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer)));
406
407 int second_count = 0;
408 int last_timestamp_count = -1;
409
410 --count; // One less unless we match the first_timestamp
411 bool found = false;
412 while ((input = fgetLongTime(buffer, sizeof(buffer), fp))) {
413 ++second_count;
414 // We want to highlight if we skip to the next entry.
415 // WAI, if the time in logd is *exactly*
416 // XX-XX XX:XX:XX.XXXXXX000 (usec) or XX-XX XX:XX:XX.XXX000000
417 // this can happen, but it should not happen with nsec.
418 // We can make this WAI behavior happen 1000 times less
419 // frequently if the caller does not use the -v usec flag,
420 // but always the second (always skip) if they use the
421 // (undocumented) -v nsec flag.
422 if (first_timestamp) {
423 found = !strcmp(input, first_timestamp);
424 if (found) {
425 ++count;
426 GTEST_LOG_(INFO)
427 << "input = first(" << first_timestamp << ")\n";
428 }
429 free(first_timestamp);
430 first_timestamp = NULL;
431 }
432 if (second_timestamp) {
433 found = found || !strcmp(input, second_timestamp);
434 if (!found) {
435 GTEST_LOG_(INFO) << "input(" << input << ") != second("
436 << second_timestamp << ")\n";
437 }
438 free(second_timestamp);
439 second_timestamp = NULL;
440 }
441 if (!strcmp(input, last_timestamp)) {
442 last_timestamp_count = second_count;
443 }
444 }
445 logcat_pclose(ctx, fp);
446
447 EXPECT_TRUE(found);
448 if (!found) {
449 if (first_timestamp) {
450 GTEST_LOG_(INFO) << "first = " << first_timestamp << "\n";
451 }
452 if (second_timestamp) {
453 GTEST_LOG_(INFO) << "second = " << second_timestamp << "\n";
454 }
455 if (last_timestamp) {
456 GTEST_LOG_(INFO) << "last = " << last_timestamp << "\n";
457 }
458 }
459 free(last_timestamp);
460 last_timestamp = NULL;
461 free(first_timestamp);
462 free(second_timestamp);
463
464 EXPECT_TRUE(first_timestamp == NULL);
465 EXPECT_TRUE(second_timestamp == NULL);
466 EXPECT_LE(count, second_count);
467 EXPECT_LE(count, last_timestamp_count);
468 }
469
TEST(logcat,tail_time)470 TEST(logcat, tail_time) {
471 do_tail_time(logcat_executable " -v long -v nsec -b all");
472 }
473
TEST(logcat,tail_time_epoch)474 TEST(logcat, tail_time_epoch) {
475 do_tail_time(logcat_executable " -v long -v nsec -v epoch -b all");
476 }
477
TEST(logcat,End_to_End)478 TEST(logcat, End_to_End) {
479 pid_t pid = getpid();
480
481 log_time ts(CLOCK_MONOTONIC);
482
483 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
484
485 FILE* fp;
486 logcat_define(ctx);
487 ASSERT_TRUE(NULL !=
488 (fp = logcat_popen(ctx, logcat_executable
489 " -v brief -b events -t 100 2>/dev/null")));
490
491 char buffer[BIG_BUFFER];
492
493 int count = 0;
494
495 while (fgets(buffer, sizeof(buffer), fp)) {
496 int p;
497 unsigned long long t;
498
499 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) ||
500 (p != pid)) {
501 continue;
502 }
503
504 log_time tx((const char*)&t);
505 if (ts == tx) {
506 ++count;
507 }
508 }
509
510 logcat_pclose(ctx, fp);
511
512 ASSERT_EQ(1, count);
513 }
514
TEST(logcat,End_to_End_multitude)515 TEST(logcat, End_to_End_multitude) {
516 pid_t pid = getpid();
517
518 log_time ts(CLOCK_MONOTONIC);
519
520 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
521
522 FILE* fp[256]; // does this count as a multitude!
523 memset(fp, 0, sizeof(fp));
524 logcat_define(ctx[sizeof(fp) / sizeof(fp[0])]);
525 size_t num = 0;
526 do {
527 EXPECT_TRUE(NULL !=
528 (fp[num] = logcat_popen(ctx[num], logcat_executable
529 " -v brief -b events -t 100")));
530 if (!fp[num]) {
531 fprintf(stderr,
532 "WARNING: limiting to %zu simultaneous logcat operations\n",
533 num);
534 break;
535 }
536 } while (++num < sizeof(fp) / sizeof(fp[0]));
537
538 char buffer[BIG_BUFFER];
539
540 size_t count = 0;
541
542 for (size_t idx = 0; idx < sizeof(fp) / sizeof(fp[0]); ++idx) {
543 if (!fp[idx]) break;
544 while (fgets(buffer, sizeof(buffer), fp[idx])) {
545 int p;
546 unsigned long long t;
547
548 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t)) ||
549 (p != pid)) {
550 continue;
551 }
552
553 log_time tx((const char*)&t);
554 if (ts == tx) {
555 ++count;
556 }
557 }
558
559 logcat_pclose(ctx[idx], fp[idx]);
560 }
561
562 ASSERT_EQ(num, count);
563 }
564
get_groups(const char * cmd)565 static int get_groups(const char* cmd) {
566 FILE* fp;
567 logcat_define(ctx);
568
569 // NB: crash log only available in user space
570 EXPECT_TRUE(NULL != (fp = logcat_popen(ctx, cmd)));
571
572 if (fp == NULL) {
573 return 0;
574 }
575
576 char buffer[BIG_BUFFER];
577
578 int count = 0;
579
580 while (fgets(buffer, sizeof(buffer), fp)) {
581 int size, consumed, max, payload;
582 char size_mult[3], consumed_mult[3];
583 long full_size, full_consumed;
584
585 size = consumed = max = payload = 0;
586 // NB: crash log can be very small, not hit a Kb of consumed space
587 // doubly lucky we are not including it.
588 if (6 != sscanf(buffer,
589 "%*s ring buffer is %d%2s (%d%2s consumed),"
590 " max entry is %db, max payload is %db",
591 &size, size_mult, &consumed, consumed_mult, &max,
592 &payload)) {
593 fprintf(stderr, "WARNING: Parse error: %s", buffer);
594 continue;
595 }
596 full_size = size;
597 switch (size_mult[0]) {
598 case 'G':
599 full_size *= 1024;
600 /* FALLTHRU */
601 case 'M':
602 full_size *= 1024;
603 /* FALLTHRU */
604 case 'K':
605 full_size *= 1024;
606 /* FALLTHRU */
607 case 'b':
608 break;
609 }
610 full_consumed = consumed;
611 switch (consumed_mult[0]) {
612 case 'G':
613 full_consumed *= 1024;
614 /* FALLTHRU */
615 case 'M':
616 full_consumed *= 1024;
617 /* FALLTHRU */
618 case 'K':
619 full_consumed *= 1024;
620 /* FALLTHRU */
621 case 'b':
622 break;
623 }
624 EXPECT_GT((full_size * 9) / 4, full_consumed);
625 EXPECT_GT(full_size, max);
626 EXPECT_GT(max, payload);
627
628 if ((((full_size * 9) / 4) >= full_consumed) && (full_size > max) &&
629 (max > payload)) {
630 ++count;
631 }
632 }
633
634 logcat_pclose(ctx, fp);
635
636 return count;
637 }
638
TEST(logcat,get_size)639 TEST(logcat, get_size) {
640 ASSERT_EQ(4, get_groups(logcat_executable
641 " -v brief -b radio -b events -b system -b "
642 "main -g 2>/dev/null"));
643 }
644
645 // duplicate test for get_size, but use comma-separated list of buffers
TEST(logcat,multiple_buffer)646 TEST(logcat, multiple_buffer) {
647 ASSERT_EQ(
648 4, get_groups(logcat_executable
649 " -v brief -b radio,events,system,main -g 2>/dev/null"));
650 }
651
TEST(logcat,bad_buffer)652 TEST(logcat, bad_buffer) {
653 ASSERT_EQ(0,
654 get_groups(
655 logcat_executable
656 " -v brief -b radio,events,bogo,system,main -g 2>/dev/null"));
657 }
658
659 #ifndef logcat
caught_blocking(int signum)660 static void caught_blocking(int signum) {
661 unsigned long long v = 0xDEADBEEFA55A0000ULL;
662
663 v += getpid() & 0xFFFF;
664 if (signum == 0) ++v;
665
666 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
667 }
668
TEST(logcat,blocking)669 TEST(logcat, blocking) {
670 FILE* fp;
671 unsigned long long v = 0xDEADBEEFA55F0000ULL;
672
673 pid_t pid = getpid();
674
675 v += pid & 0xFFFF;
676
677 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
678
679 v &= 0xFFFFFFFFFFFAFFFFULL;
680
681 ASSERT_TRUE(
682 NULL !=
683 (fp = popen("( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
684 " logcat -v brief -b events 2>&1",
685 "r")));
686
687 char buffer[BIG_BUFFER];
688
689 int count = 0;
690
691 int signals = 0;
692
693 signal(SIGALRM, caught_blocking);
694 alarm(2);
695 while (fgets(buffer, sizeof(buffer), fp)) {
696 if (!strncmp(buffer, "DONE", 4)) {
697 break;
698 }
699
700 ++count;
701
702 int p;
703 unsigned long long l;
704
705 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) {
706 continue;
707 }
708
709 if (l == v) {
710 ++signals;
711 break;
712 }
713 }
714 alarm(0);
715 signal(SIGALRM, SIG_DFL);
716
717 // Generate SIGPIPE
718 fclose(fp);
719 caught_blocking(0);
720
721 pclose(fp);
722
723 EXPECT_GE(count, 2);
724
725 EXPECT_EQ(signals, 1);
726 }
727
caught_blocking_tail(int signum)728 static void caught_blocking_tail(int signum) {
729 unsigned long long v = 0xA55ADEADBEEF0000ULL;
730
731 v += getpid() & 0xFFFF;
732 if (signum == 0) ++v;
733
734 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
735 }
736
TEST(logcat,blocking_tail)737 TEST(logcat, blocking_tail) {
738 FILE* fp;
739 unsigned long long v = 0xA55FDEADBEEF0000ULL;
740
741 pid_t pid = getpid();
742
743 v += pid & 0xFFFF;
744
745 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
746
747 v &= 0xFFFAFFFFFFFFFFFFULL;
748
749 ASSERT_TRUE(
750 NULL !=
751 (fp = popen("( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
752 " logcat -v brief -b events -T 5 2>&1",
753 "r")));
754
755 char buffer[BIG_BUFFER];
756
757 int count = 0;
758
759 int signals = 0;
760
761 signal(SIGALRM, caught_blocking_tail);
762 alarm(2);
763 while (fgets(buffer, sizeof(buffer), fp)) {
764 if (!strncmp(buffer, "DONE", 4)) {
765 break;
766 }
767
768 ++count;
769
770 int p;
771 unsigned long long l;
772
773 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) {
774 continue;
775 }
776
777 if (l == v) {
778 if (count >= 5) {
779 ++signals;
780 }
781 break;
782 }
783 }
784 alarm(0);
785 signal(SIGALRM, SIG_DFL);
786
787 // Generate SIGPIPE
788 fclose(fp);
789 caught_blocking_tail(0);
790
791 pclose(fp);
792
793 EXPECT_GE(count, 2);
794
795 EXPECT_EQ(signals, 1);
796 }
797 #endif
798
799 // meant to be handed to ASSERT_FALSE / EXPECT_FALSE to expand the message
IsFalse(int ret,const char * command)800 static testing::AssertionResult IsFalse(int ret, const char* command) {
801 return ret ? (testing::AssertionSuccess()
802 << "ret=" << ret << " command=\"" << command << "\"")
803 : testing::AssertionFailure();
804 }
805
TEST(logcat,logrotate)806 TEST(logcat, logrotate) {
807 static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX";
808 char buf[sizeof(form)];
809 ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form)));
810
811 static const char comm[] = logcat_executable
812 " -b radio -b events -b system -b main"
813 " -d -f %s/log.txt -n 7 -r 1";
814 char command[sizeof(buf) + sizeof(comm)];
815 snprintf(command, sizeof(command), comm, buf);
816
817 int ret;
818 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command));
819 if (!ret) {
820 snprintf(command, sizeof(command), "ls -s %s 2>/dev/null", buf);
821
822 FILE* fp;
823 EXPECT_TRUE(NULL != (fp = popen(command, "r")));
824 if (fp) {
825 char buffer[BIG_BUFFER];
826 int count = 0;
827
828 while (fgets(buffer, sizeof(buffer), fp)) {
829 static const char total[] = "total ";
830 int num;
831 char c;
832
833 if ((2 == sscanf(buffer, "%d log.tx%c", &num, &c)) &&
834 (num <= 40)) {
835 ++count;
836 } else if (strncmp(buffer, total, sizeof(total) - 1)) {
837 fprintf(stderr, "WARNING: Parse error: %s", buffer);
838 }
839 }
840 pclose(fp);
841 if ((count != 7) && (count != 8)) {
842 fprintf(stderr, "count=%d\n", count);
843 }
844 EXPECT_TRUE(count == 7 || count == 8);
845 }
846 }
847 snprintf(command, sizeof(command), "rm -rf %s", buf);
848 EXPECT_FALSE(IsFalse(system(command), command));
849 }
850
TEST(logcat,logrotate_suffix)851 TEST(logcat, logrotate_suffix) {
852 static const char tmp_out_dir_form[] =
853 "/data/local/tmp/logcat.logrotate.XXXXXX";
854 char tmp_out_dir[sizeof(tmp_out_dir_form)];
855 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));
856
857 static const char logcat_cmd[] = logcat_executable
858 " -b radio -b events -b system -b main"
859 " -d -f %s/log.txt -n 10 -r 1";
860 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)];
861 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir);
862
863 int ret;
864 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command));
865 if (!ret) {
866 snprintf(command, sizeof(command), "ls %s 2>/dev/null", tmp_out_dir);
867
868 FILE* fp;
869 EXPECT_TRUE(NULL != (fp = popen(command, "r")));
870 char buffer[BIG_BUFFER];
871 int log_file_count = 0;
872
873 while (fgets(buffer, sizeof(buffer), fp)) {
874 static const char rotated_log_filename_prefix[] = "log.txt.";
875 static const size_t rotated_log_filename_prefix_len =
876 strlen(rotated_log_filename_prefix);
877 static const char log_filename[] = "log.txt";
878
879 if (!strncmp(buffer, rotated_log_filename_prefix,
880 rotated_log_filename_prefix_len)) {
881 // Rotated file should have form log.txt.##
882 char* rotated_log_filename_suffix =
883 buffer + rotated_log_filename_prefix_len;
884 char* endptr;
885 const long int suffix_value =
886 strtol(rotated_log_filename_suffix, &endptr, 10);
887 EXPECT_EQ(rotated_log_filename_suffix + 2, endptr);
888 EXPECT_LE(suffix_value, 10);
889 EXPECT_GT(suffix_value, 0);
890 ++log_file_count;
891 continue;
892 }
893
894 if (!strncmp(buffer, log_filename, strlen(log_filename))) {
895 ++log_file_count;
896 continue;
897 }
898
899 fprintf(stderr, "ERROR: Unexpected file: %s", buffer);
900 ADD_FAILURE();
901 }
902 pclose(fp);
903 EXPECT_EQ(log_file_count, 11);
904 }
905 snprintf(command, sizeof(command), "rm -rf %s", tmp_out_dir);
906 EXPECT_FALSE(IsFalse(system(command), command));
907 }
908
TEST(logcat,logrotate_continue)909 TEST(logcat, logrotate_continue) {
910 static const char tmp_out_dir_form[] =
911 "/data/local/tmp/logcat.logrotate.XXXXXX";
912 char tmp_out_dir[sizeof(tmp_out_dir_form)];
913 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));
914
915 static const char log_filename[] = "log.txt";
916 static const char logcat_cmd[] =
917 logcat_executable " -b all -v nsec -d -f %s/%s -n 256 -r 1024";
918 static const char cleanup_cmd[] = "rm -rf %s";
919 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)];
920 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);
921
922 int ret;
923 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command));
924 if (ret) {
925 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
926 EXPECT_FALSE(IsFalse(system(command), command));
927 return;
928 }
929 FILE* fp;
930 snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, log_filename);
931 EXPECT_TRUE(NULL != ((fp = fopen(command, "r"))));
932 if (!fp) {
933 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
934 EXPECT_FALSE(IsFalse(system(command), command));
935 return;
936 }
937 char* line = NULL;
938 char* last_line =
939 NULL; // this line is allowed to stutter, one-line overlap
940 char* second_last_line = NULL; // should never stutter
941 char* first_line = NULL; // help diagnose failure?
942 size_t len = 0;
943 while (getline(&line, &len, fp) != -1) {
944 if (!first_line) {
945 first_line = line;
946 line = NULL;
947 continue;
948 }
949 free(second_last_line);
950 second_last_line = last_line;
951 last_line = line;
952 line = NULL;
953 }
954 fclose(fp);
955 free(line);
956 if (second_last_line == NULL) {
957 fprintf(stderr, "No second to last line, using last, test may fail\n");
958 second_last_line = last_line;
959 last_line = NULL;
960 }
961 free(last_line);
962 EXPECT_TRUE(NULL != second_last_line);
963 if (!second_last_line) {
964 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
965 EXPECT_FALSE(IsFalse(system(command), command));
966 free(first_line);
967 return;
968 }
969 // re-run the command, it should only add a few lines more content if it
970 // continues where it left off.
971 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);
972 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command));
973 if (ret) {
974 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
975 EXPECT_FALSE(IsFalse(system(command), command));
976 free(second_last_line);
977 free(first_line);
978 return;
979 }
980 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir),
981 closedir);
982 EXPECT_NE(nullptr, dir);
983 if (!dir) {
984 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
985 EXPECT_FALSE(IsFalse(system(command), command));
986 free(second_last_line);
987 free(first_line);
988 return;
989 }
990 struct dirent* entry;
991 unsigned count = 0;
992 while ((entry = readdir(dir.get()))) {
993 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) {
994 continue;
995 }
996 snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, entry->d_name);
997 EXPECT_TRUE(NULL != ((fp = fopen(command, "r"))));
998 if (!fp) {
999 fprintf(stderr, "%s ?\n", command);
1000 continue;
1001 }
1002 line = NULL;
1003 size_t number = 0;
1004 while (getline(&line, &len, fp) != -1) {
1005 ++number;
1006 if (!strcmp(line, second_last_line)) {
1007 EXPECT_TRUE(++count <= 1);
1008 fprintf(stderr, "%s(%zu):\n", entry->d_name, number);
1009 }
1010 }
1011 fclose(fp);
1012 free(line);
1013 unlink(command);
1014 }
1015 if (count > 1) {
1016 char* brk = strpbrk(second_last_line, "\r\n");
1017 if (!brk) brk = second_last_line + strlen(second_last_line);
1018 fprintf(stderr, "\"%.*s\" occurred %u times\n",
1019 (int)(brk - second_last_line), second_last_line, count);
1020 if (first_line) {
1021 brk = strpbrk(first_line, "\r\n");
1022 if (!brk) brk = first_line + strlen(first_line);
1023 fprintf(stderr, "\"%.*s\" was first line, fault?\n",
1024 (int)(brk - first_line), first_line);
1025 }
1026 }
1027 free(second_last_line);
1028 free(first_line);
1029
1030 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1031 EXPECT_FALSE(IsFalse(system(command), command));
1032 }
1033
TEST(logcat,logrotate_clear)1034 TEST(logcat, logrotate_clear) {
1035 static const char tmp_out_dir_form[] =
1036 "/data/local/tmp/logcat.logrotate.XXXXXX";
1037 char tmp_out_dir[sizeof(tmp_out_dir_form)];
1038 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));
1039
1040 static const char log_filename[] = "log.txt";
1041 static const unsigned num_val = 32;
1042 static const char logcat_cmd[] =
1043 logcat_executable " -b all -d -f %s/%s -n %d -r 1";
1044 static const char clear_cmd[] = " -c";
1045 static const char cleanup_cmd[] = "rm -rf %s";
1046 char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) +
1047 sizeof(log_filename) + sizeof(clear_cmd) + 32];
1048
1049 // Run command with all data
1050 {
1051 snprintf(command, sizeof(command) - sizeof(clear_cmd), logcat_cmd,
1052 tmp_out_dir, log_filename, num_val);
1053
1054 int ret;
1055 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command));
1056 if (ret) {
1057 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1058 EXPECT_FALSE(IsFalse(system(command), command));
1059 return;
1060 }
1061 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir),
1062 closedir);
1063 EXPECT_NE(nullptr, dir);
1064 if (!dir) {
1065 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1066 EXPECT_FALSE(IsFalse(system(command), command));
1067 return;
1068 }
1069 struct dirent* entry;
1070 unsigned count = 0;
1071 while ((entry = readdir(dir.get()))) {
1072 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) {
1073 continue;
1074 }
1075 ++count;
1076 }
1077 EXPECT_EQ(count, num_val + 1);
1078 }
1079
1080 {
1081 // Now with -c option tacked onto the end
1082 strcat(command, clear_cmd);
1083
1084 int ret;
1085 EXPECT_FALSE(IsFalse(ret = logcat_system(command), command));
1086 if (ret) {
1087 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1088 EXPECT_FALSE(system(command));
1089 EXPECT_FALSE(IsFalse(system(command), command));
1090 return;
1091 }
1092 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir),
1093 closedir);
1094 EXPECT_NE(nullptr, dir);
1095 if (!dir) {
1096 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1097 EXPECT_FALSE(IsFalse(system(command), command));
1098 return;
1099 }
1100 struct dirent* entry;
1101 unsigned count = 0;
1102 while ((entry = readdir(dir.get()))) {
1103 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) {
1104 continue;
1105 }
1106 fprintf(stderr, "Found %s/%s!!!\n", tmp_out_dir, entry->d_name);
1107 ++count;
1108 }
1109 EXPECT_EQ(count, 0U);
1110 }
1111
1112 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1113 EXPECT_FALSE(IsFalse(system(command), command));
1114 }
1115
logrotate_count_id(const char * logcat_cmd,const char * tmp_out_dir)1116 static int logrotate_count_id(const char* logcat_cmd, const char* tmp_out_dir) {
1117 static const char log_filename[] = "log.txt";
1118 char command[strlen(tmp_out_dir) + strlen(logcat_cmd) +
1119 strlen(log_filename) + 32];
1120
1121 snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename);
1122
1123 int ret = logcat_system(command);
1124 if (ret) {
1125 fprintf(stderr, "system(\"%s\")=%d", command, ret);
1126 return -1;
1127 }
1128 std::unique_ptr<DIR, decltype(&closedir)> dir(opendir(tmp_out_dir),
1129 closedir);
1130 if (!dir) {
1131 fprintf(stderr, "opendir(\"%s\") failed", tmp_out_dir);
1132 return -1;
1133 }
1134 struct dirent* entry;
1135 int count = 0;
1136 while ((entry = readdir(dir.get()))) {
1137 if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) {
1138 continue;
1139 }
1140 ++count;
1141 }
1142 return count;
1143 }
1144
TEST(logcat,logrotate_id)1145 TEST(logcat, logrotate_id) {
1146 static const char logcat_cmd[] =
1147 logcat_executable " -b all -d -f %s/%s -n 32 -r 1 --id=test";
1148 static const char logcat_short_cmd[] =
1149 logcat_executable " -b all -t 10 -f %s/%s -n 32 -r 1 --id=test";
1150 static const char tmp_out_dir_form[] =
1151 "/data/local/tmp/logcat.logrotate.XXXXXX";
1152 static const char log_filename[] = "log.txt";
1153 char tmp_out_dir[strlen(tmp_out_dir_form) + 1];
1154 ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form)));
1155
1156 EXPECT_EQ(logrotate_count_id(logcat_cmd, tmp_out_dir), 34);
1157 EXPECT_EQ(logrotate_count_id(logcat_short_cmd, tmp_out_dir), 34);
1158
1159 char id_file[strlen(tmp_out_dir_form) + strlen(log_filename) + 5];
1160 snprintf(id_file, sizeof(id_file), "%s/%s.id", tmp_out_dir, log_filename);
1161 if (getuid() != 0) {
1162 chmod(id_file, 0);
1163 EXPECT_EQ(logrotate_count_id(logcat_short_cmd, tmp_out_dir), 34);
1164 }
1165 unlink(id_file);
1166 EXPECT_EQ(logrotate_count_id(logcat_short_cmd, tmp_out_dir), 34);
1167
1168 FILE* fp = fopen(id_file, "w");
1169 if (fp) {
1170 fprintf(fp, "not_a_test");
1171 fclose(fp);
1172 }
1173 if (getuid() != 0) {
1174 chmod(id_file,
1175 0); // API to preserve content even with signature change
1176 ASSERT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir));
1177 chmod(id_file, 0600);
1178 }
1179
1180 int new_signature;
1181 EXPECT_GE(
1182 (new_signature = logrotate_count_id(logcat_short_cmd, tmp_out_dir)), 2);
1183 EXPECT_LT(new_signature, 34);
1184
1185 static const char cleanup_cmd[] = "rm -rf %s";
1186 char command[strlen(cleanup_cmd) + strlen(tmp_out_dir_form)];
1187 snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir);
1188 EXPECT_FALSE(IsFalse(system(command), command));
1189 }
1190
TEST(logcat,logrotate_nodir)1191 TEST(logcat, logrotate_nodir) {
1192 // expect logcat to error out on writing content and not exit(0) for nodir
1193 static const char command[] = logcat_executable
1194 " -b all -d"
1195 " -f /das/nein/gerfingerpoken/logcat/log.txt"
1196 " -n 256 -r 1024";
1197 EXPECT_FALSE(IsFalse(0 == logcat_system(command), command));
1198 }
1199
1200 #ifndef logcat
caught_blocking_clear(int signum)1201 static void caught_blocking_clear(int signum) {
1202 unsigned long long v = 0xDEADBEEFA55C0000ULL;
1203
1204 v += getpid() & 0xFFFF;
1205 if (signum == 0) ++v;
1206
1207 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
1208 }
1209
TEST(logcat,blocking_clear)1210 TEST(logcat, blocking_clear) {
1211 FILE* fp;
1212 unsigned long long v = 0xDEADBEEFA55C0000ULL;
1213
1214 pid_t pid = getpid();
1215
1216 v += pid & 0xFFFF;
1217
1218 // This test is racey; an event occurs between clear and dump.
1219 // We accept that we will get a false positive, but never a false negative.
1220 ASSERT_TRUE(
1221 NULL !=
1222 (fp = popen("( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
1223 " logcat -b events -c 2>&1 ;"
1224 " logcat -b events -g 2>&1 ;"
1225 " logcat -v brief -b events 2>&1",
1226 "r")));
1227
1228 char buffer[BIG_BUFFER];
1229
1230 int count = 0;
1231 int minus_g = 0;
1232
1233 int signals = 0;
1234
1235 signal(SIGALRM, caught_blocking_clear);
1236 alarm(2);
1237 while (fgets(buffer, sizeof(buffer), fp)) {
1238 if (!strncmp(buffer, "clearLog: ", strlen("clearLog: "))) {
1239 fprintf(stderr, "WARNING: Test lacks permission to run :-(\n");
1240 count = signals = 1;
1241 break;
1242 }
1243 if (!strncmp(buffer, "failed to clear", strlen("failed to clear"))) {
1244 fprintf(stderr, "WARNING: Test lacks permission to run :-(\n");
1245 count = signals = 1;
1246 break;
1247 }
1248
1249 if (!strncmp(buffer, "DONE", 4)) {
1250 break;
1251 }
1252
1253 int size, consumed, max, payload;
1254 char size_mult[3], consumed_mult[3];
1255 size = consumed = max = payload = 0;
1256 if (6 == sscanf(buffer,
1257 "events: ring buffer is %d%2s (%d%2s consumed),"
1258 " max entry is %db, max payload is %db",
1259 &size, size_mult, &consumed, consumed_mult, &max,
1260 &payload)) {
1261 long full_size = size, full_consumed = consumed;
1262
1263 switch (size_mult[0]) {
1264 case 'G':
1265 full_size *= 1024;
1266 /* FALLTHRU */
1267 case 'M':
1268 full_size *= 1024;
1269 /* FALLTHRU */
1270 case 'K':
1271 full_size *= 1024;
1272 /* FALLTHRU */
1273 case 'b':
1274 break;
1275 }
1276 switch (consumed_mult[0]) {
1277 case 'G':
1278 full_consumed *= 1024;
1279 /* FALLTHRU */
1280 case 'M':
1281 full_consumed *= 1024;
1282 /* FALLTHRU */
1283 case 'K':
1284 full_consumed *= 1024;
1285 /* FALLTHRU */
1286 case 'b':
1287 break;
1288 }
1289 EXPECT_GT(full_size, full_consumed);
1290 EXPECT_GT(full_size, max);
1291 EXPECT_GT(max, payload);
1292 EXPECT_GT(max, full_consumed);
1293
1294 ++minus_g;
1295 continue;
1296 }
1297
1298 ++count;
1299
1300 int p;
1301 unsigned long long l;
1302
1303 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l)) || (p != pid)) {
1304 continue;
1305 }
1306
1307 if (l == v) {
1308 if (count > 1) {
1309 fprintf(stderr, "WARNING: Possible false positive\n");
1310 }
1311 ++signals;
1312 break;
1313 }
1314 }
1315 alarm(0);
1316 signal(SIGALRM, SIG_DFL);
1317
1318 // Generate SIGPIPE
1319 fclose(fp);
1320 caught_blocking_clear(0);
1321
1322 pclose(fp);
1323
1324 EXPECT_GE(count, 1);
1325 EXPECT_EQ(minus_g, 1);
1326
1327 EXPECT_EQ(signals, 1);
1328 }
1329 #endif
1330
get_white_black(char ** list)1331 static bool get_white_black(char** list) {
1332 FILE* fp;
1333 logcat_define(ctx);
1334
1335 fp = logcat_popen(ctx, logcat_executable " -p 2>/dev/null");
1336 if (fp == NULL) {
1337 fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n");
1338 return false;
1339 }
1340
1341 char buffer[BIG_BUFFER];
1342
1343 while (fgets(buffer, sizeof(buffer), fp)) {
1344 char* hold = *list;
1345 char* buf = buffer;
1346 while (isspace(*buf)) {
1347 ++buf;
1348 }
1349 char* end = buf + strlen(buf);
1350 while (isspace(*--end) && (end >= buf)) {
1351 *end = '\0';
1352 }
1353 if (end < buf) {
1354 continue;
1355 }
1356 if (hold) {
1357 asprintf(list, "%s %s", hold, buf);
1358 free(hold);
1359 } else {
1360 asprintf(list, "%s", buf);
1361 }
1362 }
1363 logcat_pclose(ctx, fp);
1364 return *list != NULL;
1365 }
1366
set_white_black(const char * list)1367 static bool set_white_black(const char* list) {
1368 FILE* fp;
1369 logcat_define(ctx);
1370
1371 char buffer[BIG_BUFFER];
1372
1373 snprintf(buffer, sizeof(buffer), logcat_executable " -P '%s' 2>&1",
1374 list ? list : "");
1375 fp = logcat_popen(ctx, buffer);
1376 if (fp == NULL) {
1377 fprintf(stderr, "ERROR: %s\n", buffer);
1378 return false;
1379 }
1380
1381 while (fgets(buffer, sizeof(buffer), fp)) {
1382 char* buf = buffer;
1383 while (isspace(*buf)) {
1384 ++buf;
1385 }
1386 char* end = buf + strlen(buf);
1387 while ((end > buf) && isspace(*--end)) {
1388 *end = '\0';
1389 }
1390 if (end <= buf) {
1391 continue;
1392 }
1393 fprintf(stderr, "%s\n", buf);
1394 logcat_pclose(ctx, fp);
1395 return false;
1396 }
1397 return logcat_pclose(ctx, fp) == 0;
1398 }
1399
TEST(logcat,white_black_adjust)1400 TEST(logcat, white_black_adjust) {
1401 char* list = NULL;
1402 char* adjust = NULL;
1403
1404 get_white_black(&list);
1405
1406 static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30";
1407 ASSERT_EQ(true, set_white_black(adjustment));
1408 ASSERT_EQ(true, get_white_black(&adjust));
1409 EXPECT_STREQ(adjustment, adjust);
1410 free(adjust);
1411 adjust = NULL;
1412
1413 static const char adjustment2[] = "300/20 300/21 2000 ~1000";
1414 ASSERT_EQ(true, set_white_black(adjustment2));
1415 ASSERT_EQ(true, get_white_black(&adjust));
1416 EXPECT_STREQ(adjustment2, adjust);
1417 free(adjust);
1418 adjust = NULL;
1419
1420 ASSERT_EQ(true, set_white_black(list));
1421 get_white_black(&adjust);
1422 EXPECT_STREQ(list ? list : "", adjust ? adjust : "");
1423 free(adjust);
1424 adjust = NULL;
1425
1426 free(list);
1427 list = NULL;
1428 }
1429
TEST(logcat,regex)1430 TEST(logcat, regex) {
1431 FILE* fp;
1432 logcat_define(ctx);
1433 int count = 0;
1434
1435 char buffer[BIG_BUFFER];
1436 #define logcat_regex_prefix ___STRING(logcat) "_test"
1437
1438 snprintf(buffer, sizeof(buffer),
1439 logcat_executable " --pid %d -d -e " logcat_regex_prefix "_a+b",
1440 getpid());
1441
1442 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix,
1443 logcat_regex_prefix "_ab"));
1444 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix,
1445 logcat_regex_prefix "_b"));
1446 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix,
1447 logcat_regex_prefix "_aaaab"));
1448 LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, logcat_regex_prefix,
1449 logcat_regex_prefix "_aaaa"));
1450 // Let the logs settle
1451 rest();
1452
1453 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer)));
1454
1455 while (fgets(buffer, sizeof(buffer), fp)) {
1456 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
1457 continue;
1458 }
1459
1460 EXPECT_TRUE(strstr(buffer, logcat_regex_prefix "_") != NULL);
1461
1462 count++;
1463 }
1464
1465 logcat_pclose(ctx, fp);
1466
1467 ASSERT_EQ(2, count);
1468 }
1469
TEST(logcat,maxcount)1470 TEST(logcat, maxcount) {
1471 FILE* fp;
1472 logcat_define(ctx);
1473 int count = 0;
1474
1475 char buffer[BIG_BUFFER];
1476
1477 snprintf(buffer, sizeof(buffer),
1478 logcat_executable " --pid %d -d --max-count 3", getpid());
1479
1480 LOG_FAILURE_RETRY(
1481 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
1482 LOG_FAILURE_RETRY(
1483 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
1484 LOG_FAILURE_RETRY(
1485 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
1486 LOG_FAILURE_RETRY(
1487 __android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
1488
1489 rest();
1490
1491 ASSERT_TRUE(NULL != (fp = logcat_popen(ctx, buffer)));
1492
1493 while (fgets(buffer, sizeof(buffer), fp)) {
1494 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
1495 continue;
1496 }
1497
1498 count++;
1499 }
1500
1501 logcat_pclose(ctx, fp);
1502
1503 ASSERT_EQ(3, count);
1504 }
1505
1506 static bool End_to_End(const char* tag, const char* fmt, ...)
1507 #if defined(__GNUC__)
1508 __attribute__((__format__(printf, 2, 3)))
1509 #endif
1510 ;
1511
End_to_End(const char * tag,const char * fmt,...)1512 static bool End_to_End(const char* tag, const char* fmt, ...) {
1513 logcat_define(ctx);
1514 FILE* fp = logcat_popen(ctx, logcat_executable
1515 " -v brief"
1516 " -b events"
1517 " -v descriptive"
1518 " -t 100"
1519 " 2>/dev/null");
1520 if (!fp) {
1521 fprintf(stderr, "End_to_End: popen failed");
1522 return false;
1523 }
1524
1525 char buffer[BIG_BUFFER];
1526 va_list ap;
1527
1528 va_start(ap, fmt);
1529 vsnprintf(buffer, sizeof(buffer), fmt, ap);
1530 va_end(ap);
1531
1532 char* str = NULL;
1533 asprintf(&str, "I/%s ( %%d):%%c%s%%c", tag, buffer);
1534 std::string expect(str);
1535 free(str);
1536
1537 int count = 0;
1538 pid_t pid = getpid();
1539 std::string lastMatch;
1540 int maxMatch = 1;
1541 while (fgets(buffer, sizeof(buffer), fp)) {
1542 char space;
1543 char newline;
1544 int p;
1545 int ret = sscanf(buffer, expect.c_str(), &p, &space, &newline);
1546 if ((ret == 3) && (p == pid) && (space == ' ') && (newline == '\n')) {
1547 ++count;
1548 } else if ((ret >= maxMatch) && (p == pid) && (count == 0)) {
1549 lastMatch = buffer;
1550 maxMatch = ret;
1551 }
1552 }
1553
1554 logcat_pclose(ctx, fp);
1555
1556 if ((count == 0) && (lastMatch.length() > 0)) {
1557 // Help us pinpoint where things went wrong ...
1558 fprintf(stderr, "Closest match for\n %s\n is\n %s",
1559 expect.c_str(), lastMatch.c_str());
1560 } else if (count > 3) {
1561 fprintf(stderr, "Too many matches (%d) for %s\n", count, expect.c_str());
1562 }
1563
1564 // Three different known tests, we can see pollution from the others
1565 return count && (count <= 3);
1566 }
1567
TEST(logcat,descriptive)1568 TEST(logcat, descriptive) {
1569 struct tag {
1570 uint32_t tagNo;
1571 const char* tagStr;
1572 };
1573 int ret;
1574
1575 {
1576 static const struct tag hhgtg = { 42, "answer" };
1577 android_log_event_list ctx(hhgtg.tagNo);
1578 static const char theAnswer[] = "what is five by seven";
1579 ctx << theAnswer;
1580 // crafted to rest at least once after, and rest between retries.
1581 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1582 EXPECT_GE(ret, 0);
1583 EXPECT_TRUE(
1584 End_to_End(hhgtg.tagStr, "to life the universe etc=%s", theAnswer));
1585 }
1586
1587 {
1588 static const struct tag sync = { 2720, "sync" };
1589 static const char id[] = ___STRING(logcat) ".descriptive-sync";
1590 {
1591 android_log_event_list ctx(sync.tagNo);
1592 ctx << id << (int32_t)42 << (int32_t)-1 << (int32_t)0;
1593 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1594 EXPECT_GE(ret, 0);
1595 EXPECT_TRUE(End_to_End(sync.tagStr,
1596 "[id=%s,event=42,source=-1,account=0]", id));
1597 }
1598
1599 // Partial match to description
1600 {
1601 android_log_event_list ctx(sync.tagNo);
1602 ctx << id << (int32_t)43 << (int64_t)-1 << (int32_t)0;
1603 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1604 EXPECT_GE(ret, 0);
1605 EXPECT_TRUE(End_to_End(sync.tagStr, "[id=%s,event=43,-1,0]", id));
1606 }
1607
1608 // Negative Test of End_to_End, ensure it is working
1609 {
1610 android_log_event_list ctx(sync.tagNo);
1611 ctx << id << (int32_t)44 << (int32_t)-1 << (int64_t)0;
1612 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1613 EXPECT_GE(ret, 0);
1614 fprintf(stderr, "Expect a \"Closest match\" message\n");
1615 EXPECT_FALSE(End_to_End(
1616 sync.tagStr, "[id=%s,event=44,source=-1,account=0]", id));
1617 }
1618 }
1619
1620 {
1621 static const struct tag sync = { 2747, "contacts_aggregation" };
1622 {
1623 android_log_event_list ctx(sync.tagNo);
1624 ctx << (uint64_t)30 << (int32_t)2;
1625 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1626 EXPECT_GE(ret, 0);
1627 EXPECT_TRUE(
1628 End_to_End(sync.tagStr, "[aggregation time=30ms,count=2]"));
1629 }
1630
1631 {
1632 android_log_event_list ctx(sync.tagNo);
1633 ctx << (uint64_t)31570 << (int32_t)911;
1634 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1635 EXPECT_GE(ret, 0);
1636 EXPECT_TRUE(
1637 End_to_End(sync.tagStr, "[aggregation time=31.57s,count=911]"));
1638 }
1639 }
1640
1641 {
1642 static const struct tag sync = { 75000, "sqlite_mem_alarm_current" };
1643 {
1644 android_log_event_list ctx(sync.tagNo);
1645 ctx << (uint32_t)512;
1646 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1647 EXPECT_GE(ret, 0);
1648 EXPECT_TRUE(End_to_End(sync.tagStr, "current=512B"));
1649 }
1650
1651 {
1652 android_log_event_list ctx(sync.tagNo);
1653 ctx << (uint32_t)3072;
1654 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1655 EXPECT_GE(ret, 0);
1656 EXPECT_TRUE(End_to_End(sync.tagStr, "current=3KB"));
1657 }
1658
1659 {
1660 android_log_event_list ctx(sync.tagNo);
1661 ctx << (uint32_t)2097152;
1662 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1663 EXPECT_GE(ret, 0);
1664 EXPECT_TRUE(End_to_End(sync.tagStr, "current=2MB"));
1665 }
1666
1667 {
1668 android_log_event_list ctx(sync.tagNo);
1669 ctx << (uint32_t)2097153;
1670 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1671 EXPECT_GE(ret, 0);
1672 EXPECT_TRUE(End_to_End(sync.tagStr, "current=2097153B"));
1673 }
1674
1675 {
1676 android_log_event_list ctx(sync.tagNo);
1677 ctx << (uint32_t)1073741824;
1678 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1679 EXPECT_GE(ret, 0);
1680 EXPECT_TRUE(End_to_End(sync.tagStr, "current=1GB"));
1681 }
1682
1683 {
1684 android_log_event_list ctx(sync.tagNo);
1685 ctx << (uint32_t)3221225472; // 3MB, but on purpose overflowed
1686 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1687 EXPECT_GE(ret, 0);
1688 EXPECT_TRUE(End_to_End(sync.tagStr, "current=-1GB"));
1689 }
1690 }
1691
1692 {
1693 static const struct tag sync = { 27501, "notification_panel_hidden" };
1694 android_log_event_list ctx(sync.tagNo);
1695 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1696 EXPECT_GE(ret, 0);
1697 EXPECT_TRUE(End_to_End(sync.tagStr, ""));
1698 }
1699
1700 {
1701 // Invent new entries because existing can not serve
1702 EventTagMap* map = android_openEventTagMap(nullptr);
1703 ASSERT_TRUE(nullptr != map);
1704 static const char name[] = ___STRING(logcat) ".descriptive-monotonic";
1705 int myTag = android_lookupEventTagNum(map, name, "(new|1|s)",
1706 ANDROID_LOG_UNKNOWN);
1707 android_closeEventTagMap(map);
1708 ASSERT_NE(-1, myTag);
1709
1710 const struct tag sync = { (uint32_t)myTag, name };
1711
1712 {
1713 android_log_event_list ctx(sync.tagNo);
1714 ctx << (uint32_t)7;
1715 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1716 EXPECT_GE(ret, 0);
1717 EXPECT_TRUE(End_to_End(sync.tagStr, "new=7s"));
1718 }
1719 {
1720 android_log_event_list ctx(sync.tagNo);
1721 ctx << (uint32_t)62;
1722 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1723 EXPECT_GE(ret, 0);
1724 EXPECT_TRUE(End_to_End(sync.tagStr, "new=1:02"));
1725 }
1726 {
1727 android_log_event_list ctx(sync.tagNo);
1728 ctx << (uint32_t)3673;
1729 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1730 EXPECT_GE(ret, 0);
1731 EXPECT_TRUE(End_to_End(sync.tagStr, "new=1:01:13"));
1732 }
1733 {
1734 android_log_event_list ctx(sync.tagNo);
1735 ctx << (uint32_t)(86400 + 7200 + 180 + 58);
1736 for (ret = -EBUSY; ret == -EBUSY; rest()) ret = ctx.write();
1737 EXPECT_GE(ret, 0);
1738 EXPECT_TRUE(End_to_End(sync.tagStr, "new=1d 2:03:58"));
1739 }
1740 }
1741 }
1742
reportedSecurity(const char * command)1743 static bool reportedSecurity(const char* command) {
1744 logcat_define(ctx);
1745 FILE* fp = logcat_popen(ctx, command);
1746 if (!fp) return true;
1747
1748 std::string ret;
1749 bool val = android::base::ReadFdToString(fileno(fp), &ret);
1750 logcat_pclose(ctx, fp);
1751
1752 if (!val) return true;
1753 return std::string::npos != ret.find("'security'");
1754 }
1755
TEST(logcat,security)1756 TEST(logcat, security) {
1757 EXPECT_FALSE(reportedSecurity(logcat_executable " -b all -g 2>&1"));
1758 EXPECT_TRUE(reportedSecurity(logcat_executable " -b security -g 2>&1"));
1759 EXPECT_TRUE(reportedSecurity(logcat_executable " -b security -c 2>&1"));
1760 EXPECT_TRUE(
1761 reportedSecurity(logcat_executable " -b security -G 256K 2>&1"));
1762 }
1763
commandOutputSize(const char * command)1764 static size_t commandOutputSize(const char* command) {
1765 logcat_define(ctx);
1766 FILE* fp = logcat_popen(ctx, command);
1767 if (!fp) return 0;
1768
1769 std::string ret;
1770 if (!android::base::ReadFdToString(fileno(fp), &ret)) return 0;
1771 if (logcat_pclose(ctx, fp) != 0) return 0;
1772
1773 return ret.size();
1774 }
1775
TEST(logcat,help)1776 TEST(logcat, help) {
1777 size_t logcatHelpTextSize = commandOutputSize(logcat_executable " -h 2>&1");
1778 EXPECT_GT(logcatHelpTextSize, 4096UL);
1779 size_t logcatLastHelpTextSize =
1780 commandOutputSize(logcat_executable " -L -h 2>&1");
1781 #ifdef USING_LOGCAT_EXECUTABLE_DEFAULT // logcat and liblogcat
1782 EXPECT_EQ(logcatHelpTextSize, logcatLastHelpTextSize);
1783 #else
1784 // logcatd -L -h prints the help twice, as designed.
1785 EXPECT_EQ(logcatHelpTextSize * 2, logcatLastHelpTextSize);
1786 #endif
1787 }
1788