Home | History | Annotate | Download | only in tests 
      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  */
     34 static 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 
     66 static 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 
     93 static 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 
    134 TEST(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 
    187 static void caught_signal(int signum __unused) { }
    188 
    189 static 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 
    271 TEST(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 //
    361 TEST(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