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