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