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 <signal.h>
19 #include <stdio.h>
20 #include <stdlib.h>
21 #include <string.h>
22
23 #include <gtest/gtest.h>
24 #include <log/log.h>
25 #include <log/logger.h>
26 #include <log/log_read.h>
27
28 // enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
29 // non-syscall libs. Since we are only using this in the emergency of
30 // a signal to stuff a terminating code into the logs, we will spin rather
31 // than try a usleep.
32 #define LOG_FAILURE_RETRY(exp) ({ \
33 typeof (exp) _rc; \
34 do { \
35 _rc = (exp); \
36 } while (((_rc == -1) \
37 && ((errno == EINTR) \
38 || (errno == EAGAIN))) \
39 || (_rc == -EINTR) \
40 || (_rc == -EAGAIN)); \
41 _rc; })
42
43 static const char begin[] = "--------- beginning of ";
44
TEST(logcat,buckets)45 TEST(logcat, buckets) {
46 FILE *fp;
47
48 ASSERT_TRUE(NULL != (fp = popen(
49 "logcat -b radio -b events -b system -b main -d 2>/dev/null",
50 "r")));
51
52 char buffer[5120];
53
54 int ids = 0;
55 int count = 0;
56
57 while (fgets(buffer, sizeof(buffer), fp)) {
58 if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
59 while (char *cp = strrchr(buffer, '\n')) {
60 *cp = '\0';
61 }
62 log_id_t id = android_name_to_log_id(buffer + sizeof(begin) - 1);
63 ids |= 1 << id;
64 ++count;
65 }
66 }
67
68 pclose(fp);
69
70 EXPECT_EQ(15, ids);
71
72 EXPECT_EQ(4, count);
73 }
74
TEST(logcat,tail_3)75 TEST(logcat, tail_3) {
76 FILE *fp;
77
78 ASSERT_TRUE(NULL != (fp = popen(
79 "logcat -v long -b radio -b events -b system -b main -t 3 2>/dev/null",
80 "r")));
81
82 char buffer[5120];
83
84 int count = 0;
85
86 while (fgets(buffer, sizeof(buffer), fp)) {
87 if ((buffer[0] == '[') && (buffer[1] == ' ')
88 && isdigit(buffer[2]) && isdigit(buffer[3])
89 && (buffer[4] == '-')) {
90 ++count;
91 }
92 }
93
94 pclose(fp);
95
96 ASSERT_EQ(3, count);
97 }
98
TEST(logcat,tail_10)99 TEST(logcat, tail_10) {
100 FILE *fp;
101
102 ASSERT_TRUE(NULL != (fp = popen(
103 "logcat -v long -b radio -b events -b system -b main -t 10 2>/dev/null",
104 "r")));
105
106 char buffer[5120];
107
108 int count = 0;
109
110 while (fgets(buffer, sizeof(buffer), fp)) {
111 if ((buffer[0] == '[') && (buffer[1] == ' ')
112 && isdigit(buffer[2]) && isdigit(buffer[3])
113 && (buffer[4] == '-')) {
114 ++count;
115 }
116 }
117
118 pclose(fp);
119
120 ASSERT_EQ(10, count);
121 }
122
TEST(logcat,tail_100)123 TEST(logcat, tail_100) {
124 FILE *fp;
125
126 ASSERT_TRUE(NULL != (fp = popen(
127 "logcat -v long -b radio -b events -b system -b main -t 100 2>/dev/null",
128 "r")));
129
130 char buffer[5120];
131
132 int count = 0;
133
134 while (fgets(buffer, sizeof(buffer), fp)) {
135 if ((buffer[0] == '[') && (buffer[1] == ' ')
136 && isdigit(buffer[2]) && isdigit(buffer[3])
137 && (buffer[4] == '-')) {
138 ++count;
139 }
140 }
141
142 pclose(fp);
143
144 ASSERT_EQ(100, count);
145 }
146
TEST(logcat,tail_1000)147 TEST(logcat, tail_1000) {
148 FILE *fp;
149
150 ASSERT_TRUE(NULL != (fp = popen(
151 "logcat -v long -b radio -b events -b system -b main -t 1000 2>/dev/null",
152 "r")));
153
154 char buffer[5120];
155
156 int count = 0;
157
158 while (fgets(buffer, sizeof(buffer), fp)) {
159 if ((buffer[0] == '[') && (buffer[1] == ' ')
160 && isdigit(buffer[2]) && isdigit(buffer[3])
161 && (buffer[4] == '-')) {
162 ++count;
163 }
164 }
165
166 pclose(fp);
167
168 ASSERT_EQ(1000, count);
169 }
170
TEST(logcat,tail_time)171 TEST(logcat, tail_time) {
172 FILE *fp;
173
174 ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r")));
175
176 char buffer[5120];
177 char *last_timestamp = NULL;
178 char *first_timestamp = NULL;
179 int count = 0;
180 const unsigned int time_length = 18;
181 const unsigned int time_offset = 2;
182
183 while (fgets(buffer, sizeof(buffer), fp)) {
184 if ((buffer[0] == '[') && (buffer[1] == ' ')
185 && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1])
186 && (buffer[time_offset + 2] == '-')) {
187 ++count;
188 buffer[time_length + time_offset] = '\0';
189 if (!first_timestamp) {
190 first_timestamp = strdup(buffer + time_offset);
191 }
192 free(last_timestamp);
193 last_timestamp = strdup(buffer + time_offset);
194 }
195 }
196 pclose(fp);
197
198 EXPECT_EQ(10, count);
199 EXPECT_TRUE(last_timestamp != NULL);
200 EXPECT_TRUE(first_timestamp != NULL);
201
202 snprintf(buffer, sizeof(buffer), "logcat -v long -b all -t '%s' 2>&1",
203 first_timestamp);
204 ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
205
206 int second_count = 0;
207 int last_timestamp_count = -1;
208
209 while (fgets(buffer, sizeof(buffer), fp)) {
210 if ((buffer[0] == '[') && (buffer[1] == ' ')
211 && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1])
212 && (buffer[time_offset + 2] == '-')) {
213 ++second_count;
214 buffer[time_length + time_offset] = '\0';
215 if (first_timestamp) {
216 // we can get a transitory *extremely* rare failure if hidden
217 // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000
218 EXPECT_STREQ(buffer + time_offset, first_timestamp);
219 free(first_timestamp);
220 first_timestamp = NULL;
221 }
222 if (!strcmp(buffer + time_offset, last_timestamp)) {
223 last_timestamp_count = second_count;
224 }
225 }
226 }
227 pclose(fp);
228
229 free(last_timestamp);
230 last_timestamp = NULL;
231
232 EXPECT_TRUE(first_timestamp == NULL);
233 EXPECT_LE(count, second_count);
234 EXPECT_LE(count, last_timestamp_count);
235 }
236
TEST(logcat,End_to_End)237 TEST(logcat, End_to_End) {
238 pid_t pid = getpid();
239
240 log_time ts(CLOCK_MONOTONIC);
241
242 ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
243
244 FILE *fp;
245 ASSERT_TRUE(NULL != (fp = popen(
246 "logcat -b events -t 100 2>/dev/null",
247 "r")));
248
249 char buffer[5120];
250
251 int count = 0;
252
253 while (fgets(buffer, sizeof(buffer), fp)) {
254 int p;
255 unsigned long long t;
256
257 if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t))
258 || (p != pid)) {
259 continue;
260 }
261
262 log_time tx((const char *) &t);
263 if (ts == tx) {
264 ++count;
265 }
266 }
267
268 pclose(fp);
269
270 ASSERT_EQ(1, count);
271 }
272
TEST(logcat,get_size)273 TEST(logcat, get_size) {
274 FILE *fp;
275
276 // NB: crash log only available in user space
277 ASSERT_TRUE(NULL != (fp = popen(
278 "logcat -b radio -b events -b system -b main -g 2>/dev/null",
279 "r")));
280
281 char buffer[5120];
282
283 int count = 0;
284
285 while (fgets(buffer, sizeof(buffer), fp)) {
286 int size, consumed, max, payload;
287 char size_mult[2], consumed_mult[2];
288 long full_size, full_consumed;
289
290 size = consumed = max = payload = 0;
291 // NB: crash log can be very small, not hit a Kb of consumed space
292 // doubly lucky we are not including it.
293 if (6 != sscanf(buffer, "%*s ring buffer is %d%2s (%d%2s consumed),"
294 " max entry is %db, max payload is %db",
295 &size, size_mult, &consumed, consumed_mult,
296 &max, &payload)) {
297 fprintf(stderr, "WARNING: Parse error: %s", buffer);
298 continue;
299 }
300 full_size = size;
301 switch(size_mult[0]) {
302 case 'G':
303 full_size *= 1024;
304 /* FALLTHRU */
305 case 'M':
306 full_size *= 1024;
307 /* FALLTHRU */
308 case 'K':
309 full_size *= 1024;
310 /* FALLTHRU */
311 case 'b':
312 break;
313 }
314 full_consumed = consumed;
315 switch(consumed_mult[0]) {
316 case 'G':
317 full_consumed *= 1024;
318 /* FALLTHRU */
319 case 'M':
320 full_consumed *= 1024;
321 /* FALLTHRU */
322 case 'K':
323 full_consumed *= 1024;
324 /* FALLTHRU */
325 case 'b':
326 break;
327 }
328 EXPECT_GT((full_size * 9) / 4, full_consumed);
329 EXPECT_GT(full_size, max);
330 EXPECT_GT(max, payload);
331
332 if ((((full_size * 9) / 4) >= full_consumed)
333 && (full_size > max)
334 && (max > payload)) {
335 ++count;
336 }
337 }
338
339 pclose(fp);
340
341 ASSERT_EQ(4, count);
342 }
343
caught_blocking(int)344 static void caught_blocking(int /*signum*/)
345 {
346 unsigned long long v = 0xDEADBEEFA55A0000ULL;
347
348 v += getpid() & 0xFFFF;
349
350 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
351 }
352
TEST(logcat,blocking)353 TEST(logcat, blocking) {
354 FILE *fp;
355 unsigned long long v = 0xDEADBEEFA55F0000ULL;
356
357 pid_t pid = getpid();
358
359 v += pid & 0xFFFF;
360
361 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
362
363 v &= 0xFFFFFFFFFFFAFFFFULL;
364
365 ASSERT_TRUE(NULL != (fp = popen(
366 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
367 " logcat -b events 2>&1",
368 "r")));
369
370 char buffer[5120];
371
372 int count = 0;
373
374 int signals = 0;
375
376 signal(SIGALRM, caught_blocking);
377 alarm(2);
378 while (fgets(buffer, sizeof(buffer), fp)) {
379
380 if (!strncmp(buffer, "DONE", 4)) {
381 break;
382 }
383
384 ++count;
385
386 int p;
387 unsigned long long l;
388
389 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
390 || (p != pid)) {
391 continue;
392 }
393
394 if (l == v) {
395 ++signals;
396 break;
397 }
398 }
399 alarm(0);
400 signal(SIGALRM, SIG_DFL);
401
402 // Generate SIGPIPE
403 fclose(fp);
404 caught_blocking(0);
405
406 pclose(fp);
407
408 EXPECT_LE(2, count);
409
410 EXPECT_EQ(1, signals);
411 }
412
caught_blocking_tail(int)413 static void caught_blocking_tail(int /*signum*/)
414 {
415 unsigned long long v = 0xA55ADEADBEEF0000ULL;
416
417 v += getpid() & 0xFFFF;
418
419 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
420 }
421
TEST(logcat,blocking_tail)422 TEST(logcat, blocking_tail) {
423 FILE *fp;
424 unsigned long long v = 0xA55FDEADBEEF0000ULL;
425
426 pid_t pid = getpid();
427
428 v += pid & 0xFFFF;
429
430 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
431
432 v &= 0xFFFAFFFFFFFFFFFFULL;
433
434 ASSERT_TRUE(NULL != (fp = popen(
435 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
436 " logcat -b events -T 5 2>&1",
437 "r")));
438
439 char buffer[5120];
440
441 int count = 0;
442
443 int signals = 0;
444
445 signal(SIGALRM, caught_blocking_tail);
446 alarm(2);
447 while (fgets(buffer, sizeof(buffer), fp)) {
448
449 if (!strncmp(buffer, "DONE", 4)) {
450 break;
451 }
452
453 ++count;
454
455 int p;
456 unsigned long long l;
457
458 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
459 || (p != pid)) {
460 continue;
461 }
462
463 if (l == v) {
464 if (count >= 5) {
465 ++signals;
466 }
467 break;
468 }
469 }
470 alarm(0);
471 signal(SIGALRM, SIG_DFL);
472
473 // Generate SIGPIPE
474 fclose(fp);
475 caught_blocking_tail(0);
476
477 pclose(fp);
478
479 EXPECT_LE(2, count);
480
481 EXPECT_EQ(1, signals);
482 }
483
TEST(logcat,logrotate)484 TEST(logcat, logrotate) {
485 static const char form[] = "/data/local/tmp/logcat.logrotate.XXXXXX";
486 char buf[sizeof(form)];
487 ASSERT_TRUE(NULL != mkdtemp(strcpy(buf, form)));
488
489 static const char comm[] = "logcat -b radio -b events -b system -b main"
490 " -d -f %s/log.txt -n 7 -r 1";
491 char command[sizeof(buf) + sizeof(comm)];
492 sprintf(command, comm, buf);
493
494 int ret;
495 EXPECT_FALSE((ret = system(command)));
496 if (!ret) {
497 sprintf(command, "ls -s %s 2>/dev/null", buf);
498
499 FILE *fp;
500 EXPECT_TRUE(NULL != (fp = popen(command, "r")));
501 if (fp) {
502 char buffer[5120];
503 int count = 0;
504
505 while (fgets(buffer, sizeof(buffer), fp)) {
506 static const char match[] = "4 log.txt";
507 static const char total[] = "total ";
508
509 if (!strncmp(buffer, match, sizeof(match) - 1)) {
510 ++count;
511 } else if (strncmp(buffer, total, sizeof(total) - 1)) {
512 fprintf(stderr, "WARNING: Parse error: %s", buffer);
513 }
514 }
515 pclose(fp);
516 EXPECT_TRUE(count == 7 || count == 8);
517 }
518 }
519 sprintf(command, "rm -rf %s", buf);
520 EXPECT_FALSE(system(command));
521 }
522
caught_blocking_clear(int)523 static void caught_blocking_clear(int /*signum*/)
524 {
525 unsigned long long v = 0xDEADBEEFA55C0000ULL;
526
527 v += getpid() & 0xFFFF;
528
529 LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
530 }
531
TEST(logcat,blocking_clear)532 TEST(logcat, blocking_clear) {
533 FILE *fp;
534 unsigned long long v = 0xDEADBEEFA55C0000ULL;
535
536 pid_t pid = getpid();
537
538 v += pid & 0xFFFF;
539
540 // This test is racey; an event occurs between clear and dump.
541 // We accept that we will get a false positive, but never a false negative.
542 ASSERT_TRUE(NULL != (fp = popen(
543 "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
544 " logcat -b events -c 2>&1 ;"
545 " logcat -b events 2>&1",
546 "r")));
547
548 char buffer[5120];
549
550 int count = 0;
551
552 int signals = 0;
553
554 signal(SIGALRM, caught_blocking_clear);
555 alarm(2);
556 while (fgets(buffer, sizeof(buffer), fp)) {
557
558 if (!strncmp(buffer, "clearLog: ", 10)) {
559 fprintf(stderr, "WARNING: Test lacks permission to run :-(\n");
560 count = signals = 1;
561 break;
562 }
563
564 if (!strncmp(buffer, "DONE", 4)) {
565 break;
566 }
567
568 ++count;
569
570 int p;
571 unsigned long long l;
572
573 if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
574 || (p != pid)) {
575 continue;
576 }
577
578 if (l == v) {
579 if (count > 1) {
580 fprintf(stderr, "WARNING: Possible false positive\n");
581 }
582 ++signals;
583 break;
584 }
585 }
586 alarm(0);
587 signal(SIGALRM, SIG_DFL);
588
589 // Generate SIGPIPE
590 fclose(fp);
591 caught_blocking_clear(0);
592
593 pclose(fp);
594
595 EXPECT_LE(1, count);
596
597 EXPECT_EQ(1, signals);
598 }
599
get_white_black(char ** list)600 static bool get_white_black(char **list) {
601 FILE *fp;
602
603 fp = popen("logcat -p 2>/dev/null", "r");
604 if (fp == NULL) {
605 fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n");
606 return false;
607 }
608
609 char buffer[5120];
610
611 while (fgets(buffer, sizeof(buffer), fp)) {
612 char *hold = *list;
613 char *buf = buffer;
614 while (isspace(*buf)) {
615 ++buf;
616 }
617 char *end = buf + strlen(buf);
618 while (isspace(*--end) && (end >= buf)) {
619 *end = '\0';
620 }
621 if (end < buf) {
622 continue;
623 }
624 if (hold) {
625 asprintf(list, "%s %s", hold, buf);
626 free(hold);
627 } else {
628 asprintf(list, "%s", buf);
629 }
630 }
631 pclose(fp);
632 return *list != NULL;
633 }
634
set_white_black(const char * list)635 static bool set_white_black(const char *list) {
636 FILE *fp;
637
638 char buffer[5120];
639
640 snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list ? list : "");
641 fp = popen(buffer, "r");
642 if (fp == NULL) {
643 fprintf(stderr, "ERROR: %s\n", buffer);
644 return false;
645 }
646
647 while (fgets(buffer, sizeof(buffer), fp)) {
648 char *buf = buffer;
649 while (isspace(*buf)) {
650 ++buf;
651 }
652 char *end = buf + strlen(buf);
653 while ((end > buf) && isspace(*--end)) {
654 *end = '\0';
655 }
656 if (end <= buf) {
657 continue;
658 }
659 fprintf(stderr, "%s\n", buf);
660 pclose(fp);
661 return false;
662 }
663 return pclose(fp) == 0;
664 }
665
TEST(logcat,white_black_adjust)666 TEST(logcat, white_black_adjust) {
667 char *list = NULL;
668 char *adjust = NULL;
669
670 get_white_black(&list);
671
672 static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30";
673 ASSERT_EQ(true, set_white_black(adjustment));
674 ASSERT_EQ(true, get_white_black(&adjust));
675 EXPECT_STREQ(adjustment, adjust);
676 free(adjust);
677 adjust = NULL;
678
679 static const char adjustment2[] = "300/20 300/21 2000 ~1000";
680 ASSERT_EQ(true, set_white_black(adjustment2));
681 ASSERT_EQ(true, get_white_black(&adjust));
682 EXPECT_STREQ(adjustment2, adjust);
683 free(adjust);
684 adjust = NULL;
685
686 ASSERT_EQ(true, set_white_black(list));
687 get_white_black(&adjust);
688 EXPECT_STREQ(list ? list : "", adjust ? adjust : "");
689 free(adjust);
690 adjust = NULL;
691
692 free(list);
693 list = NULL;
694 }
695