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