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 */
my_android_logger_get_statistics(char * buf,size_t len)38 static 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
alloc_statistics(char ** buffer,size_t * length)70 static 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
find_benchmark_spam(char * cp)97 static 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
TEST(logd,statistics)158 TEST(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
caught_signal(int)203 static void caught_signal(int /* signum */) { }
204
dump_log_msg(const char * prefix,log_msg * msg,unsigned int version,int lid)205 static 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
TEST(logd,both)301 TEST(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 //
TEST(logd,benchmark)391 TEST(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
timeout_negative(const char * command)542 void 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
TEST(logd,timeout_no_start)612 TEST(logd, timeout_no_start) {
613 timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6");
614 }
615
TEST(logd,timeout_start_epoch)616 TEST(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
TEST(logd,timeout)621 TEST(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
TEST(logd,SNDTIMEO)720 TEST(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