liblog_test.cpp revision 7e2f83c0bcc3ad8a2840a48be14d302ed79d671c 
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 <fcntl.h>
18#include <inttypes.h>
19#include <signal.h>
20#include <gtest/gtest.h>
21#include <log/log.h>
22#include <log/logger.h>
23#include <log/log_read.h>
24
25// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
26// non-syscall libs. Since we are only using this in the emergency of
27// a signal to stuff a terminating code into the logs, we will spin rather
28// than try a usleep.
29#define LOG_FAILURE_RETRY(exp) ({  \
30    typeof (exp) _rc;              \
31    do {                           \
32        _rc = (exp);               \
33    } while (((_rc == -1)          \
34           && ((errno == EINTR)    \
35            || (errno == EAGAIN))) \
36          || (_rc == -EINTR)       \
37          || (_rc == -EAGAIN));    \
38    _rc; })
39
40TEST(liblog, __android_log_buf_print) {
41    ASSERT_LT(0, __android_log_buf_print(LOG_ID_RADIO, ANDROID_LOG_INFO,
42                                         "TEST__android_log_buf_print",
43                                         "radio"));
44    usleep(1000);
45    ASSERT_LT(0, __android_log_buf_print(LOG_ID_SYSTEM, ANDROID_LOG_INFO,
46                                         "TEST__android_log_buf_print",
47                                         "system"));
48    usleep(1000);
49    ASSERT_LT(0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO,
50                                         "TEST__android_log_buf_print",
51                                         "main"));
52    usleep(1000);
53}
54
55TEST(liblog, __android_log_buf_write) {
56    ASSERT_LT(0, __android_log_buf_write(LOG_ID_RADIO, ANDROID_LOG_INFO,
57                                         "TEST__android_log_buf_write",
58                                         "radio"));
59    usleep(1000);
60    ASSERT_LT(0, __android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO,
61                                         "TEST__android_log_buf_write",
62                                         "system"));
63    usleep(1000);
64    ASSERT_LT(0, __android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO,
65                                         "TEST__android_log_buf_write",
66                                         "main"));
67    usleep(1000);
68}
69
70TEST(liblog, __android_log_btwrite) {
71    int intBuf = 0xDEADBEEF;
72    ASSERT_LT(0, __android_log_btwrite(0,
73                                      EVENT_TYPE_INT,
74                                      &intBuf, sizeof(intBuf)));
75    long long longBuf = 0xDEADBEEFA55A5AA5;
76    ASSERT_LT(0, __android_log_btwrite(0,
77                                      EVENT_TYPE_LONG,
78                                      &longBuf, sizeof(longBuf)));
79    usleep(1000);
80    char Buf[] = "\20\0\0\0DeAdBeEfA55a5aA5";
81    ASSERT_LT(0, __android_log_btwrite(0,
82                                      EVENT_TYPE_STRING,
83                                      Buf, sizeof(Buf) - 1));
84    usleep(1000);
85}
86
87static void* ConcurrentPrintFn(void *arg) {
88    int ret = __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO,
89                                  "TEST__android_log_print", "Concurrent %" PRIuPTR,
90                                  reinterpret_cast<uintptr_t>(arg));
91    return reinterpret_cast<void*>(ret);
92}
93
94#define NUM_CONCURRENT 64
95#define _concurrent_name(a,n) a##__concurrent##n
96#define concurrent_name(a,n) _concurrent_name(a,n)
97
98TEST(liblog, concurrent_name(__android_log_buf_print, NUM_CONCURRENT)) {
99    pthread_t t[NUM_CONCURRENT];
100    int i;
101    for (i=0; i < NUM_CONCURRENT; i++) {
102        ASSERT_EQ(0, pthread_create(&t[i], NULL,
103                                    ConcurrentPrintFn,
104                                    reinterpret_cast<void *>(i)));
105    }
106    int ret = 0;
107    for (i=0; i < NUM_CONCURRENT; i++) {
108        void* result;
109        ASSERT_EQ(0, pthread_join(t[i], &result));
110        int this_result = reinterpret_cast<uintptr_t>(result);
111        if ((0 == ret) && (0 != this_result)) {
112            ret = this_result;
113        }
114    }
115    ASSERT_LT(0, ret);
116}
117
118TEST(liblog, __android_log_btwrite__android_logger_list_read) {
119    struct logger_list *logger_list;
120
121    pid_t pid = getpid();
122
123    ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open(
124        LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid)));
125
126    log_time ts(CLOCK_MONOTONIC);
127
128    ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
129    usleep(1000000);
130
131    int count = 0;
132
133    for (;;) {
134        log_msg log_msg;
135        if (android_logger_list_read(logger_list, &log_msg) <= 0) {
136            break;
137        }
138
139        ASSERT_EQ(log_msg.entry.pid, pid);
140
141        if ((log_msg.entry.len != (4 + 1 + 8))
142         || (log_msg.id() != LOG_ID_EVENTS)) {
143            continue;
144        }
145
146        char *eventData = log_msg.msg();
147
148        if (eventData[4] != EVENT_TYPE_LONG) {
149            continue;
150        }
151
152        log_time tx(eventData + 4 + 1);
153        if (ts == tx) {
154            ++count;
155        }
156    }
157
158    ASSERT_EQ(1, count);
159
160    android_logger_list_close(logger_list);
161}
162
163static unsigned signaled;
164log_time signal_time;
165
166static void caught_blocking(int signum)
167{
168    unsigned long long v = 0xDEADBEEFA55A0000ULL;
169
170    v += getpid() & 0xFFFF;
171
172    ++signaled;
173    if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) {
174        signal_time = log_time(CLOCK_MONOTONIC);
175        signal_time.tv_sec += 2;
176    }
177
178    LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
179}
180
181// Fill in current process user and system time in 10ms increments
182static void get_ticks(unsigned long long *uticks, unsigned long long *sticks)
183{
184    *uticks = *sticks = 0;
185
186    pid_t pid = getpid();
187
188    char buffer[512];
189    snprintf(buffer, sizeof(buffer), "/proc/%u/stat", pid);
190
191    FILE *fp = fopen(buffer, "r");
192    if (!fp) {
193        return;
194    }
195
196    char *cp = fgets(buffer, sizeof(buffer), fp);
197    fclose(fp);
198    if (!cp) {
199        return;
200    }
201
202    pid_t d;
203    char s[sizeof(buffer)];
204    char c;
205    long long ll;
206    unsigned long long ull;
207
208    if (15 != sscanf(buffer,
209      "%d %s %c %lld %lld %lld %lld %lld %llu %llu %llu %llu %llu %llu %llu ",
210      &d, s, &c, &ll, &ll, &ll, &ll, &ll, &ull, &ull, &ull, &ull, &ull,
211      uticks, sticks)) {
212        *uticks = *sticks = 0;
213    }
214}
215
216TEST(liblog, android_logger_list_read__cpu) {
217    struct logger_list *logger_list;
218    unsigned long long v = 0xDEADBEEFA55A0000ULL;
219
220    pid_t pid = getpid();
221
222    v += pid & 0xFFFF;
223
224    ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open(
225        LOG_ID_EVENTS, O_RDONLY, 1000, pid)));
226
227    int count = 0;
228
229    int signals = 0;
230
231    unsigned long long uticks_start;
232    unsigned long long sticks_start;
233    get_ticks(&uticks_start, &sticks_start);
234
235    const unsigned alarm_time = 10;
236
237    memset(&signal_time, 0, sizeof(signal_time));
238
239    signal(SIGALRM, caught_blocking);
240    alarm(alarm_time);
241
242    signaled = 0;
243
244    do {
245        log_msg log_msg;
246        if (android_logger_list_read(logger_list, &log_msg) <= 0) {
247            break;
248        }
249
250        alarm(alarm_time);
251
252        ++count;
253
254        ASSERT_EQ(log_msg.entry.pid, pid);
255
256        if ((log_msg.entry.len != (4 + 1 + 8))
257         || (log_msg.id() != LOG_ID_EVENTS)) {
258            continue;
259        }
260
261        char *eventData = log_msg.msg();
262
263        if (eventData[4] != EVENT_TYPE_LONG) {
264            continue;
265        }
266
267        unsigned long long l = eventData[4 + 1 + 0] & 0xFF;
268        l |= (unsigned long long) (eventData[4 + 1 + 1] & 0xFF) << 8;
269        l |= (unsigned long long) (eventData[4 + 1 + 2] & 0xFF) << 16;
270        l |= (unsigned long long) (eventData[4 + 1 + 3] & 0xFF) << 24;
271        l |= (unsigned long long) (eventData[4 + 1 + 4] & 0xFF) << 32;
272        l |= (unsigned long long) (eventData[4 + 1 + 5] & 0xFF) << 40;
273        l |= (unsigned long long) (eventData[4 + 1 + 6] & 0xFF) << 48;
274        l |= (unsigned long long) (eventData[4 + 1 + 7] & 0xFF) << 56;
275
276        if (l == v) {
277            ++signals;
278            break;
279        }
280    } while (!signaled || ({log_time t(CLOCK_MONOTONIC); t < signal_time;}));
281    alarm(0);
282    signal(SIGALRM, SIG_DFL);
283
284    ASSERT_LT(1, count);
285
286    ASSERT_EQ(1, signals);
287
288    android_logger_list_close(logger_list);
289
290    unsigned long long uticks_end;
291    unsigned long long sticks_end;
292    get_ticks(&uticks_end, &sticks_end);
293
294    // Less than 1% in either user or system time, or both
295    const unsigned long long one_percent_ticks = alarm_time;
296    unsigned long long user_ticks = uticks_end - uticks_start;
297    unsigned long long system_ticks = sticks_end - sticks_start;
298    ASSERT_GT(one_percent_ticks, user_ticks);
299    ASSERT_GT(one_percent_ticks, system_ticks);
300    ASSERT_GT(one_percent_ticks, user_ticks + system_ticks);
301}
302
303TEST(liblog, android_logger_get_) {
304    struct logger_list * logger_list = android_logger_list_alloc(O_WRONLY, 0, 0);
305
306    for(int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) {
307        log_id_t id = static_cast<log_id_t>(i);
308        const char *name = android_log_id_to_name(id);
309        if (id != android_name_to_log_id(name)) {
310            continue;
311        }
312        struct logger * logger;
313        ASSERT_EQ(0, NULL == (logger = android_logger_open(logger_list, id)));
314        ASSERT_EQ(id, android_logger_get_id(logger));
315        ASSERT_LT(0, android_logger_get_log_size(logger));
316        ASSERT_LT(0, android_logger_get_log_readable_size(logger));
317        ASSERT_LT(0, android_logger_get_log_version(logger));
318    }
319
320    android_logger_list_close(logger_list);
321}
322