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 one of the following:
97    //
98    // main: UID/PID Total size/num   Now          UID/PID[?]  Total
99    // 0           7500306/304207     71608/3183   0/4225?     7454388/303656
100    //    <wrap>                                                     93432/1012
101    // -or-
102    // 0/gone      7454388/303656     93432/1012
103    //
104    // basically if we see a *large* number of 0/????? entries
105    unsigned long value;
106    do {
107        char *benchmark = strstr(cp, " 0/");
108        char *benchmark_newline = strstr(cp, "\n0/");
109        if (!benchmark) {
110            benchmark = benchmark_newline;
111        }
112        if (benchmark_newline && (benchmark > benchmark_newline)) {
113            benchmark = benchmark_newline;
114        }
115        cp = benchmark;
116        if (!cp) {
117            break;
118        }
119        cp += 3;
120        while (isdigit(*cp) || (*cp == 'g') || (*cp == 'o') || (*cp == 'n')) {
121            ++cp;
122        }
123        value = 0;
124        // ###? or gone
125        if ((*cp == '?') || (*cp == 'e')) {
126            while (*++cp == ' ');
127            while (isdigit(*cp)) {
128                value = value * 10ULL + *cp - '0';
129                ++cp;
130            }
131            if (*cp != '/') {
132                value = 0;
133                continue;
134            }
135            while (isdigit(*++cp));
136            while (*cp == ' ') ++cp;
137            if (!isdigit(*cp)) {
138                value = 0;
139            }
140        }
141    } while ((value < 900000ULL) && *cp);
142    return cp;
143}
144
145TEST(logd, statistics) {
146    size_t len;
147    char *buf;
148
149    alloc_statistics(&buf, &len);
150
151#ifdef TARGET_USES_LOGD
152    ASSERT_TRUE(NULL != buf);
153#else
154    if (!buf) {
155        return;
156    }
157#endif
158
159    // remove trailing FF
160    char *cp = buf + len - 1;
161    *cp = '\0';
162    bool truncated = *--cp != '\f';
163    if (!truncated) {
164        *cp = '\0';
165    }
166
167    // squash out the byte count
168    cp = buf;
169    if (!truncated) {
170        while (isdigit(*cp) || (*cp == '\n')) {
171            ++cp;
172        }
173    }
174
175    fprintf(stderr, "%s", cp);
176
177    EXPECT_LT((size_t)64, strlen(cp));
178
179    EXPECT_EQ(0, truncated);
180
181#ifdef TARGET_USES_LOGD
182    char *main_logs = strstr(cp, "\nmain:");
183    EXPECT_TRUE(NULL != main_logs);
184
185    char *radio_logs = strstr(cp, "\nradio:");
186    EXPECT_TRUE(NULL != radio_logs);
187
188    char *system_logs = strstr(cp, "\nsystem:");
189    EXPECT_TRUE(NULL != system_logs);
190
191    char *events_logs = strstr(cp, "\nevents:");
192    EXPECT_TRUE(NULL != events_logs);
193#endif
194
195    // Parse timing stats
196
197    cp = strstr(cp, "Minimum time between log events per dgram_qlen:");
198
199    if (cp) {
200        while (*cp && (*cp != '\n')) {
201            ++cp;
202        }
203        if (*cp == '\n') {
204            ++cp;
205        }
206
207        char *list_of_spans = cp;
208        EXPECT_NE('\0', *list_of_spans);
209
210        unsigned short number_of_buckets = 0;
211        unsigned short *dgram_qlen = NULL;
212        unsigned short bucket = 0;
213        while (*cp && (*cp != '\n')) {
214            bucket = 0;
215            while (isdigit(*cp)) {
216                bucket = bucket * 10 + *cp - '0';
217                ++cp;
218            }
219            while (*cp == ' ') {
220                ++cp;
221            }
222            if (!bucket) {
223                break;
224            }
225            unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1];
226            EXPECT_TRUE(new_dgram_qlen != NULL);
227            if (dgram_qlen) {
228                memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets);
229                delete [] dgram_qlen;
230            }
231
232            dgram_qlen = new_dgram_qlen;
233            dgram_qlen[number_of_buckets++] = bucket;
234        }
235
236        char *end_of_spans = cp;
237        EXPECT_NE('\0', *end_of_spans);
238
239        EXPECT_LT(5, number_of_buckets);
240
241        unsigned long long *times = new unsigned long long [number_of_buckets];
242        ASSERT_TRUE(times != NULL);
243
244        memset(times, 0, sizeof(*times) * number_of_buckets);
245
246        while (*cp == '\n') {
247            ++cp;
248        }
249
250        unsigned short number_of_values = 0;
251        unsigned long long value;
252        while (*cp && (*cp != '\n')) {
253            EXPECT_GE(number_of_buckets, number_of_values);
254
255            value = 0;
256            while (isdigit(*cp)) {
257                value = value * 10ULL + *cp - '0';
258                ++cp;
259            }
260
261            switch(*cp) {
262            case ' ':
263            case '\n':
264                value *= 1000ULL;
265                /* FALLTHRU */
266            case 'm':
267                value *= 1000ULL;
268                /* FALLTHRU */
269            case 'u':
270                value *= 1000ULL;
271                /* FALLTHRU */
272            case 'n':
273            default:
274                break;
275            }
276            while (*++cp == ' ');
277
278            if (!value) {
279                break;
280            }
281
282            times[number_of_values] = value;
283            ++number_of_values;
284        }
285
286#ifdef TARGET_USES_LOGD
287        EXPECT_EQ(number_of_values, number_of_buckets);
288#endif
289
290        FILE *fp;
291        ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r")));
292
293        unsigned max_dgram_qlen = 0;
294        fscanf(fp, "%u", &max_dgram_qlen);
295
296        fclose(fp);
297
298        // Find launch point
299        unsigned short launch = 0;
300        unsigned long long total = 0;
301        do {
302            total += times[launch];
303        } while (((++launch < number_of_buckets)
304                && ((total / launch) >= (times[launch] / 8ULL)))
305            || (launch == 1)); // too soon
306
307        bool failure = number_of_buckets <= launch;
308        if (!failure) {
309            unsigned short l = launch;
310            if (l >= number_of_buckets) {
311                l = number_of_buckets - 1;
312            }
313            failure = max_dgram_qlen < dgram_qlen[l];
314        }
315
316        // We can get failure if at any time liblog_benchmarks has been run
317        // because designed to overload /proc/sys/net/unix/max_dgram_qlen even
318        // at excessive values like 20000. It does so to measure the raw processing
319        // performance of logd.
320        if (failure) {
321            cp = find_benchmark_spam(cp);
322        }
323
324        if (cp) {
325            // Fake a failure, but without the failure code
326            if (number_of_buckets <= launch) {
327                printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n",
328                        number_of_buckets, launch);
329            }
330            if (launch >= number_of_buckets) {
331                launch = number_of_buckets - 1;
332            }
333            if (max_dgram_qlen < dgram_qlen[launch]) {
334                printf ("Expected: max_dgram_qlen >= dgram_qlen[%d],"
335                            " actual: %u vs %u\n",
336                        launch, max_dgram_qlen, dgram_qlen[launch]);
337            }
338        } else
339#ifndef TARGET_USES_LOGD
340        if (total)
341#endif
342        {
343            EXPECT_GT(number_of_buckets, launch);
344            if (launch >= number_of_buckets) {
345                launch = number_of_buckets - 1;
346            }
347            EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]);
348        }
349
350        delete [] dgram_qlen;
351        delete [] times;
352    }
353    delete [] buf;
354}
355
356static void caught_signal(int signum __unused) { }
357
358static void dump_log_msg(const char *prefix,
359                         log_msg *msg, unsigned int version, int lid) {
360    switch(msg->entry.hdr_size) {
361    case 0:
362        version = 1;
363        break;
364
365    case sizeof(msg->entry_v2):
366        if (version == 0) {
367            version = 2;
368        }
369        break;
370    }
371
372    fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
373    if (version != 1) {
374        fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
375    }
376    fprintf(stderr, "pid=%u tid=%u %u.%09u ",
377            msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec);
378    switch(version) {
379    case 1:
380         break;
381    case 2:
382        fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
383        break;
384    case 3:
385    default:
386        lid = msg->entry.lid;
387        break;
388    }
389
390    switch(lid) {
391    case 0:
392        fprintf(stderr, "lid=main ");
393        break;
394    case 1:
395        fprintf(stderr, "lid=radio ");
396        break;
397    case 2:
398        fprintf(stderr, "lid=events ");
399        break;
400    case 3:
401        fprintf(stderr, "lid=system ");
402        break;
403    default:
404        if (lid >= 0) {
405            fprintf(stderr, "lid=%d ", lid);
406        }
407    }
408
409    unsigned int len = msg->entry.len;
410    fprintf(stderr, "msg[%u]={", len);
411    unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg());
412    while(len) {
413        unsigned char *p = cp;
414        while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
415            ++p;
416        }
417        if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
418            fprintf(stderr, "\"");
419            while (*cp) {
420                fprintf(stderr, (*cp != '\n') ? "%c" : "\\n", *cp);
421                ++cp;
422                --len;
423            }
424            fprintf(stderr, "\"");
425        } else {
426            fprintf(stderr, "%02x", *cp);
427        }
428        ++cp;
429        if (--len) {
430            fprintf(stderr, ", ");
431        }
432    }
433    fprintf(stderr, "}\n");
434}
435
436TEST(logd, both) {
437    log_msg msg;
438
439    // check if we can read any logs from logd
440    bool user_logger_available = false;
441    bool user_logger_content = false;
442
443    int fd = socket_local_client("logdr",
444                                 ANDROID_SOCKET_NAMESPACE_RESERVED,
445                                 SOCK_SEQPACKET);
446    if (fd >= 0) {
447        struct sigaction ignore, old_sigaction;
448        memset(&ignore, 0, sizeof(ignore));
449        ignore.sa_handler = caught_signal;
450        sigemptyset(&ignore.sa_mask);
451        sigaction(SIGALRM, &ignore, &old_sigaction);
452        unsigned int old_alarm = alarm(10);
453
454        static const char ask[] = "dumpAndClose lids=0,1,2,3";
455        user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);
456
457        user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;
458
459        if (user_logger_content) {
460            dump_log_msg("user", &msg, 3, -1);
461        }
462
463        alarm(old_alarm);
464        sigaction(SIGALRM, &old_sigaction, NULL);
465
466        close(fd);
467    }
468
469    // check if we can read any logs from kernel logger
470    bool kernel_logger_available = false;
471    bool kernel_logger_content = false;
472
473    static const char *loggers[] = {
474        "/dev/log/main",   "/dev/log_main",
475        "/dev/log/radio",  "/dev/log_radio",
476        "/dev/log/events", "/dev/log_events",
477        "/dev/log/system", "/dev/log_system",
478    };
479
480    for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) {
481        fd = open(loggers[i], O_RDONLY);
482        if (fd < 0) {
483            continue;
484        }
485        kernel_logger_available = true;
486        fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK);
487        int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
488        if (result > 0) {
489            kernel_logger_content = true;
490            dump_log_msg("kernel", &msg, 0, i / 2);
491        }
492        close(fd);
493    }
494
495    static const char yes[] = "\xE2\x9C\x93";
496    static const char no[] = "\xE2\x9c\x98";
497    fprintf(stderr,
498            "LOGGER  Available  Content\n"
499            "user    %-13s%s\n"
500            "kernel  %-13s%s\n"
501            " status %-11s%s\n",
502            (user_logger_available)   ? yes : no,
503            (user_logger_content)     ? yes : no,
504            (kernel_logger_available) ? yes : no,
505            (kernel_logger_content)   ? yes : no,
506            (user_logger_available && kernel_logger_available) ? "ERROR" : "ok",
507            (user_logger_content && kernel_logger_content) ? "ERROR" : "ok");
508
509    EXPECT_EQ(0, user_logger_available && kernel_logger_available);
510    EXPECT_EQ(0, !user_logger_available && !kernel_logger_available);
511    EXPECT_EQ(0, user_logger_content && kernel_logger_content);
512    EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
513}
514
515// BAD ROBOT
516//   Benchmark threshold are generally considered bad form unless there is
517//   is some human love applied to the continued maintenance and whether the
518//   thresholds are tuned on a per-target basis. Here we check if the values
519//   are more than double what is expected. Doubling will not prevent failure
520//   on busy or low-end systems that could have a tendency to stretch values.
521//
522//   The primary goal of this test is to simulate a spammy app (benchmark
523//   being the worst) and check to make sure the logger can deal with it
524//   appropriately by checking all the statistics are in an expected range.
525//
526TEST(logd, benchmark) {
527    size_t len;
528    char *buf;
529
530    alloc_statistics(&buf, &len);
531    bool benchmark_already_run = buf && find_benchmark_spam(buf);
532    delete [] buf;
533
534    if (benchmark_already_run) {
535        fprintf(stderr, "WARNING: spam already present and too much history\n"
536                        "         false OK for prune by worst UID check\n");
537    }
538
539    FILE *fp;
540
541    // Introduce some extreme spam for the worst UID filter
542    ASSERT_TRUE(NULL != (fp = popen(
543        "/data/nativetest/liblog-benchmarks/liblog-benchmarks",
544        "r")));
545
546    char buffer[5120];
547
548    static const char *benchmarks[] = {
549        "BM_log_maximum_retry ",
550        "BM_log_maximum ",
551        "BM_clock_overhead ",
552        "BM_log_overhead ",
553        "BM_log_latency ",
554        "BM_log_delay "
555    };
556    static const unsigned int log_maximum_retry = 0;
557    static const unsigned int log_maximum = 1;
558    static const unsigned int clock_overhead = 2;
559    static const unsigned int log_overhead = 3;
560    static const unsigned int log_latency = 4;
561    static const unsigned int log_delay = 5;
562
563    unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];
564
565    memset(ns, 0, sizeof(ns));
566
567    while (fgets(buffer, sizeof(buffer), fp)) {
568        for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
569            char *cp = strstr(buffer, benchmarks[i]);
570            if (!cp) {
571                continue;
572            }
573            sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]);
574            fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
575        }
576    }
577    int ret = pclose(fp);
578
579    if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
580        fprintf(stderr,
581                "WARNING: "
582                "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
583                "         can not perform test\n");
584        return;
585    }
586
587#ifdef TARGET_USES_LOGD
588    EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user
589#else
590    EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel
591#endif
592
593#ifdef TARGET_USES_LOGD
594    EXPECT_GE(30000UL, ns[log_maximum]); // 27305 user
595#else
596    EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel
597#endif
598
599    EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
600
601#ifdef TARGET_USES_LOGD
602    EXPECT_GE(250000UL, ns[log_overhead]); // 121876 user
603#else
604    EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel
605#endif
606
607#ifdef TARGET_USES_LOGD
608    EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space
609#else
610    EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel
611#endif
612
613#ifdef TARGET_USES_LOGD
614    EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
615#else
616    EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel
617#endif
618
619    for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
620        EXPECT_NE(0UL, ns[i]);
621    }
622
623    alloc_statistics(&buf, &len);
624
625#ifdef TARGET_USES_LOGD
626    bool collected_statistics = !!buf;
627    EXPECT_EQ(true, collected_statistics);
628#else
629    if (!buf) {
630        return;
631    }
632#endif
633
634    ASSERT_TRUE(NULL != buf);
635
636    char *benchmark_statistics_found = find_benchmark_spam(buf);
637    ASSERT_TRUE(benchmark_statistics_found != NULL);
638
639    // Check how effective the SPAM filter is, parse out Now size.
640    //             Total               Now
641    // 0/4225?     7454388/303656      31488/755
642    //                                 ^-- benchmark_statistics_found
643
644    unsigned long nowSpamSize = atol(benchmark_statistics_found);
645
646    delete [] buf;
647
648    ASSERT_NE(0UL, nowSpamSize);
649
650    // Determine if we have the spam filter enabled
651    int sock = socket_local_client("logd",
652                                   ANDROID_SOCKET_NAMESPACE_RESERVED,
653                                   SOCK_STREAM);
654
655    ASSERT_TRUE(sock >= 0);
656
657    static const char getPruneList[] = "getPruneList";
658    if (write(sock, getPruneList, sizeof(getPruneList)) > 0) {
659        char buffer[80];
660        memset(buffer, 0, sizeof(buffer));
661        read(sock, buffer, sizeof(buffer));
662        char *cp = strchr(buffer, '\n');
663        if (!cp || (cp[1] != '~') || (cp[2] != '!')) {
664            close(sock);
665            fprintf(stderr,
666                    "WARNING: "
667                    "Logger has SPAM filtration turned off \"%s\"\n", buffer);
668            return;
669        }
670    } else {
671        int save_errno = errno;
672        close(sock);
673        FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno);
674    }
675
676    static const unsigned long expected_absolute_minimum_log_size = 65536UL;
677    unsigned long totalSize = expected_absolute_minimum_log_size;
678    static const char getSize[] = {
679        'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ',
680        LOG_ID_MAIN + '0', '\0'
681    };
682    if (write(sock, getSize, sizeof(getSize)) > 0) {
683        char buffer[80];
684        memset(buffer, 0, sizeof(buffer));
685        read(sock, buffer, sizeof(buffer));
686        totalSize = atol(buffer);
687        if (totalSize < expected_absolute_minimum_log_size) {
688            fprintf(stderr,
689                    "WARNING: "
690                    "Logger had unexpected referenced size \"%s\"\n", buffer);
691            totalSize = expected_absolute_minimum_log_size;
692        }
693    }
694    close(sock);
695
696    // logd allows excursions to 110% of total size
697    totalSize = (totalSize * 11 ) / 10;
698
699    // 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
700    ASSERT_GT(totalSize, nowSpamSize * 2);
701}
702