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