logd_test.cpp revision 696817d3524e2fb8bbbcc2ec3526f4383f789163 
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/logger.h"
27
28#define __unused __attribute__((__unused__))
29
30/*
31 * returns statistics
32 */
33static void my_android_logger_get_statistics(char *buf, size_t len)
34{
35    snprintf(buf, len, "getStatistics 0 1 2 3 4");
36    int sock = socket_local_client("logd",
37                                   ANDROID_SOCKET_NAMESPACE_RESERVED,
38                                   SOCK_STREAM);
39    if (sock >= 0) {
40        if (write(sock, buf, strlen(buf) + 1) > 0) {
41            ssize_t ret;
42            while ((ret = read(sock, buf, len)) > 0) {
43                if ((size_t)ret == len) {
44                    break;
45                }
46                len -= ret;
47                buf += ret;
48
49                struct pollfd p = {
50                    .fd = sock,
51                    .events = POLLIN,
52                    .revents = 0
53                };
54
55                ret = poll(&p, 1, 20);
56                if ((ret <= 0) || !(p.revents & POLLIN)) {
57                    break;
58                }
59            }
60        }
61        close(sock);
62    }
63}
64
65static void alloc_statistics(char **buffer, size_t *length)
66{
67    size_t len = 8192;
68    char *buf;
69
70    for(int retry = 32; (retry >= 0); delete [] buf, --retry) {
71        buf = new char [len];
72        my_android_logger_get_statistics(buf, len);
73
74        buf[len-1] = '\0';
75        size_t ret = atol(buf) + 1;
76        if (ret < 4) {
77            delete [] buf;
78            buf = NULL;
79            break;
80        }
81        bool check = ret <= len;
82        len = ret;
83        if (check) {
84            break;
85        }
86        len += len / 8; // allow for some slop
87    }
88    *buffer = buf;
89    *length = len;
90}
91
92static char *find_benchmark_spam(char *cp)
93{
94    // liblog_benchmarks has been run designed to SPAM.  The signature of
95    // a noisiest UID statistics is one of the following:
96    //
97    // main: UID/PID Total size/num   Now          UID/PID[?]  Total
98    // 0           7500306/304207     71608/3183   0/4225?     7454388/303656
99    // -or-
100    // 0/gone      7454388/303656
101    //
102    // basically if we see a *large* number of 0/????? entries
103    unsigned long value;
104    do {
105        char *benchmark = strstr(cp, " 0/");
106        char *benchmark_newline = strstr(cp, "\n0/");
107        if (!benchmark) {
108            benchmark = benchmark_newline;
109        }
110        if (benchmark_newline && (benchmark > benchmark_newline)) {
111            benchmark = benchmark_newline;
112        }
113        cp = benchmark;
114        if (!cp) {
115            break;
116        }
117        cp += 3;
118        while (isdigit(*cp) || (*cp == 'g') || (*cp == 'o') || (*cp == 'n')) {
119            ++cp;
120        }
121        value = 0;
122        // ###? or gone
123        if ((*cp == '?') || (*cp == 'e')) {
124            while (*++cp == ' ');
125            while (isdigit(*cp)) {
126                value = value * 10ULL + *cp - '0';
127                ++cp;
128            }
129        }
130    } while ((value < 900000ULL) && *cp);
131    return cp;
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, "\nmain:");
172    EXPECT_TRUE(NULL != main_logs);
173
174    char *radio_logs = strstr(cp, "\nradio:");
175    EXPECT_TRUE(NULL != radio_logs);
176
177    char *system_logs = strstr(cp, "\nsystem:");
178    EXPECT_TRUE(NULL != system_logs);
179
180    char *events_logs = strstr(cp, "\nevents:");
181    EXPECT_TRUE(NULL != events_logs);
182#endif
183
184    // Parse timing stats
185
186    cp = strstr(cp, "Minimum time between log events per dgram_qlen:");
187
188    char *log_events_per_span = cp;
189
190    if (cp) {
191        while (*cp && (*cp != '\n')) {
192            ++cp;
193        }
194        if (*cp == '\n') {
195            ++cp;
196        }
197
198        char *list_of_spans = cp;
199        EXPECT_NE('\0', *list_of_spans);
200
201        unsigned short number_of_buckets = 0;
202        unsigned short *dgram_qlen = NULL;
203        unsigned short bucket = 0;
204        while (*cp && (*cp != '\n')) {
205            bucket = 0;
206            while (isdigit(*cp)) {
207                bucket = bucket * 10 + *cp - '0';
208                ++cp;
209            }
210            while (*cp == ' ') {
211                ++cp;
212            }
213            if (!bucket) {
214                break;
215            }
216            unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1];
217            EXPECT_TRUE(new_dgram_qlen != NULL);
218            if (dgram_qlen) {
219                memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets);
220                delete [] dgram_qlen;
221            }
222
223            dgram_qlen = new_dgram_qlen;
224            dgram_qlen[number_of_buckets++] = bucket;
225        }
226
227        char *end_of_spans = cp;
228        EXPECT_NE('\0', *end_of_spans);
229
230        EXPECT_LT(5, number_of_buckets);
231
232        unsigned long long *times = new unsigned long long [number_of_buckets];
233        ASSERT_TRUE(times != NULL);
234
235        memset(times, 0, sizeof(*times) * number_of_buckets);
236
237        while (*cp == '\n') {
238            ++cp;
239        }
240
241        unsigned short number_of_values = 0;
242        unsigned long long value;
243        while (*cp && (*cp != '\n')) {
244            EXPECT_GE(number_of_buckets, number_of_values);
245
246            value = 0;
247            while (isdigit(*cp)) {
248                value = value * 10ULL + *cp - '0';
249                ++cp;
250            }
251
252            switch(*cp) {
253            case ' ':
254            case '\n':
255                value *= 1000ULL;
256                /* FALLTHRU */
257            case 'm':
258                value *= 1000ULL;
259                /* FALLTHRU */
260            case 'u':
261                value *= 1000ULL;
262                /* FALLTHRU */
263            case 'n':
264            default:
265                break;
266            }
267            while (*++cp == ' ');
268
269            if (!value) {
270                break;
271            }
272
273            times[number_of_values] = value;
274            ++number_of_values;
275        }
276
277#ifdef TARGET_USES_LOGD
278        EXPECT_EQ(number_of_values, number_of_buckets);
279#endif
280
281        FILE *fp;
282        ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r")));
283
284        unsigned max_dgram_qlen = 0;
285        fscanf(fp, "%u", &max_dgram_qlen);
286
287        fclose(fp);
288
289        // Find launch point
290        unsigned short launch = 0;
291        unsigned long long total = 0;
292        do {
293            total += times[launch];
294        } while (((++launch < number_of_buckets)
295                && ((total / launch) >= (times[launch] / 8ULL)))
296            || (launch == 1)); // too soon
297
298        bool failure = number_of_buckets <= launch;
299        if (!failure) {
300            unsigned short l = launch;
301            if (l >= number_of_buckets) {
302                l = number_of_buckets - 1;
303            }
304            failure = max_dgram_qlen < dgram_qlen[l];
305        }
306
307        // We can get failure if at any time liblog_benchmarks has been run
308        // because designed to overload /proc/sys/net/unix/max_dgram_qlen even
309        // at excessive values like 20000. It does so to measure the raw processing
310        // performance of logd.
311        if (failure) {
312            cp = find_benchmark_spam(cp);
313        }
314
315        if (cp) {
316            // Fake a failure, but without the failure code
317            if (number_of_buckets <= launch) {
318                printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n",
319                        number_of_buckets, launch);
320            }
321            if (launch >= number_of_buckets) {
322                launch = number_of_buckets - 1;
323            }
324            if (max_dgram_qlen < dgram_qlen[launch]) {
325                printf ("Expected: max_dgram_qlen >= dgram_qlen[%d],"
326                            " actual: %u vs %u\n",
327                        launch, max_dgram_qlen, dgram_qlen[launch]);
328            }
329        } else
330#ifndef TARGET_USES_LOGD
331        if (total)
332#endif
333        {
334            EXPECT_GT(number_of_buckets, launch);
335            if (launch >= number_of_buckets) {
336                launch = number_of_buckets - 1;
337            }
338            EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]);
339        }
340
341        delete [] dgram_qlen;
342        delete [] times;
343    }
344    delete [] buf;
345}
346
347static void caught_signal(int signum __unused) { }
348
349static void dump_log_msg(const char *prefix,
350                         log_msg *msg, unsigned int version, int lid) {
351    switch(msg->entry.hdr_size) {
352    case 0:
353        version = 1;
354        break;
355
356    case sizeof(msg->entry_v2):
357        if (version == 0) {
358            version = 2;
359        }
360        break;
361    }
362
363    fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
364    if (version != 1) {
365        fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
366    }
367    fprintf(stderr, "pid=%u tid=%u %u.%09u ",
368            msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec);
369    switch(version) {
370    case 1:
371         break;
372    case 2:
373        fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
374        break;
375    case 3:
376    default:
377        lid = msg->entry.lid;
378        break;
379    }
380
381    switch(lid) {
382    case 0:
383        fprintf(stderr, "lid=main ");
384        break;
385    case 1:
386        fprintf(stderr, "lid=radio ");
387        break;
388    case 2:
389        fprintf(stderr, "lid=events ");
390        break;
391    case 3:
392        fprintf(stderr, "lid=system ");
393        break;
394    default:
395        if (lid >= 0) {
396            fprintf(stderr, "lid=%d ", lid);
397        }
398    }
399
400    unsigned int len = msg->entry.len;
401    fprintf(stderr, "msg[%u]={", len);
402    unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg());
403    while(len) {
404        unsigned char *p = cp;
405        while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
406            ++p;
407        }
408        if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
409            fprintf(stderr, "\"");
410            while (*cp) {
411                fprintf(stderr, (*cp != '\n') ? "%c" : "\\n", *cp);
412                ++cp;
413                --len;
414            }
415            fprintf(stderr, "\"");
416        } else {
417            fprintf(stderr, "%02x", *cp);
418        }
419        ++cp;
420        if (--len) {
421            fprintf(stderr, ", ");
422        }
423    }
424    fprintf(stderr, "}\n");
425}
426
427TEST(logd, both) {
428    log_msg msg;
429
430    // check if we can read any logs from logd
431    bool user_logger_available = false;
432    bool user_logger_content = false;
433
434    int fd = socket_local_client("logdr",
435                                 ANDROID_SOCKET_NAMESPACE_RESERVED,
436                                 SOCK_SEQPACKET);
437    if (fd >= 0) {
438        struct sigaction ignore, old_sigaction;
439        memset(&ignore, 0, sizeof(ignore));
440        ignore.sa_handler = caught_signal;
441        sigemptyset(&ignore.sa_mask);
442        sigaction(SIGALRM, &ignore, &old_sigaction);
443        unsigned int old_alarm = alarm(10);
444
445        static const char ask[] = "dumpAndClose lids=0,1,2,3";
446        user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);
447
448        user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;
449
450        if (user_logger_content) {
451            dump_log_msg("user", &msg, 3, -1);
452        }
453
454        alarm(0);
455        sigaction(SIGALRM, &old_sigaction, NULL);
456
457        close(fd);
458    }
459
460    // check if we can read any logs from kernel logger
461    bool kernel_logger_available = false;
462    bool kernel_logger_content = false;
463
464    static const char *loggers[] = {
465        "/dev/log/main",   "/dev/log_main",
466        "/dev/log/radio",  "/dev/log_radio",
467        "/dev/log/events", "/dev/log_events",
468        "/dev/log/system", "/dev/log_system",
469    };
470
471    for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) {
472        fd = open(loggers[i], O_RDONLY);
473        if (fd < 0) {
474            continue;
475        }
476        kernel_logger_available = true;
477        fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK);
478        int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
479        if (result > 0) {
480            kernel_logger_content = true;
481            dump_log_msg("kernel", &msg, 0, i / 2);
482        }
483        close(fd);
484    }
485
486    static const char yes[] = "\xE2\x9C\x93";
487    static const char no[] = "\xE2\x9c\x98";
488    fprintf(stderr,
489            "LOGGER  Available  Content\n"
490            "user    %-13s%s\n"
491            "kernel  %-13s%s\n"
492            " status %-11s%s\n",
493            (user_logger_available)   ? yes : no,
494            (user_logger_content)     ? yes : no,
495            (kernel_logger_available) ? yes : no,
496            (kernel_logger_content)   ? yes : no,
497            (user_logger_available && kernel_logger_available) ? "WARNING" : "ok",
498            (user_logger_content && kernel_logger_content) ? "ERROR" : "ok");
499
500    if (user_logger_available && kernel_logger_available) {
501        printf("WARNING: kernel & user logger; both consuming resources!!!\n");
502    }
503
504    EXPECT_EQ(0, user_logger_content && kernel_logger_content);
505    EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
506}
507
508// BAD ROBOT
509//   Benchmark threshold are generally considered bad form unless there is
510//   is some human love applied to the continued maintenance and whether the
511//   thresholds are tuned on a per-target basis. Here we check if the values
512//   are more than double what is expected. Doubling will not prevent failure
513//   on busy or low-end systems that could have a tendency to stretch values.
514//
515//   The primary goal of this test is to simulate a spammy app (benchmark
516//   being the worst) and check to make sure the logger can deal with it
517//   appropriately by checking all the statistics are in an expected range.
518//
519TEST(logd, benchmark) {
520    size_t len;
521    char *buf;
522
523    alloc_statistics(&buf, &len);
524    bool benchmark_already_run = buf && find_benchmark_spam(buf);
525    delete [] buf;
526
527    if (benchmark_already_run) {
528        fprintf(stderr, "WARNING: spam already present and too much history\n"
529                        "         false OK for prune by worst UID check\n");
530    }
531
532    FILE *fp;
533
534    // Introduce some extreme spam for the worst UID filter
535    ASSERT_TRUE(NULL != (fp = popen(
536        "/data/nativetest/liblog-benchmarks/liblog-benchmarks",
537        "r")));
538
539    char buffer[5120];
540
541    static const char *benchmarks[] = {
542        "BM_log_maximum_retry ",
543        "BM_log_maximum ",
544        "BM_clock_overhead ",
545        "BM_log_overhead ",
546        "BM_log_latency ",
547        "BM_log_delay "
548    };
549    static const unsigned int log_maximum_retry = 0;
550    static const unsigned int log_maximum = 1;
551    static const unsigned int clock_overhead = 2;
552    static const unsigned int log_overhead = 3;
553    static const unsigned int log_latency = 4;
554    static const unsigned int log_delay = 5;
555
556    unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];
557
558    memset(ns, 0, sizeof(ns));
559
560    while (fgets(buffer, sizeof(buffer), fp)) {
561        for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
562            if (strncmp(benchmarks[i], buffer, strlen(benchmarks[i]))) {
563                continue;
564            }
565            sscanf(buffer, "%*s %lu %lu", &ns[i], &ns[i]);
566            fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
567        }
568    }
569    int ret = pclose(fp);
570
571    if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
572        fprintf(stderr,
573                "WARNING: "
574                "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
575                "         can not perform test\n");
576        return;
577    }
578
579#ifdef TARGET_USES_LOGD
580    EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user
581#else
582    EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel
583#endif
584
585#ifdef TARGET_USES_LOGD
586    EXPECT_GE(25000UL, ns[log_maximum]); // 14055 user
587#else
588    EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel
589#endif
590
591    EXPECT_GE(4000UL, ns[clock_overhead]); // 2008
592
593#ifdef TARGET_USES_LOGD
594    EXPECT_GE(250000UL, ns[log_overhead]); // 113219 user
595#else
596    EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel
597#endif
598
599#ifdef TARGET_USES_LOGD
600    EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space
601#else
602    EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel
603#endif
604
605#ifdef TARGET_USES_LOGD
606    EXPECT_GE(20000000UL, ns[log_delay]); // 9542541 user
607#else
608    EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel
609#endif
610
611    for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
612        EXPECT_NE(0UL, ns[i]);
613    }
614
615    alloc_statistics(&buf, &len);
616
617#ifdef TARGET_USES_LOGD
618    bool collected_statistics = !!buf;
619    EXPECT_EQ(true, collected_statistics);
620#else
621    if (!buf) {
622        return;
623    }
624#endif
625
626    ASSERT_TRUE(NULL != buf);
627    EXPECT_TRUE(find_benchmark_spam(buf) != NULL);
628
629    delete [] buf;
630}
631