logcat_test.cpp revision 5d3d1f17dbcb01aedd510b5435ebdaf1d6afc138 
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 = 0xDEADBEEFA55A0000ULL;
323
324    pid_t pid = getpid();
325
326    v += pid & 0xFFFF;
327
328    ASSERT_EQ(0, NULL == (fp = popen(
329      "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
330      " logcat -b events 2>&1",
331      "r")));
332
333    char buffer[5120];
334
335    int count = 0;
336
337    int signals = 0;
338
339    signal(SIGALRM, caught_blocking);
340    alarm(2);
341    while (fgets(buffer, sizeof(buffer), fp)) {
342        alarm(2);
343
344        ++count;
345
346        if (!strncmp(buffer, "DONE", 4)) {
347            break;
348        }
349
350        int p;
351        unsigned long long l;
352
353        if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
354         || (p != pid)) {
355            continue;
356        }
357
358        if (l == v) {
359            ++signals;
360            break;
361        }
362    }
363    alarm(0);
364    signal(SIGALRM, SIG_DFL);
365
366    // Generate SIGPIPE
367    fclose(fp);
368    caught_blocking(0);
369
370    pclose(fp);
371
372    ASSERT_LT(10, count);
373
374    ASSERT_EQ(1, signals);
375}
376
377static void caught_blocking_tail(int signum)
378{
379    unsigned long long v = 0xA55ADEADBEEF0000ULL;
380
381    v += getpid() & 0xFFFF;
382
383    LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
384}
385
386TEST(logcat, blocking_tail) {
387    FILE *fp;
388    unsigned long long v = 0xA55ADEADBEEF0000ULL;
389
390    pid_t pid = getpid();
391
392    v += pid & 0xFFFF;
393
394    ASSERT_EQ(0, NULL == (fp = popen(
395      "( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
396      " logcat -b events -T 5 2>&1",
397      "r")));
398
399    char buffer[5120];
400
401    int count = 0;
402
403    int signals = 0;
404
405    signal(SIGALRM, caught_blocking_tail);
406    alarm(2);
407    while (fgets(buffer, sizeof(buffer), fp)) {
408        alarm(2);
409
410        ++count;
411
412        if (!strncmp(buffer, "DONE", 4)) {
413            break;
414        }
415
416        int p;
417        unsigned long long l;
418
419        if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
420         || (p != pid)) {
421            continue;
422        }
423
424        if (l == v) {
425            if (count >= 5) {
426                ++signals;
427            }
428            break;
429        }
430    }
431    alarm(0);
432    signal(SIGALRM, SIG_DFL);
433
434    /* Generate SIGPIPE */
435    fclose(fp);
436    caught_blocking_tail(0);
437
438    pclose(fp);
439
440    ASSERT_LT(5, count);
441
442    ASSERT_EQ(1, signals);
443}
444