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