logd_test.cpp revision d26b2cacadc3f0cc143b3afd392f6a0135dc16bd 
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 <inttypes.h>
19#include <poll.h>
20#include <signal.h>
21#include <stdio.h>
22#include <string.h>
23
24#include <string>
25
26#include <gtest/gtest.h>
27
28#include <android-base/stringprintf.h>
29#include <cutils/sockets.h>
30#include <log/log.h>
31#include <log/logger.h>
32
33#include "../LogReader.h" // pickup LOGD_SNDTIMEO
34
35/*
36 * returns statistics
37 */
38static void my_android_logger_get_statistics(char *buf, size_t len)
39{
40    snprintf(buf, len, "getStatistics 0 1 2 3 4");
41    int sock = socket_local_client("logd",
42                                   ANDROID_SOCKET_NAMESPACE_RESERVED,
43                                   SOCK_STREAM);
44    if (sock >= 0) {
45        if (write(sock, buf, strlen(buf) + 1) > 0) {
46            ssize_t ret;
47            while ((ret = read(sock, buf, len)) > 0) {
48                if ((size_t)ret == len) {
49                    break;
50                }
51                len -= ret;
52                buf += ret;
53
54                struct pollfd p = {
55                    .fd = sock,
56                    .events = POLLIN,
57                    .revents = 0
58                };
59
60                ret = poll(&p, 1, 20);
61                if ((ret <= 0) || !(p.revents & POLLIN)) {
62                    break;
63                }
64            }
65        }
66        close(sock);
67    }
68}
69
70static void alloc_statistics(char **buffer, size_t *length)
71{
72    size_t len = 8192;
73    char *buf;
74
75    for(int retry = 32; (retry >= 0); delete [] buf, --retry) {
76        buf = new char [len];
77        my_android_logger_get_statistics(buf, len);
78
79        buf[len-1] = '\0';
80        size_t ret = atol(buf) + 1;
81        if (ret < 4) {
82            delete [] buf;
83            buf = NULL;
84            break;
85        }
86        bool check = ret <= len;
87        len = ret;
88        if (check) {
89            break;
90        }
91        len += len / 8; // allow for some slop
92    }
93    *buffer = buf;
94    *length = len;
95}
96
97static char *find_benchmark_spam(char *cp)
98{
99    // liblog_benchmarks has been run designed to SPAM.  The signature of
100    // a noisiest UID statistics is:
101    //
102    // Chattiest UIDs in main log buffer:                           Size Pruned
103    // UID   PACKAGE                                                BYTES LINES
104    // 0     root                                                  54164 147569
105    //
106    char *benchmark = NULL;
107    do {
108        static const char signature[] = "\n0     root ";
109
110        benchmark = strstr(cp, signature);
111        if (!benchmark) {
112            break;
113        }
114        cp = benchmark + sizeof(signature);
115        while (isspace(*cp)) {
116            ++cp;
117        }
118        benchmark = cp;
119#ifdef DEBUG
120        char *end = strstr(benchmark, "\n");
121        if (end == NULL) {
122            end = benchmark + strlen(benchmark);
123        }
124        fprintf(stderr, "parse for spam counter in \"%.*s\"\n",
125                (int)(end - benchmark), benchmark);
126#endif
127        // content
128        while (isdigit(*cp)) {
129            ++cp;
130        }
131        while (isspace(*cp)) {
132            ++cp;
133        }
134        // optional +/- field?
135        if ((*cp == '-') || (*cp == '+')) {
136            while (isdigit(*++cp) ||
137                   (*cp == '.') || (*cp == '%') || (*cp == 'X')) {
138                ;
139            }
140            while (isspace(*cp)) {
141                ++cp;
142            }
143        }
144        // number of entries pruned
145        unsigned long value = 0;
146        while (isdigit(*cp)) {
147            value = value * 10ULL + *cp - '0';
148            ++cp;
149        }
150        if (value > 10UL) {
151            break;
152        }
153        benchmark = NULL;
154    } while (*cp);
155    return benchmark;
156}
157
158TEST(logd, statistics) {
159    size_t len;
160    char *buf;
161
162    alloc_statistics(&buf, &len);
163
164    ASSERT_TRUE(NULL != buf);
165
166    // remove trailing FF
167    char *cp = buf + len - 1;
168    *cp = '\0';
169    bool truncated = *--cp != '\f';
170    if (!truncated) {
171        *cp = '\0';
172    }
173
174    // squash out the byte count
175    cp = buf;
176    if (!truncated) {
177        while (isdigit(*cp) || (*cp == '\n')) {
178            ++cp;
179        }
180    }
181
182    fprintf(stderr, "%s", cp);
183
184    EXPECT_LT((size_t)64, strlen(cp));
185
186    EXPECT_EQ(0, truncated);
187
188    char *main_logs = strstr(cp, "\nChattiest UIDs in main ");
189    EXPECT_TRUE(NULL != main_logs);
190
191    char *radio_logs = strstr(cp, "\nChattiest UIDs in radio ");
192    EXPECT_TRUE(NULL != radio_logs);
193
194    char *system_logs = strstr(cp, "\nChattiest UIDs in system ");
195    EXPECT_TRUE(NULL != system_logs);
196
197    char *events_logs = strstr(cp, "\nChattiest UIDs in events ");
198    EXPECT_TRUE(NULL != events_logs);
199
200    delete [] buf;
201}
202
203static void caught_signal(int /* signum */) { }
204
205static void dump_log_msg(const char *prefix,
206                         log_msg *msg, unsigned int version, int lid) {
207    std::cout << std::flush;
208    std::cerr << std::flush;
209    fflush(stdout);
210    fflush(stderr);
211    switch(msg->entry.hdr_size) {
212    case 0:
213        version = 1;
214        break;
215
216    case sizeof(msg->entry_v2):
217        if (version == 0) {
218            version = 2;
219        }
220        break;
221    }
222
223    fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
224    if (version != 1) {
225        fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
226    }
227    fprintf(stderr, "pid=%u tid=%u %u.%09u ",
228            msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec);
229    switch(version) {
230    case 1:
231         break;
232    case 2:
233        fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
234        break;
235    case 3:
236    default:
237        lid = msg->entry.lid;
238        break;
239    }
240
241    switch(lid) {
242    case 0:
243        fprintf(stderr, "lid=main ");
244        break;
245    case 1:
246        fprintf(stderr, "lid=radio ");
247        break;
248    case 2:
249        fprintf(stderr, "lid=events ");
250        break;
251    case 3:
252        fprintf(stderr, "lid=system ");
253        break;
254    case 4:
255        fprintf(stderr, "lid=crash ");
256        break;
257    case 5:
258        fprintf(stderr, "lid=security ");
259        break;
260    case 6:
261        fprintf(stderr, "lid=kernel ");
262        break;
263    default:
264        if (lid >= 0) {
265            fprintf(stderr, "lid=%d ", lid);
266        }
267    }
268
269    unsigned int len = msg->entry.len;
270    fprintf(stderr, "msg[%u]={", len);
271    unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg());
272    while(len) {
273        unsigned char *p = cp;
274        while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
275            ++p;
276        }
277        if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
278            fprintf(stderr, "\"");
279            while (*cp) {
280                if (*cp != '\n') {
281                    fprintf(stderr, "%c", *cp);
282                } else {
283                    fprintf(stderr, "\\n");
284                }
285                ++cp;
286                --len;
287            }
288            fprintf(stderr, "\"");
289        } else {
290            fprintf(stderr, "%02x", *cp);
291        }
292        ++cp;
293        if (--len) {
294            fprintf(stderr, ", ");
295        }
296    }
297    fprintf(stderr, "}\n");
298    fflush(stderr);
299}
300
301TEST(logd, both) {
302    log_msg msg;
303
304    // check if we can read any logs from logd
305    bool user_logger_available = false;
306    bool user_logger_content = false;
307
308    int fd = socket_local_client("logdr",
309                                 ANDROID_SOCKET_NAMESPACE_RESERVED,
310                                 SOCK_SEQPACKET);
311    if (fd >= 0) {
312        struct sigaction ignore, old_sigaction;
313        memset(&ignore, 0, sizeof(ignore));
314        ignore.sa_handler = caught_signal;
315        sigemptyset(&ignore.sa_mask);
316        sigaction(SIGALRM, &ignore, &old_sigaction);
317        unsigned int old_alarm = alarm(10);
318
319        static const char ask[] = "dumpAndClose lids=0,1,2,3";
320        user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);
321
322        user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;
323
324        if (user_logger_content) {
325            dump_log_msg("user", &msg, 3, -1);
326        }
327
328        alarm(old_alarm);
329        sigaction(SIGALRM, &old_sigaction, NULL);
330
331        close(fd);
332    }
333
334    // check if we can read any logs from kernel logger
335    bool kernel_logger_available = false;
336    bool kernel_logger_content = false;
337
338    static const char *loggers[] = {
339        "/dev/log/main",   "/dev/log_main",
340        "/dev/log/radio",  "/dev/log_radio",
341        "/dev/log/events", "/dev/log_events",
342        "/dev/log/system", "/dev/log_system",
343    };
344
345    for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) {
346        fd = open(loggers[i], O_RDONLY);
347        if (fd < 0) {
348            continue;
349        }
350        kernel_logger_available = true;
351        fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK);
352        int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
353        if (result > 0) {
354            kernel_logger_content = true;
355            dump_log_msg("kernel", &msg, 0, i / 2);
356        }
357        close(fd);
358    }
359
360    static const char yes[] = "\xE2\x9C\x93";
361    static const char no[] = "\xE2\x9c\x98";
362    fprintf(stderr,
363            "LOGGER  Available  Content\n"
364            "user    %-13s%s\n"
365            "kernel  %-13s%s\n"
366            " status %-11s%s\n",
367            (user_logger_available)   ? yes : no,
368            (user_logger_content)     ? yes : no,
369            (kernel_logger_available) ? yes : no,
370            (kernel_logger_content)   ? yes : no,
371            (user_logger_available && kernel_logger_available) ? "ERROR" : "ok",
372            (user_logger_content && kernel_logger_content) ? "ERROR" : "ok");
373
374    EXPECT_EQ(0, user_logger_available && kernel_logger_available);
375    EXPECT_EQ(0, !user_logger_available && !kernel_logger_available);
376    EXPECT_EQ(0, user_logger_content && kernel_logger_content);
377    EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
378}
379
380// BAD ROBOT
381//   Benchmark threshold are generally considered bad form unless there is
382//   is some human love applied to the continued maintenance and whether the
383//   thresholds are tuned on a per-target basis. Here we check if the values
384//   are more than double what is expected. Doubling will not prevent failure
385//   on busy or low-end systems that could have a tendency to stretch values.
386//
387//   The primary goal of this test is to simulate a spammy app (benchmark
388//   being the worst) and check to make sure the logger can deal with it
389//   appropriately by checking all the statistics are in an expected range.
390//
391TEST(logd, benchmark) {
392    size_t len;
393    char *buf;
394
395    alloc_statistics(&buf, &len);
396    bool benchmark_already_run = buf && find_benchmark_spam(buf);
397    delete [] buf;
398
399    if (benchmark_already_run) {
400        fprintf(stderr, "WARNING: spam already present and too much history\n"
401                        "         false OK for prune by worst UID check\n");
402    }
403
404    FILE *fp;
405
406    // Introduce some extreme spam for the worst UID filter
407    ASSERT_TRUE(NULL != (fp = popen(
408        "/data/nativetest/liblog-benchmarks/liblog-benchmarks",
409        "r")));
410
411    char buffer[5120];
412
413    static const char *benchmarks[] = {
414        "BM_log_maximum_retry ",
415        "BM_log_maximum ",
416        "BM_clock_overhead ",
417        "BM_log_overhead ",
418        "BM_log_latency ",
419        "BM_log_delay "
420    };
421    static const unsigned int log_maximum_retry = 0;
422    static const unsigned int log_maximum = 1;
423    static const unsigned int clock_overhead = 2;
424    static const unsigned int log_overhead = 3;
425    static const unsigned int log_latency = 4;
426    static const unsigned int log_delay = 5;
427
428    unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];
429
430    memset(ns, 0, sizeof(ns));
431
432    while (fgets(buffer, sizeof(buffer), fp)) {
433        for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
434            char *cp = strstr(buffer, benchmarks[i]);
435            if (!cp) {
436                continue;
437            }
438            sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]);
439            fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
440        }
441    }
442    int ret = pclose(fp);
443
444    if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
445        fprintf(stderr,
446                "WARNING: "
447                "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
448                "         can not perform test\n");
449        return;
450    }
451
452    EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user
453
454    EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user
455
456    EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
457
458    EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user
459
460    EXPECT_GE(10000000UL, ns[log_latency]); // 1453559 user space (background cgroup)
461
462    EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
463
464    for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
465        EXPECT_NE(0UL, ns[i]);
466    }
467
468    alloc_statistics(&buf, &len);
469
470    bool collected_statistics = !!buf;
471    EXPECT_EQ(true, collected_statistics);
472
473    ASSERT_TRUE(NULL != buf);
474
475    char *benchmark_statistics_found = find_benchmark_spam(buf);
476    ASSERT_TRUE(benchmark_statistics_found != NULL);
477
478    // Check how effective the SPAM filter is, parse out Now size.
479    // 0     root                      54164 147569
480    //                                 ^-- benchmark_statistics_found
481
482    unsigned long nowSpamSize = atol(benchmark_statistics_found);
483
484    delete [] buf;
485
486    ASSERT_NE(0UL, nowSpamSize);
487
488    // Determine if we have the spam filter enabled
489    int sock = socket_local_client("logd",
490                                   ANDROID_SOCKET_NAMESPACE_RESERVED,
491                                   SOCK_STREAM);
492
493    ASSERT_TRUE(sock >= 0);
494
495    static const char getPruneList[] = "getPruneList";
496    if (write(sock, getPruneList, sizeof(getPruneList)) > 0) {
497        char buffer[80];
498        memset(buffer, 0, sizeof(buffer));
499        read(sock, buffer, sizeof(buffer));
500        char *cp = strchr(buffer, '\n');
501        if (!cp || (cp[1] != '~') || (cp[2] != '!')) {
502            close(sock);
503            fprintf(stderr,
504                    "WARNING: "
505                    "Logger has SPAM filtration turned off \"%s\"\n", buffer);
506            return;
507        }
508    } else {
509        int save_errno = errno;
510        close(sock);
511        FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno);
512    }
513
514    static const unsigned long expected_absolute_minimum_log_size = 65536UL;
515    unsigned long totalSize = expected_absolute_minimum_log_size;
516    static const char getSize[] = {
517        'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ',
518        LOG_ID_MAIN + '0', '\0'
519    };
520    if (write(sock, getSize, sizeof(getSize)) > 0) {
521        char buffer[80];
522        memset(buffer, 0, sizeof(buffer));
523        read(sock, buffer, sizeof(buffer));
524        totalSize = atol(buffer);
525        if (totalSize < expected_absolute_minimum_log_size) {
526            fprintf(stderr,
527                    "WARNING: "
528                    "Logger had unexpected referenced size \"%s\"\n", buffer);
529            totalSize = expected_absolute_minimum_log_size;
530        }
531    }
532    close(sock);
533
534    // logd allows excursions to 110% of total size
535    totalSize = (totalSize * 11 ) / 10;
536
537    // 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
538    ASSERT_GT(totalSize, nowSpamSize * 2);
539}
540
541// b/26447386 confirm fixed
542void timeout_negative(const char *command) {
543    log_msg msg_wrap, msg_timeout;
544    bool content_wrap = false, content_timeout = false, written = false;
545    unsigned int alarm_wrap = 0, alarm_timeout = 0;
546    // A few tries to get it right just in case wrap kicks in due to
547    // content providers being active during the test.
548    int i = 3;
549
550    while (--i) {
551        int fd = socket_local_client("logdr",
552                                     ANDROID_SOCKET_NAMESPACE_RESERVED,
553                                     SOCK_SEQPACKET);
554        ASSERT_LT(0, fd);
555
556        std::string ask(command);
557
558        struct sigaction ignore, old_sigaction;
559        memset(&ignore, 0, sizeof(ignore));
560        ignore.sa_handler = caught_signal;
561        sigemptyset(&ignore.sa_mask);
562        sigaction(SIGALRM, &ignore, &old_sigaction);
563        unsigned int old_alarm = alarm(3);
564
565        size_t len = ask.length() + 1;
566        written = write(fd, ask.c_str(), len) == (ssize_t)len;
567        if (!written) {
568            alarm(old_alarm);
569            sigaction(SIGALRM, &old_sigaction, NULL);
570            close(fd);
571            continue;
572        }
573
574        content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
575
576        alarm_wrap = alarm(5);
577
578        content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
579        if (!content_timeout) { // make sure we hit dumpAndClose
580            content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
581        }
582
583        alarm_timeout = alarm((old_alarm <= 0)
584            ? old_alarm
585            : (old_alarm > (1 + 3 - alarm_wrap))
586                ? old_alarm - 3 + alarm_wrap
587                : 2);
588        sigaction(SIGALRM, &old_sigaction, NULL);
589
590        close(fd);
591
592        if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) {
593            break;
594        }
595    }
596
597    if (content_wrap) {
598        dump_log_msg("wrap", &msg_wrap, 3, -1);
599    }
600
601    if (content_timeout) {
602        dump_log_msg("timeout", &msg_timeout, 3, -1);
603    }
604
605    EXPECT_TRUE(written);
606    EXPECT_TRUE(content_wrap);
607    EXPECT_NE(0U, alarm_wrap);
608    EXPECT_TRUE(content_timeout);
609    EXPECT_NE(0U, alarm_timeout);
610}
611
612TEST(logd, timeout_no_start) {
613    timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6");
614}
615
616TEST(logd, timeout_start_epoch) {
617    timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000");
618}
619
620// b/26447386 refined behavior
621TEST(logd, timeout) {
622    log_msg msg_wrap, msg_timeout;
623    bool content_wrap = false, content_timeout = false, written = false;
624    unsigned int alarm_wrap = 0, alarm_timeout = 0;
625    // A few tries to get it right just in case wrap kicks in due to
626    // content providers being active during the test
627    int i = 5;
628    log_time now(android_log_clockid());
629    now.tv_sec -= 30; // reach back a moderate period of time
630
631    while (--i) {
632        int fd = socket_local_client("logdr",
633                                     ANDROID_SOCKET_NAMESPACE_RESERVED,
634                                     SOCK_SEQPACKET);
635        ASSERT_LT(0, fd);
636
637        std::string ask = android::base::StringPrintf(
638            "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%"
639                PRIu32 ".%09" PRIu32,
640            now.tv_sec, now.tv_nsec);
641
642        struct sigaction ignore, old_sigaction;
643        memset(&ignore, 0, sizeof(ignore));
644        ignore.sa_handler = caught_signal;
645        sigemptyset(&ignore.sa_mask);
646        sigaction(SIGALRM, &ignore, &old_sigaction);
647        unsigned int old_alarm = alarm(3);
648
649        size_t len = ask.length() + 1;
650        written = write(fd, ask.c_str(), len) == (ssize_t)len;
651        if (!written) {
652            alarm(old_alarm);
653            sigaction(SIGALRM, &old_sigaction, NULL);
654            close(fd);
655            continue;
656        }
657
658        content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
659
660        alarm_wrap = alarm(5);
661
662        content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
663        if (!content_timeout) { // make sure we hit dumpAndClose
664            content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
665        }
666
667        alarm_timeout = alarm((old_alarm <= 0)
668            ? old_alarm
669            : (old_alarm > (1 + 3 - alarm_wrap))
670                ? old_alarm - 3 + alarm_wrap
671                : 2);
672        sigaction(SIGALRM, &old_sigaction, NULL);
673
674        close(fd);
675
676        if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) {
677            break;
678        }
679
680        // modify start time in case content providers are relatively
681        // active _or_ inactive during the test.
682        if (content_timeout) {
683            log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
684            EXPECT_FALSE(msg < now);
685            if (msg > now) {
686                now = msg;
687                now.tv_sec += 30;
688                msg = log_time(android_log_clockid());
689                if (now > msg) {
690                    now = msg;
691                    --now.tv_sec;
692                }
693            }
694        } else {
695            now.tv_sec -= 120; // inactive, reach further back!
696        }
697    }
698
699    if (content_wrap) {
700        dump_log_msg("wrap", &msg_wrap, 3, -1);
701    }
702
703    if (content_timeout) {
704        dump_log_msg("timeout", &msg_timeout, 3, -1);
705    }
706
707    if (content_wrap || !content_timeout) {
708        fprintf(stderr, "now=%" PRIu32 ".%09" PRIu32 "\n",
709                now.tv_sec, now.tv_nsec);
710    }
711
712    EXPECT_TRUE(written);
713    EXPECT_FALSE(content_wrap);
714    EXPECT_EQ(0U, alarm_wrap);
715    EXPECT_TRUE(content_timeout);
716    EXPECT_NE(0U, alarm_timeout);
717}
718
719// b/27242723 confirmed fixed
720TEST(logd, SNDTIMEO) {
721    static const unsigned sndtimeo = LOGD_SNDTIMEO; // <sigh> it has to be done!
722    static const unsigned sleep_time = sndtimeo + 3;
723    static const unsigned alarm_time = sleep_time + 5;
724
725    int fd;
726
727    ASSERT_TRUE((fd = socket_local_client("logdr",
728                                 ANDROID_SOCKET_NAMESPACE_RESERVED,
729                                 SOCK_SEQPACKET)) > 0);
730
731    struct sigaction ignore, old_sigaction;
732    memset(&ignore, 0, sizeof(ignore));
733    ignore.sa_handler = caught_signal;
734    sigemptyset(&ignore.sa_mask);
735    sigaction(SIGALRM, &ignore, &old_sigaction);
736    unsigned int old_alarm = alarm(alarm_time);
737
738    static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources
739    bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask);
740    EXPECT_TRUE(reader_requested);
741
742    log_msg msg;
743    bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0;
744
745    EXPECT_TRUE(read_one);
746    if (read_one) {
747        dump_log_msg("user", &msg, 3, -1);
748    }
749
750    fprintf (stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo);
751    sleep(sleep_time);
752
753    // flush will block if we did not trigger. if it did, last entry returns 0
754    int recv_ret;
755    do {
756        recv_ret = recv(fd, msg.buf, sizeof(msg), 0);
757    } while (recv_ret > 0);
758    int save_errno = (recv_ret < 0) ? errno : 0;
759
760    EXPECT_NE(0U, alarm(old_alarm));
761    sigaction(SIGALRM, &old_sigaction, NULL);
762
763    EXPECT_EQ(0, recv_ret);
764    if (recv_ret > 0) {
765        dump_log_msg("user", &msg, 3, -1);
766    }
767    EXPECT_EQ(0, save_errno);
768
769    close(fd);
770}
771