logcat_test.cpp revision a5e2429f09295dd94b0ae2125e380cfb3b02ab04 
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
43static const char begin[] = "--------- beginning of ";
44
45TEST(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
75TEST(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
99TEST(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
123TEST(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
147TEST(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
171TEST(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
237TEST(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 -v brief -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
273TEST(logcat, get_size) {
274    FILE *fp;
275
276    // NB: crash log only available in user space
277    ASSERT_TRUE(NULL != (fp = popen(
278      "logcat -v brief -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
344static 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
353TEST(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 -v brief -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
413static 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
422TEST(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 -v brief -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
484TEST(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_1[] = "4 log.txt";
507                static const char match_2[] = "8 log.txt";
508                static const char match_3[] = "16 log.txt";
509                static const char total[] = "total ";
510
511                if (!strncmp(buffer, match_1, sizeof(match_1) - 1)
512                 || !strncmp(buffer, match_2, sizeof(match_2) - 1)
513                 || !strncmp(buffer, match_3, sizeof(match_3) - 1)) {
514                    ++count;
515                } else if (strncmp(buffer, total, sizeof(total) - 1)) {
516                    fprintf(stderr, "WARNING: Parse error: %s", buffer);
517                }
518            }
519            pclose(fp);
520            EXPECT_TRUE(count == 7 || count == 8);
521        }
522    }
523    sprintf(command, "rm -rf %s", buf);
524    EXPECT_FALSE(system(command));
525}
526
527static void caught_blocking_clear(int /*signum*/)
528{
529    unsigned long long v = 0xDEADBEEFA55C0000ULL;
530
531    v += getpid() & 0xFFFF;
532
533    LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
534}
535
536TEST(logcat, blocking_clear) {
537    FILE *fp;
538    unsigned long long v = 0xDEADBEEFA55C0000ULL;
539
540    pid_t pid = getpid();
541
542    v += pid & 0xFFFF;
543
544    // This test is racey; an event occurs between clear and dump.
545    // We accept that we will get a false positive, but never a false negative.
546    ASSERT_TRUE(NULL != (fp = popen(
547      "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
548      " logcat -b events -c 2>&1 ;"
549      " logcat -v brief -b events 2>&1",
550      "r")));
551
552    char buffer[5120];
553
554    int count = 0;
555
556    int signals = 0;
557
558    signal(SIGALRM, caught_blocking_clear);
559    alarm(2);
560    while (fgets(buffer, sizeof(buffer), fp)) {
561
562        if (!strncmp(buffer, "clearLog: ", 10)) {
563            fprintf(stderr, "WARNING: Test lacks permission to run :-(\n");
564            count = signals = 1;
565            break;
566        }
567
568        if (!strncmp(buffer, "DONE", 4)) {
569            break;
570        }
571
572        ++count;
573
574        int p;
575        unsigned long long l;
576
577        if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
578         || (p != pid)) {
579            continue;
580        }
581
582        if (l == v) {
583            if (count > 1) {
584                fprintf(stderr, "WARNING: Possible false positive\n");
585            }
586            ++signals;
587            break;
588        }
589    }
590    alarm(0);
591    signal(SIGALRM, SIG_DFL);
592
593    // Generate SIGPIPE
594    fclose(fp);
595    caught_blocking_clear(0);
596
597    pclose(fp);
598
599    EXPECT_LE(1, count);
600
601    EXPECT_EQ(1, signals);
602}
603
604static bool get_white_black(char **list) {
605    FILE *fp;
606
607    fp = popen("logcat -p 2>/dev/null", "r");
608    if (fp == NULL) {
609        fprintf(stderr, "ERROR: logcat -p 2>/dev/null\n");
610        return false;
611    }
612
613    char buffer[5120];
614
615    while (fgets(buffer, sizeof(buffer), fp)) {
616        char *hold = *list;
617        char *buf = buffer;
618	while (isspace(*buf)) {
619            ++buf;
620        }
621        char *end = buf + strlen(buf);
622        while (isspace(*--end) && (end >= buf)) {
623            *end = '\0';
624        }
625        if (end < buf) {
626            continue;
627        }
628        if (hold) {
629            asprintf(list, "%s %s", hold, buf);
630            free(hold);
631        } else {
632            asprintf(list, "%s", buf);
633        }
634    }
635    pclose(fp);
636    return *list != NULL;
637}
638
639static bool set_white_black(const char *list) {
640    FILE *fp;
641
642    char buffer[5120];
643
644    snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list ? list : "");
645    fp = popen(buffer, "r");
646    if (fp == NULL) {
647        fprintf(stderr, "ERROR: %s\n", buffer);
648        return false;
649    }
650
651    while (fgets(buffer, sizeof(buffer), fp)) {
652        char *buf = buffer;
653	while (isspace(*buf)) {
654            ++buf;
655        }
656        char *end = buf + strlen(buf);
657        while ((end > buf) && isspace(*--end)) {
658            *end = '\0';
659        }
660        if (end <= buf) {
661            continue;
662        }
663        fprintf(stderr, "%s\n", buf);
664        pclose(fp);
665        return false;
666    }
667    return pclose(fp) == 0;
668}
669
670TEST(logcat, white_black_adjust) {
671    char *list = NULL;
672    char *adjust = NULL;
673
674    get_white_black(&list);
675
676    static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30";
677    ASSERT_EQ(true, set_white_black(adjustment));
678    ASSERT_EQ(true, get_white_black(&adjust));
679    EXPECT_STREQ(adjustment, adjust);
680    free(adjust);
681    adjust = NULL;
682
683    static const char adjustment2[] = "300/20 300/21 2000 ~1000";
684    ASSERT_EQ(true, set_white_black(adjustment2));
685    ASSERT_EQ(true, get_white_black(&adjust));
686    EXPECT_STREQ(adjustment2, adjust);
687    free(adjust);
688    adjust = NULL;
689
690    ASSERT_EQ(true, set_white_black(list));
691    get_white_black(&adjust);
692    EXPECT_STREQ(list ? list : "", adjust ? adjust : "");
693    free(adjust);
694    adjust = NULL;
695
696    free(list);
697    list = NULL;
698}
699