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