logd_test.cpp revision 62d6a2a921d5ee5cc455e6ae5e62d4ad2474fd25 
1/*
2 * Copyright (C) 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 <poll.h>
19#include <signal.h>
20#include <stdio.h>
21#include <string.h>
22
23#include <gtest/gtest.h>
24
25#include "cutils/sockets.h"
26#include "log/log.h"
27#include "log/logger.h"
28
29#define __unused __attribute__((__unused__))
30
31/*
32 * returns statistics
33 */
34static void my_android_logger_get_statistics(char *buf, size_t len)
35{
36    snprintf(buf, len, "getStatistics 0 1 2 3 4");
37    int sock = socket_local_client("logd",
38                                   ANDROID_SOCKET_NAMESPACE_RESERVED,
39                                   SOCK_STREAM);
40    if (sock >= 0) {
41        if (write(sock, buf, strlen(buf) + 1) > 0) {
42            ssize_t ret;
43            while ((ret = read(sock, buf, len)) > 0) {
44                if ((size_t)ret == len) {
45                    break;
46                }
47                len -= ret;
48                buf += ret;
49
50                struct pollfd p = {
51                    .fd = sock,
52                    .events = POLLIN,
53                    .revents = 0
54                };
55
56                ret = poll(&p, 1, 20);
57                if ((ret <= 0) || !(p.revents & POLLIN)) {
58                    break;
59                }
60            }
61        }
62        close(sock);
63    }
64}
65
66static void alloc_statistics(char **buffer, size_t *length)
67{
68    size_t len = 8192;
69    char *buf;
70
71    for(int retry = 32; (retry >= 0); delete [] buf, --retry) {
72        buf = new char [len];
73        my_android_logger_get_statistics(buf, len);
74
75        buf[len-1] = '\0';
76        size_t ret = atol(buf) + 1;
77        if (ret < 4) {
78            delete [] buf;
79            buf = NULL;
80            break;
81        }
82        bool check = ret <= len;
83        len = ret;
84        if (check) {
85            break;
86        }
87        len += len / 8; // allow for some slop
88    }
89    *buffer = buf;
90    *length = len;
91}
92
93static char *find_benchmark_spam(char *cp)
94{
95    // liblog_benchmarks has been run designed to SPAM.  The signature of
96    // a noisiest UID statistics is:
97    //
98    // Chattiest UIDs in main log buffer:                           Size Pruned
99    // UID   PACKAGE                                                BYTES LINES
100    // 0     root                                                  54164 147569
101    //
102    char *benchmark = NULL;
103    do {
104        static const char signature[] = "\n0     root ";
105
106        benchmark = strstr(cp, signature);
107        if (!benchmark) {
108            break;
109        }
110        cp = benchmark + sizeof(signature);
111        while (isspace(*cp)) {
112            ++cp;
113        }
114        benchmark = cp;
115        while (isdigit(*cp)) {
116            ++cp;
117        }
118        while (isspace(*cp)) {
119            ++cp;
120        }
121        unsigned long value = 0;
122        while (isdigit(*cp)) {
123            value = value * 10ULL + *cp - '0';
124            ++cp;
125        }
126        if (value > 100000UL) {
127            break;
128        }
129        benchmark = NULL;
130    } while (*cp);
131    return benchmark;
132}
133
134TEST(logd, statistics) {
135    size_t len;
136    char *buf;
137
138    alloc_statistics(&buf, &len);
139
140#ifdef TARGET_USES_LOGD
141    ASSERT_TRUE(NULL != buf);
142#else
143    if (!buf) {
144        return;
145    }
146#endif
147
148    // remove trailing FF
149    char *cp = buf + len - 1;
150    *cp = '\0';
151    bool truncated = *--cp != '\f';
152    if (!truncated) {
153        *cp = '\0';
154    }
155
156    // squash out the byte count
157    cp = buf;
158    if (!truncated) {
159        while (isdigit(*cp) || (*cp == '\n')) {
160            ++cp;
161        }
162    }
163
164    fprintf(stderr, "%s", cp);
165
166    EXPECT_LT((size_t)64, strlen(cp));
167
168    EXPECT_EQ(0, truncated);
169
170#ifdef TARGET_USES_LOGD
171    char *main_logs = strstr(cp, "\nChattiest UIDs in main ");
172    EXPECT_TRUE(NULL != main_logs);
173
174    char *radio_logs = strstr(cp, "\nChattiest UIDs in radio ");
175    EXPECT_TRUE(NULL != radio_logs);
176
177    char *system_logs = strstr(cp, "\nChattiest UIDs in system ");
178    EXPECT_TRUE(NULL != system_logs);
179
180    char *events_logs = strstr(cp, "\nChattiest UIDs in events ");
181    EXPECT_TRUE(NULL != events_logs);
182#endif
183
184    delete [] buf;
185}
186
187static void caught_signal(int signum __unused) { }
188
189static void dump_log_msg(const char *prefix,
190                         log_msg *msg, unsigned int version, int lid) {
191    switch(msg->entry.hdr_size) {
192    case 0:
193        version = 1;
194        break;
195
196    case sizeof(msg->entry_v2):
197        if (version == 0) {
198            version = 2;
199        }
200        break;
201    }
202
203    fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
204    if (version != 1) {
205        fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
206    }
207    fprintf(stderr, "pid=%u tid=%u %u.%09u ",
208            msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec);
209    switch(version) {
210    case 1:
211         break;
212    case 2:
213        fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
214        break;
215    case 3:
216    default:
217        lid = msg->entry.lid;
218        break;
219    }
220
221    switch(lid) {
222    case 0:
223        fprintf(stderr, "lid=main ");
224        break;
225    case 1:
226        fprintf(stderr, "lid=radio ");
227        break;
228    case 2:
229        fprintf(stderr, "lid=events ");
230        break;
231    case 3:
232        fprintf(stderr, "lid=system ");
233        break;
234    default:
235        if (lid >= 0) {
236            fprintf(stderr, "lid=%d ", lid);
237        }
238    }
239
240    unsigned int len = msg->entry.len;
241    fprintf(stderr, "msg[%u]={", len);
242    unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg());
243    while(len) {
244        unsigned char *p = cp;
245        while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
246            ++p;
247        }
248        if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
249            fprintf(stderr, "\"");
250            while (*cp) {
251                if (*cp != '\n') {
252                    fprintf(stderr, "%c", *cp);
253                } else {
254                    fprintf(stderr, "\\n");
255                }
256                ++cp;
257                --len;
258            }
259            fprintf(stderr, "\"");
260        } else {
261            fprintf(stderr, "%02x", *cp);
262        }
263        ++cp;
264        if (--len) {
265            fprintf(stderr, ", ");
266        }
267    }
268    fprintf(stderr, "}\n");
269}
270
271TEST(logd, both) {
272    log_msg msg;
273
274    // check if we can read any logs from logd
275    bool user_logger_available = false;
276    bool user_logger_content = false;
277
278    int fd = socket_local_client("logdr",
279                                 ANDROID_SOCKET_NAMESPACE_RESERVED,
280                                 SOCK_SEQPACKET);
281    if (fd >= 0) {
282        struct sigaction ignore, old_sigaction;
283        memset(&ignore, 0, sizeof(ignore));
284        ignore.sa_handler = caught_signal;
285        sigemptyset(&ignore.sa_mask);
286        sigaction(SIGALRM, &ignore, &old_sigaction);
287        unsigned int old_alarm = alarm(10);
288
289        static const char ask[] = "dumpAndClose lids=0,1,2,3";
290        user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);
291
292        user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;
293
294        if (user_logger_content) {
295            dump_log_msg("user", &msg, 3, -1);
296        }
297
298        alarm(old_alarm);
299        sigaction(SIGALRM, &old_sigaction, NULL);
300
301        close(fd);
302    }
303
304    // check if we can read any logs from kernel logger
305    bool kernel_logger_available = false;
306    bool kernel_logger_content = false;
307
308    static const char *loggers[] = {
309        "/dev/log/main",   "/dev/log_main",
310        "/dev/log/radio",  "/dev/log_radio",
311        "/dev/log/events", "/dev/log_events",
312        "/dev/log/system", "/dev/log_system",
313    };
314
315    for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) {
316        fd = open(loggers[i], O_RDONLY);
317        if (fd < 0) {
318            continue;
319        }
320        kernel_logger_available = true;
321        fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK);
322        int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
323        if (result > 0) {
324            kernel_logger_content = true;
325            dump_log_msg("kernel", &msg, 0, i / 2);
326        }
327        close(fd);
328    }
329
330    static const char yes[] = "\xE2\x9C\x93";
331    static const char no[] = "\xE2\x9c\x98";
332    fprintf(stderr,
333            "LOGGER  Available  Content\n"
334            "user    %-13s%s\n"
335            "kernel  %-13s%s\n"
336            " status %-11s%s\n",
337            (user_logger_available)   ? yes : no,
338            (user_logger_content)     ? yes : no,
339            (kernel_logger_available) ? yes : no,
340            (kernel_logger_content)   ? yes : no,
341            (user_logger_available && kernel_logger_available) ? "ERROR" : "ok",
342            (user_logger_content && kernel_logger_content) ? "ERROR" : "ok");
343
344    EXPECT_EQ(0, user_logger_available && kernel_logger_available);
345    EXPECT_EQ(0, !user_logger_available && !kernel_logger_available);
346    EXPECT_EQ(0, user_logger_content && kernel_logger_content);
347    EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
348}
349
350// BAD ROBOT
351//   Benchmark threshold are generally considered bad form unless there is
352//   is some human love applied to the continued maintenance and whether the
353//   thresholds are tuned on a per-target basis. Here we check if the values
354//   are more than double what is expected. Doubling will not prevent failure
355//   on busy or low-end systems that could have a tendency to stretch values.
356//
357//   The primary goal of this test is to simulate a spammy app (benchmark
358//   being the worst) and check to make sure the logger can deal with it
359//   appropriately by checking all the statistics are in an expected range.
360//
361TEST(logd, benchmark) {
362    size_t len;
363    char *buf;
364
365    alloc_statistics(&buf, &len);
366    bool benchmark_already_run = buf && find_benchmark_spam(buf);
367    delete [] buf;
368
369    if (benchmark_already_run) {
370        fprintf(stderr, "WARNING: spam already present and too much history\n"
371                        "         false OK for prune by worst UID check\n");
372    }
373
374    FILE *fp;
375
376    // Introduce some extreme spam for the worst UID filter
377    ASSERT_TRUE(NULL != (fp = popen(
378        "/data/nativetest/liblog-benchmarks/liblog-benchmarks",
379        "r")));
380
381    char buffer[5120];
382
383    static const char *benchmarks[] = {
384        "BM_log_maximum_retry ",
385        "BM_log_maximum ",
386        "BM_clock_overhead ",
387        "BM_log_overhead ",
388        "BM_log_latency ",
389        "BM_log_delay "
390    };
391    static const unsigned int log_maximum_retry = 0;
392    static const unsigned int log_maximum = 1;
393    static const unsigned int clock_overhead = 2;
394    static const unsigned int log_overhead = 3;
395    static const unsigned int log_latency = 4;
396    static const unsigned int log_delay = 5;
397
398    unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];
399
400    memset(ns, 0, sizeof(ns));
401
402    while (fgets(buffer, sizeof(buffer), fp)) {
403        for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
404            char *cp = strstr(buffer, benchmarks[i]);
405            if (!cp) {
406                continue;
407            }
408            sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]);
409            fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
410        }
411    }
412    int ret = pclose(fp);
413
414    if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
415        fprintf(stderr,
416                "WARNING: "
417                "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
418                "         can not perform test\n");
419        return;
420    }
421
422#ifdef TARGET_USES_LOGD
423    EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user
424#else
425    EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel
426#endif
427
428#ifdef TARGET_USES_LOGD
429    EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user
430#else
431    EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel
432#endif
433
434    EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
435
436#ifdef TARGET_USES_LOGD
437    EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user
438#else
439    EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel
440#endif
441
442#ifdef TARGET_USES_LOGD
443    EXPECT_GE(10000UL, ns[log_latency]); // 5669 user space
444#else
445    EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel
446#endif
447
448#ifdef TARGET_USES_LOGD
449    EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
450#else
451    EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel
452#endif
453
454    for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
455        EXPECT_NE(0UL, ns[i]);
456    }
457
458    alloc_statistics(&buf, &len);
459
460#ifdef TARGET_USES_LOGD
461    bool collected_statistics = !!buf;
462    EXPECT_EQ(true, collected_statistics);
463#else
464    if (!buf) {
465        return;
466    }
467#endif
468
469    ASSERT_TRUE(NULL != buf);
470
471    char *benchmark_statistics_found = find_benchmark_spam(buf);
472    ASSERT_TRUE(benchmark_statistics_found != NULL);
473
474    // Check how effective the SPAM filter is, parse out Now size.
475    // 0     root                      54164 147569
476    //                                 ^-- benchmark_statistics_found
477
478    unsigned long nowSpamSize = atol(benchmark_statistics_found);
479
480    delete [] buf;
481
482    ASSERT_NE(0UL, nowSpamSize);
483
484    // Determine if we have the spam filter enabled
485    int sock = socket_local_client("logd",
486                                   ANDROID_SOCKET_NAMESPACE_RESERVED,
487                                   SOCK_STREAM);
488
489    ASSERT_TRUE(sock >= 0);
490
491    static const char getPruneList[] = "getPruneList";
492    if (write(sock, getPruneList, sizeof(getPruneList)) > 0) {
493        char buffer[80];
494        memset(buffer, 0, sizeof(buffer));
495        read(sock, buffer, sizeof(buffer));
496        char *cp = strchr(buffer, '\n');
497        if (!cp || (cp[1] != '~') || (cp[2] != '!')) {
498            close(sock);
499            fprintf(stderr,
500                    "WARNING: "
501                    "Logger has SPAM filtration turned off \"%s\"\n", buffer);
502            return;
503        }
504    } else {
505        int save_errno = errno;
506        close(sock);
507        FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno);
508    }
509
510    static const unsigned long expected_absolute_minimum_log_size = 65536UL;
511    unsigned long totalSize = expected_absolute_minimum_log_size;
512    static const char getSize[] = {
513        'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ',
514        LOG_ID_MAIN + '0', '\0'
515    };
516    if (write(sock, getSize, sizeof(getSize)) > 0) {
517        char buffer[80];
518        memset(buffer, 0, sizeof(buffer));
519        read(sock, buffer, sizeof(buffer));
520        totalSize = atol(buffer);
521        if (totalSize < expected_absolute_minimum_log_size) {
522            fprintf(stderr,
523                    "WARNING: "
524                    "Logger had unexpected referenced size \"%s\"\n", buffer);
525            totalSize = expected_absolute_minimum_log_size;
526        }
527    }
528    close(sock);
529
530    // logd allows excursions to 110% of total size
531    totalSize = (totalSize * 11 ) / 10;
532
533    // 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
534    ASSERT_GT(totalSize, nowSpamSize * 2);
535}
536