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