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 #include <sys/stat.h>
24 #include <sys/types.h>
25 #include <unistd.h>
26
27 #include <string>
28
29 #include <android-base/macros.h>
30 #include <android-base/stringprintf.h>
31 #include <cutils/sockets.h>
32 #include <gtest/gtest.h>
33 #include <log/log.h>
34 #include <private/android_filesystem_config.h>
35 #ifdef __ANDROID__
36 #include <selinux/selinux.h>
37 #endif
38
39 #include "../LogReader.h" // pickup LOGD_SNDTIMEO
40 #include "../libaudit.h" // pickup AUDIT_RATE_LIMIT_*
41
send_to_control(char * buf,size_t len)42 static void send_to_control(char* buf, size_t len) {
43 int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED,
44 SOCK_STREAM);
45 if (sock >= 0) {
46 if (write(sock, buf, strlen(buf) + 1) > 0) {
47 ssize_t ret;
48 while ((ret = read(sock, buf, len)) > 0) {
49 if (((size_t)ret == len) || (len < PAGE_SIZE)) {
50 break;
51 }
52 len -= ret;
53 buf += ret;
54
55 struct pollfd p = {.fd = sock, .events = POLLIN, .revents = 0 };
56
57 ret = poll(&p, 1, 20);
58 if ((ret <= 0) || !(p.revents & POLLIN)) {
59 break;
60 }
61 }
62 }
63 close(sock);
64 }
65 }
66
67 /*
68 * returns statistics
69 */
my_android_logger_get_statistics(char * buf,size_t len)70 static void my_android_logger_get_statistics(char* buf, size_t len) {
71 snprintf(buf, len, "getStatistics 0 1 2 3 4");
72 send_to_control(buf, len);
73 }
74
alloc_statistics(char ** buffer,size_t * length)75 static void alloc_statistics(char** buffer, size_t* length) {
76 size_t len = 8192;
77 char* buf;
78
79 for (int retry = 32; (retry >= 0); delete[] buf, --retry) {
80 buf = new char[len];
81 my_android_logger_get_statistics(buf, len);
82
83 buf[len - 1] = '\0';
84 size_t ret = atol(buf) + 1;
85 if (ret < 4) {
86 delete[] buf;
87 buf = NULL;
88 break;
89 }
90 bool check = ret <= len;
91 len = ret;
92 if (check) {
93 break;
94 }
95 len += len / 8; // allow for some slop
96 }
97 *buffer = buf;
98 *length = len;
99 }
100
find_benchmark_spam(char * cp)101 static char* find_benchmark_spam(char* cp) {
102 // liblog_benchmarks has been run designed to SPAM. The signature of
103 // a noisiest UID statistics is:
104 //
105 // Chattiest UIDs in main log buffer: Size Pruned
106 // UID PACKAGE BYTES LINES
107 // 0 root 54164 147569
108 //
109 char* benchmark = NULL;
110 do {
111 static const char signature[] = "\n0 root ";
112
113 benchmark = strstr(cp, signature);
114 if (!benchmark) {
115 break;
116 }
117 cp = benchmark + sizeof(signature);
118 while (isspace(*cp)) {
119 ++cp;
120 }
121 benchmark = cp;
122 #ifdef DEBUG
123 char* end = strstr(benchmark, "\n");
124 if (end == NULL) {
125 end = benchmark + strlen(benchmark);
126 }
127 fprintf(stderr, "parse for spam counter in \"%.*s\"\n",
128 (int)(end - benchmark), benchmark);
129 #endif
130 // content
131 while (isdigit(*cp)) {
132 ++cp;
133 }
134 while (isspace(*cp)) {
135 ++cp;
136 }
137 // optional +/- field?
138 if ((*cp == '-') || (*cp == '+')) {
139 while (isdigit(*++cp) || (*cp == '.') || (*cp == '%') ||
140 (*cp == 'X')) {
141 ;
142 }
143 while (isspace(*cp)) {
144 ++cp;
145 }
146 }
147 // number of entries pruned
148 unsigned long value = 0;
149 while (isdigit(*cp)) {
150 value = value * 10ULL + *cp - '0';
151 ++cp;
152 }
153 if (value > 10UL) {
154 break;
155 }
156 benchmark = NULL;
157 } while (*cp);
158 return benchmark;
159 }
160
TEST(logd,statistics)161 TEST(logd, statistics) {
162 size_t len;
163 char* buf;
164
165 alloc_statistics(&buf, &len);
166
167 ASSERT_TRUE(NULL != buf);
168
169 // remove trailing FF
170 char* cp = buf + len - 1;
171 *cp = '\0';
172 bool truncated = *--cp != '\f';
173 if (!truncated) {
174 *cp = '\0';
175 }
176
177 // squash out the byte count
178 cp = buf;
179 if (!truncated) {
180 while (isdigit(*cp) || (*cp == '\n')) {
181 ++cp;
182 }
183 }
184
185 fprintf(stderr, "%s", cp);
186
187 EXPECT_LT((size_t)64, strlen(cp));
188
189 EXPECT_EQ(0, truncated);
190
191 char* main_logs = strstr(cp, "\nChattiest UIDs in main ");
192 EXPECT_TRUE(NULL != main_logs);
193
194 char* radio_logs = strstr(cp, "\nChattiest UIDs in radio ");
195 if (!radio_logs)
196 GTEST_LOG_(INFO) << "Value of: NULL != radio_logs\n"
197 "Actual: false\n"
198 "Expected: false\n";
199
200 char* system_logs = strstr(cp, "\nChattiest UIDs in system ");
201 EXPECT_TRUE(NULL != system_logs);
202
203 char* events_logs = strstr(cp, "\nChattiest UIDs in events ");
204 EXPECT_TRUE(NULL != events_logs);
205
206 delete[] buf;
207 }
208
caught_signal(int)209 static void caught_signal(int /* signum */) {
210 }
211
dump_log_msg(const char * prefix,log_msg * msg,unsigned int version,int lid)212 static void dump_log_msg(const char* prefix, log_msg* msg, unsigned int version,
213 int lid) {
214 std::cout << std::flush;
215 std::cerr << std::flush;
216 fflush(stdout);
217 fflush(stderr);
218 switch (msg->entry.hdr_size) {
219 case 0:
220 version = 1;
221 break;
222
223 case sizeof(msg->entry_v2): /* PLUS case sizeof(msg->entry_v3): */
224 if (version == 0) {
225 version = (msg->entry_v3.lid < LOG_ID_MAX) ? 3 : 2;
226 }
227 break;
228
229 case sizeof(msg->entry_v4):
230 if (version == 0) {
231 version = 4;
232 }
233 break;
234 }
235
236 fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
237 if (version != 1) {
238 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
239 }
240 fprintf(stderr, "pid=%u tid=%u %u.%09u ", msg->entry.pid, msg->entry.tid,
241 msg->entry.sec, msg->entry.nsec);
242 switch (version) {
243 case 1:
244 break;
245 case 2:
246 fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
247 break;
248 case 3:
249 default:
250 lid = msg->entry.lid;
251 break;
252 }
253
254 switch (lid) {
255 case 0:
256 fprintf(stderr, "lid=main ");
257 break;
258 case 1:
259 fprintf(stderr, "lid=radio ");
260 break;
261 case 2:
262 fprintf(stderr, "lid=events ");
263 break;
264 case 3:
265 fprintf(stderr, "lid=system ");
266 break;
267 case 4:
268 fprintf(stderr, "lid=crash ");
269 break;
270 case 5:
271 fprintf(stderr, "lid=security ");
272 break;
273 case 6:
274 fprintf(stderr, "lid=kernel ");
275 break;
276 default:
277 if (lid >= 0) {
278 fprintf(stderr, "lid=%d ", lid);
279 }
280 }
281
282 unsigned int len = msg->entry.len;
283 fprintf(stderr, "msg[%u]={", len);
284 unsigned char* cp = reinterpret_cast<unsigned char*>(msg->msg());
285 if (!cp) {
286 static const unsigned char garbage[] = "<INVALID>";
287 cp = const_cast<unsigned char*>(garbage);
288 len = strlen(reinterpret_cast<const char*>(garbage));
289 }
290 while (len) {
291 unsigned char* p = cp;
292 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
293 ++p;
294 }
295 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
296 fprintf(stderr, "\"");
297 while (*cp) {
298 if (*cp != '\n') {
299 fprintf(stderr, "%c", *cp);
300 } else {
301 fprintf(stderr, "\\n");
302 }
303 ++cp;
304 --len;
305 }
306 fprintf(stderr, "\"");
307 } else {
308 fprintf(stderr, "%02x", *cp);
309 }
310 ++cp;
311 if (--len) {
312 fprintf(stderr, ", ");
313 }
314 }
315 fprintf(stderr, "}\n");
316 fflush(stderr);
317 }
318
TEST(logd,both)319 TEST(logd, both) {
320 log_msg msg;
321
322 // check if we can read any logs from logd
323 bool user_logger_available = false;
324 bool user_logger_content = false;
325
326 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
327 SOCK_SEQPACKET);
328 if (fd >= 0) {
329 struct sigaction ignore, old_sigaction;
330 memset(&ignore, 0, sizeof(ignore));
331 ignore.sa_handler = caught_signal;
332 sigemptyset(&ignore.sa_mask);
333 sigaction(SIGALRM, &ignore, &old_sigaction);
334 unsigned int old_alarm = alarm(10);
335
336 static const char ask[] = "dumpAndClose lids=0,1,2,3";
337 user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);
338
339 user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;
340
341 if (user_logger_content) {
342 dump_log_msg("user", &msg, 3, -1);
343 }
344
345 alarm(old_alarm);
346 sigaction(SIGALRM, &old_sigaction, NULL);
347
348 close(fd);
349 }
350
351 // check if we can read any logs from kernel logger
352 bool kernel_logger_available = false;
353 bool kernel_logger_content = false;
354
355 static const char* loggers[] = {
356 "/dev/log/main", "/dev/log_main", "/dev/log/radio",
357 "/dev/log_radio", "/dev/log/events", "/dev/log_events",
358 "/dev/log/system", "/dev/log_system",
359 };
360
361 for (unsigned int i = 0; i < arraysize(loggers); ++i) {
362 fd = open(loggers[i], O_RDONLY);
363 if (fd < 0) {
364 continue;
365 }
366 kernel_logger_available = true;
367 fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK);
368 int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
369 if (result > 0) {
370 kernel_logger_content = true;
371 dump_log_msg("kernel", &msg, 0, i / 2);
372 }
373 close(fd);
374 }
375
376 static const char yes[] = "\xE2\x9C\x93";
377 static const char no[] = "\xE2\x9c\x98";
378 fprintf(stderr,
379 "LOGGER Available Content\n"
380 "user %-13s%s\n"
381 "kernel %-13s%s\n"
382 " status %-11s%s\n",
383 (user_logger_available) ? yes : no, (user_logger_content) ? yes : no,
384 (kernel_logger_available) ? yes : no,
385 (kernel_logger_content) ? yes : no,
386 (user_logger_available && kernel_logger_available) ? "ERROR" : "ok",
387 (user_logger_content && kernel_logger_content) ? "ERROR" : "ok");
388
389 EXPECT_EQ(0, user_logger_available && kernel_logger_available);
390 EXPECT_EQ(0, !user_logger_available && !kernel_logger_available);
391 EXPECT_EQ(0, user_logger_content && kernel_logger_content);
392 EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
393 }
394
395 // BAD ROBOT
396 // Benchmark threshold are generally considered bad form unless there is
397 // is some human love applied to the continued maintenance and whether the
398 // thresholds are tuned on a per-target basis. Here we check if the values
399 // are more than double what is expected. Doubling will not prevent failure
400 // on busy or low-end systems that could have a tendency to stretch values.
401 //
402 // The primary goal of this test is to simulate a spammy app (benchmark
403 // being the worst) and check to make sure the logger can deal with it
404 // appropriately by checking all the statistics are in an expected range.
405 //
TEST(logd,benchmark)406 TEST(logd, benchmark) {
407 size_t len;
408 char* buf;
409
410 alloc_statistics(&buf, &len);
411 bool benchmark_already_run = buf && find_benchmark_spam(buf);
412 delete[] buf;
413
414 if (benchmark_already_run) {
415 fprintf(stderr,
416 "WARNING: spam already present and too much history\n"
417 " false OK for prune by worst UID check\n");
418 }
419
420 FILE* fp;
421
422 // Introduce some extreme spam for the worst UID filter
423 ASSERT_TRUE(
424 NULL !=
425 (fp = popen("/data/nativetest/liblog-benchmarks/liblog-benchmarks"
426 " BM_log_maximum_retry"
427 " BM_log_maximum"
428 " BM_clock_overhead"
429 " BM_log_overhead"
430 " BM_log_latency"
431 " BM_log_delay",
432 "r")));
433
434 char buffer[5120];
435
436 static const char* benchmarks[] = {
437 "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ",
438 "BM_log_overhead ", "BM_log_latency ", "BM_log_delay "
439 };
440 static const unsigned int log_maximum_retry = 0;
441 static const unsigned int log_maximum = 1;
442 static const unsigned int clock_overhead = 2;
443 static const unsigned int log_overhead = 3;
444 static const unsigned int log_latency = 4;
445 static const unsigned int log_delay = 5;
446
447 unsigned long ns[arraysize(benchmarks)];
448
449 memset(ns, 0, sizeof(ns));
450
451 while (fgets(buffer, sizeof(buffer), fp)) {
452 for (unsigned i = 0; i < arraysize(ns); ++i) {
453 char* cp = strstr(buffer, benchmarks[i]);
454 if (!cp) {
455 continue;
456 }
457 sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]);
458 fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
459 }
460 }
461 int ret = pclose(fp);
462
463 if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
464 fprintf(stderr,
465 "WARNING: "
466 "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
467 " can not perform test\n");
468 return;
469 }
470
471 EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user
472
473 EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user
474
475 EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
476
477 EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user
478
479 EXPECT_GE(10000000UL,
480 ns[log_latency]); // 1453559 user space (background cgroup)
481
482 EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
483
484 for (unsigned i = 0; i < arraysize(ns); ++i) {
485 EXPECT_NE(0UL, ns[i]);
486 }
487
488 alloc_statistics(&buf, &len);
489
490 bool collected_statistics = !!buf;
491 EXPECT_EQ(true, collected_statistics);
492
493 ASSERT_TRUE(NULL != buf);
494
495 char* benchmark_statistics_found = find_benchmark_spam(buf);
496 ASSERT_TRUE(benchmark_statistics_found != NULL);
497
498 // Check how effective the SPAM filter is, parse out Now size.
499 // 0 root 54164 147569
500 // ^-- benchmark_statistics_found
501
502 unsigned long nowSpamSize = atol(benchmark_statistics_found);
503
504 delete[] buf;
505
506 ASSERT_NE(0UL, nowSpamSize);
507
508 // Determine if we have the spam filter enabled
509 int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED,
510 SOCK_STREAM);
511
512 ASSERT_TRUE(sock >= 0);
513
514 static const char getPruneList[] = "getPruneList";
515 if (write(sock, getPruneList, sizeof(getPruneList)) > 0) {
516 char buffer[80];
517 memset(buffer, 0, sizeof(buffer));
518 read(sock, buffer, sizeof(buffer));
519 char* cp = strchr(buffer, '\n');
520 if (!cp || (cp[1] != '~') || (cp[2] != '!')) {
521 close(sock);
522 fprintf(stderr,
523 "WARNING: "
524 "Logger has SPAM filtration turned off \"%s\"\n",
525 buffer);
526 return;
527 }
528 } else {
529 int save_errno = errno;
530 close(sock);
531 FAIL() << "Can not send " << getPruneList << " to logger -- "
532 << strerror(save_errno);
533 }
534
535 static const unsigned long expected_absolute_minimum_log_size = 65536UL;
536 unsigned long totalSize = expected_absolute_minimum_log_size;
537 static const char getSize[] = { 'g', 'e', 't', 'L', 'o', 'g',
538 'S', 'i', 'z', 'e', ' ', LOG_ID_MAIN + '0',
539 '\0' };
540 if (write(sock, getSize, sizeof(getSize)) > 0) {
541 char buffer[80];
542 memset(buffer, 0, sizeof(buffer));
543 read(sock, buffer, sizeof(buffer));
544 totalSize = atol(buffer);
545 if (totalSize < expected_absolute_minimum_log_size) {
546 fprintf(stderr,
547 "WARNING: "
548 "Logger had unexpected referenced size \"%s\"\n",
549 buffer);
550 totalSize = expected_absolute_minimum_log_size;
551 }
552 }
553 close(sock);
554
555 // logd allows excursions to 110% of total size
556 totalSize = (totalSize * 11) / 10;
557
558 // 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
559 ASSERT_GT(totalSize, nowSpamSize * 2);
560 }
561
562 // b/26447386 confirm fixed
timeout_negative(const char * command)563 void timeout_negative(const char* command) {
564 log_msg msg_wrap, msg_timeout;
565 bool content_wrap = false, content_timeout = false, written = false;
566 unsigned int alarm_wrap = 0, alarm_timeout = 0;
567 // A few tries to get it right just in case wrap kicks in due to
568 // content providers being active during the test.
569 int i = 3;
570
571 while (--i) {
572 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
573 SOCK_SEQPACKET);
574 ASSERT_LT(0, fd);
575
576 std::string ask(command);
577
578 struct sigaction ignore, old_sigaction;
579 memset(&ignore, 0, sizeof(ignore));
580 ignore.sa_handler = caught_signal;
581 sigemptyset(&ignore.sa_mask);
582 sigaction(SIGALRM, &ignore, &old_sigaction);
583 unsigned int old_alarm = alarm(3);
584
585 size_t len = ask.length() + 1;
586 written = write(fd, ask.c_str(), len) == (ssize_t)len;
587 if (!written) {
588 alarm(old_alarm);
589 sigaction(SIGALRM, &old_sigaction, NULL);
590 close(fd);
591 continue;
592 }
593
594 // alarm triggers at 50% of the --wrap time out
595 content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
596
597 alarm_wrap = alarm(5);
598
599 // alarm triggers at 133% of the --wrap time out
600 content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
601 if (!content_timeout) { // make sure we hit dumpAndClose
602 content_timeout =
603 recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
604 }
605
606 alarm_timeout =
607 alarm((old_alarm <= 0) ? old_alarm
608 : (old_alarm > (1 + 3 - alarm_wrap))
609 ? old_alarm - 3 + alarm_wrap
610 : 2);
611 sigaction(SIGALRM, &old_sigaction, NULL);
612
613 close(fd);
614
615 if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) {
616 break;
617 }
618 }
619
620 if (content_wrap) {
621 dump_log_msg("wrap", &msg_wrap, 3, -1);
622 }
623
624 if (content_timeout) {
625 dump_log_msg("timeout", &msg_timeout, 3, -1);
626 }
627
628 EXPECT_TRUE(written);
629 EXPECT_TRUE(content_wrap);
630 EXPECT_NE(0U, alarm_wrap);
631 EXPECT_TRUE(content_timeout);
632 EXPECT_NE(0U, alarm_timeout);
633 }
634
TEST(logd,timeout_no_start)635 TEST(logd, timeout_no_start) {
636 timeout_negative("dumpAndClose lids=0,1,2,3,4,5 timeout=6");
637 }
638
TEST(logd,timeout_start_epoch)639 TEST(logd, timeout_start_epoch) {
640 timeout_negative(
641 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=0.000000000");
642 }
643
644 // b/26447386 refined behavior
TEST(logd,timeout)645 TEST(logd, timeout) {
646 // b/33962045 This test interferes with other log reader tests that
647 // follow because of file descriptor socket persistence in the same
648 // process. So let's fork it to isolate it from giving us pain.
649
650 pid_t pid = fork();
651
652 if (pid) {
653 siginfo_t info = {};
654 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
655 ASSERT_EQ(0, info.si_status);
656 return;
657 }
658
659 log_msg msg_wrap, msg_timeout;
660 bool content_wrap = false, content_timeout = false, written = false;
661 unsigned int alarm_wrap = 0, alarm_timeout = 0;
662 // A few tries to get it right just in case wrap kicks in due to
663 // content providers being active during the test.
664 int i = 5;
665 log_time now(android_log_clockid());
666 now.tv_sec -= 30; // reach back a moderate period of time
667
668 while (--i) {
669 int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
670 SOCK_SEQPACKET);
671 int save_errno = errno;
672 if (fd < 0) {
673 fprintf(stderr, "failed to open /dev/socket/logdr %s\n",
674 strerror(save_errno));
675 _exit(fd);
676 }
677
678 std::string ask = android::base::StringPrintf(
679 "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32
680 ".%09" PRIu32,
681 now.tv_sec, now.tv_nsec);
682
683 struct sigaction ignore, old_sigaction;
684 memset(&ignore, 0, sizeof(ignore));
685 ignore.sa_handler = caught_signal;
686 sigemptyset(&ignore.sa_mask);
687 sigaction(SIGALRM, &ignore, &old_sigaction);
688 unsigned int old_alarm = alarm(3);
689
690 size_t len = ask.length() + 1;
691 written = write(fd, ask.c_str(), len) == (ssize_t)len;
692 if (!written) {
693 alarm(old_alarm);
694 sigaction(SIGALRM, &old_sigaction, NULL);
695 close(fd);
696 continue;
697 }
698
699 // alarm triggers at 50% of the --wrap time out
700 content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
701
702 alarm_wrap = alarm(5);
703
704 // alarm triggers at 133% of the --wrap time out
705 content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
706 if (!content_timeout) { // make sure we hit dumpAndClose
707 content_timeout =
708 recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
709 }
710
711 alarm_timeout =
712 alarm((old_alarm <= 0) ? old_alarm
713 : (old_alarm > (1 + 3 - alarm_wrap))
714 ? old_alarm - 3 + alarm_wrap
715 : 2);
716 sigaction(SIGALRM, &old_sigaction, NULL);
717
718 close(fd);
719
720 if (!content_wrap && !alarm_wrap && content_timeout && alarm_timeout) {
721 break;
722 }
723
724 // modify start time in case content providers are relatively
725 // active _or_ inactive during the test.
726 if (content_timeout) {
727 log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
728 if (msg < now) {
729 fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec,
730 msg_timeout.entry.nsec, (unsigned)now.tv_sec,
731 (unsigned)now.tv_nsec);
732 _exit(-1);
733 }
734 if (msg > now) {
735 now = msg;
736 now.tv_sec += 30;
737 msg = log_time(android_log_clockid());
738 if (now > msg) {
739 now = msg;
740 --now.tv_sec;
741 }
742 }
743 } else {
744 now.tv_sec -= 120; // inactive, reach further back!
745 }
746 }
747
748 if (content_wrap) {
749 dump_log_msg("wrap", &msg_wrap, 3, -1);
750 }
751
752 if (content_timeout) {
753 dump_log_msg("timeout", &msg_timeout, 3, -1);
754 }
755
756 if (content_wrap || !content_timeout) {
757 fprintf(stderr, "now=%" PRIu32 ".%09" PRIu32 "\n", now.tv_sec,
758 now.tv_nsec);
759 }
760
761 EXPECT_TRUE(written);
762 EXPECT_FALSE(content_wrap);
763 EXPECT_EQ(0U, alarm_wrap);
764 EXPECT_TRUE(content_timeout);
765 EXPECT_NE(0U, alarm_timeout);
766
767 _exit(!written + content_wrap + alarm_wrap + !content_timeout +
768 !alarm_timeout);
769 }
770
771 // b/27242723 confirmed fixed
TEST(logd,SNDTIMEO)772 TEST(logd, SNDTIMEO) {
773 static const unsigned sndtimeo =
774 LOGD_SNDTIMEO; // <sigh> it has to be done!
775 static const unsigned sleep_time = sndtimeo + 3;
776 static const unsigned alarm_time = sleep_time + 5;
777
778 int fd;
779
780 ASSERT_TRUE(
781 (fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
782 SOCK_SEQPACKET)) > 0);
783
784 struct sigaction ignore, old_sigaction;
785 memset(&ignore, 0, sizeof(ignore));
786 ignore.sa_handler = caught_signal;
787 sigemptyset(&ignore.sa_mask);
788 sigaction(SIGALRM, &ignore, &old_sigaction);
789 unsigned int old_alarm = alarm(alarm_time);
790
791 static const char ask[] = "stream lids=0,1,2,3,4,5,6"; // all sources
792 bool reader_requested = write(fd, ask, sizeof(ask)) == sizeof(ask);
793 EXPECT_TRUE(reader_requested);
794
795 log_msg msg;
796 bool read_one = recv(fd, msg.buf, sizeof(msg), 0) > 0;
797
798 EXPECT_TRUE(read_one);
799 if (read_one) {
800 dump_log_msg("user", &msg, 3, -1);
801 }
802
803 fprintf(stderr, "Sleep for >%d seconds logd SO_SNDTIMEO ...\n", sndtimeo);
804 sleep(sleep_time);
805
806 // flush will block if we did not trigger. if it did, last entry returns 0
807 int recv_ret;
808 do {
809 recv_ret = recv(fd, msg.buf, sizeof(msg), 0);
810 } while (recv_ret > 0);
811 int save_errno = (recv_ret < 0) ? errno : 0;
812
813 EXPECT_NE(0U, alarm(old_alarm));
814 sigaction(SIGALRM, &old_sigaction, NULL);
815
816 EXPECT_EQ(0, recv_ret);
817 if (recv_ret > 0) {
818 dump_log_msg("user", &msg, 3, -1);
819 }
820 EXPECT_EQ(0, save_errno);
821
822 close(fd);
823 }
824
TEST(logd,getEventTag_list)825 TEST(logd, getEventTag_list) {
826 #ifdef __ANDROID__
827 char buffer[256];
828 memset(buffer, 0, sizeof(buffer));
829 snprintf(buffer, sizeof(buffer), "getEventTag name=*");
830 send_to_control(buffer, sizeof(buffer));
831 buffer[sizeof(buffer) - 1] = '\0';
832 char* cp;
833 long ret = strtol(buffer, &cp, 10);
834 EXPECT_GT(ret, 4096);
835 #else
836 GTEST_LOG_(INFO) << "This test does nothing.\n";
837 #endif
838 }
839
TEST(logd,getEventTag_42)840 TEST(logd, getEventTag_42) {
841 #ifdef __ANDROID__
842 char buffer[256];
843 memset(buffer, 0, sizeof(buffer));
844 snprintf(buffer, sizeof(buffer), "getEventTag id=42");
845 send_to_control(buffer, sizeof(buffer));
846 buffer[sizeof(buffer) - 1] = '\0';
847 char* cp;
848 long ret = strtol(buffer, &cp, 10);
849 EXPECT_GT(ret, 16);
850 EXPECT_TRUE(strstr(buffer, "\t(to life the universe etc|3)") != NULL);
851 EXPECT_TRUE(strstr(buffer, "answer") != NULL);
852 #else
853 GTEST_LOG_(INFO) << "This test does nothing.\n";
854 #endif
855 }
856
TEST(logd,getEventTag_newentry)857 TEST(logd, getEventTag_newentry) {
858 #ifdef __ANDROID__
859 char buffer[256];
860 memset(buffer, 0, sizeof(buffer));
861 log_time now(CLOCK_MONOTONIC);
862 char name[64];
863 snprintf(name, sizeof(name), "a%" PRIu64, now.nsec());
864 snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"",
865 name);
866 send_to_control(buffer, sizeof(buffer));
867 buffer[sizeof(buffer) - 1] = '\0';
868 char* cp;
869 long ret = strtol(buffer, &cp, 10);
870 EXPECT_GT(ret, 16);
871 EXPECT_TRUE(strstr(buffer, "\t(new|1)") != NULL);
872 EXPECT_TRUE(strstr(buffer, name) != NULL);
873 // ToDo: also look for this in /data/misc/logd/event-log-tags and
874 // /dev/event-log-tags.
875 #else
876 GTEST_LOG_(INFO) << "This test does nothing.\n";
877 #endif
878 }
879
get4LE(const char * src)880 static inline int32_t get4LE(const char* src) {
881 return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
882 }
883
__android_log_btwrite_multiple__helper(int count)884 void __android_log_btwrite_multiple__helper(int count) {
885 log_time ts(CLOCK_MONOTONIC);
886
887 log_time ts1(CLOCK_MONOTONIC);
888
889 // We fork to create a unique pid for the submitted log messages
890 // so that we do not collide with the other _multiple_ tests.
891
892 pid_t pid = fork();
893
894 if (pid == 0) {
895 // child
896 for (int i = count; i; --i) {
897 ASSERT_LT(
898 0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
899 usleep(100);
900 }
901 ASSERT_LT(0,
902 __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
903 usleep(1000000);
904
905 _exit(0);
906 }
907
908 siginfo_t info = {};
909 ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
910 ASSERT_EQ(0, info.si_status);
911
912 struct logger_list* logger_list;
913 ASSERT_TRUE(NULL !=
914 (logger_list = android_logger_list_open(
915 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK,
916 0, pid)));
917
918 int expected_count = (count < 2) ? count : 2;
919 int expected_chatty_count = (count <= 2) ? 0 : 1;
920 int expected_identical_count = (count < 2) ? 0 : (count - 2);
921 static const int expected_expire_count = 0;
922
923 count = 0;
924 int second_count = 0;
925 int chatty_count = 0;
926 int identical_count = 0;
927 int expire_count = 0;
928
929 for (;;) {
930 log_msg log_msg;
931 if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
932
933 if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) ||
934 (log_msg.id() != LOG_ID_EVENTS))
935 continue;
936
937 char* eventData = log_msg.msg();
938 if (!eventData) continue;
939
940 uint32_t tag = get4LE(eventData);
941
942 if ((eventData[4] == EVENT_TYPE_LONG) &&
943 (log_msg.entry.len == (4 + 1 + 8))) {
944 if (tag != 0) continue;
945
946 log_time tx(eventData + 4 + 1);
947 if (ts == tx) {
948 ++count;
949 } else if (ts1 == tx) {
950 ++second_count;
951 }
952 } else if (eventData[4] == EVENT_TYPE_STRING) {
953 if (tag != CHATTY_LOG_TAG) continue;
954 ++chatty_count;
955 // int len = get4LE(eventData + 4 + 1);
956 log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0';
957 const char* cp;
958 if ((cp = strstr(eventData + 4 + 1 + 4, " identical "))) {
959 unsigned val = 0;
960 sscanf(cp, " identical %u lines", &val);
961 identical_count += val;
962 } else if ((cp = strstr(eventData + 4 + 1 + 4, " expire "))) {
963 unsigned val = 0;
964 sscanf(cp, " expire %u lines", &val);
965 expire_count += val;
966 }
967 }
968 }
969
970 android_logger_list_close(logger_list);
971
972 EXPECT_EQ(expected_count, count);
973 EXPECT_EQ(1, second_count);
974 EXPECT_EQ(expected_chatty_count, chatty_count);
975 EXPECT_EQ(expected_identical_count, identical_count);
976 EXPECT_EQ(expected_expire_count, expire_count);
977 }
978
TEST(logd,multiple_test_1)979 TEST(logd, multiple_test_1) {
980 __android_log_btwrite_multiple__helper(1);
981 }
982
TEST(logd,multiple_test_2)983 TEST(logd, multiple_test_2) {
984 __android_log_btwrite_multiple__helper(2);
985 }
986
TEST(logd,multiple_test_3)987 TEST(logd, multiple_test_3) {
988 __android_log_btwrite_multiple__helper(3);
989 }
990
TEST(logd,multiple_test_10)991 TEST(logd, multiple_test_10) {
992 __android_log_btwrite_multiple__helper(10);
993 }
994
995 #ifdef __ANDROID__
996 // returns violating pid
sepolicy_rate(unsigned rate,unsigned num)997 static pid_t sepolicy_rate(unsigned rate, unsigned num) {
998 pid_t pid = fork();
999
1000 if (pid) {
1001 siginfo_t info = {};
1002 if (TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED))) return 0;
1003 if (info.si_status) return 0;
1004 return pid;
1005 }
1006
1007 // We may have DAC, but let's not have MAC
1008 if (setcon("u:object_r:shell:s0") < 0) {
1009 int save_errno = errno;
1010 security_context_t context;
1011 getcon(&context);
1012 fprintf(stderr, "setcon(\"u:r:shell:s0\") failed @\"%s\" %s\n", context,
1013 strerror(save_errno));
1014 freecon(context);
1015 _exit(-1);
1016 // NOTREACHED
1017 return 0;
1018 }
1019
1020 // The key here is we are root, but we are in u:r:shell:s0,
1021 // and the directory does not provide us DAC access
1022 // (eg: 0700 system system) so we trigger the pair dac_override
1023 // and dac_read_search on every try to get past the message
1024 // de-duper. We will also rotate the file name in the directory
1025 // as another measure.
1026 static const char file[] = "/data/backup/cannot_access_directory_%u";
1027 static const unsigned avc_requests_per_access = 2;
1028
1029 rate /= avc_requests_per_access;
1030 useconds_t usec;
1031 if (rate == 0) {
1032 rate = 1;
1033 usec = 2000000;
1034 } else {
1035 usec = (1000000 + (rate / 2)) / rate;
1036 }
1037 num = (num + (avc_requests_per_access / 2)) / avc_requests_per_access;
1038
1039 if (usec < 2) usec = 2;
1040
1041 while (num > 0) {
1042 if (access(android::base::StringPrintf(file, num).c_str(), F_OK) == 0) {
1043 _exit(-1);
1044 // NOTREACHED
1045 return 0;
1046 }
1047 usleep(usec);
1048 --num;
1049 }
1050 _exit(0);
1051 // NOTREACHED
1052 return 0;
1053 }
1054
count_avc(pid_t pid)1055 static int count_avc(pid_t pid) {
1056 int count = 0;
1057
1058 if (pid == 0) return count;
1059
1060 struct logger_list* logger_list;
1061 if (!(logger_list = android_logger_list_open(
1062 LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, pid)))
1063 return count;
1064 for (;;) {
1065 log_msg log_msg;
1066
1067 if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
1068
1069 if ((log_msg.entry.pid != pid) || (log_msg.entry.len < (4 + 1 + 8)) ||
1070 (log_msg.id() != LOG_ID_EVENTS))
1071 continue;
1072
1073 char* eventData = log_msg.msg();
1074 if (!eventData) continue;
1075
1076 uint32_t tag = get4LE(eventData);
1077 if (tag != AUDITD_LOG_TAG) continue;
1078
1079 if (eventData[4] != EVENT_TYPE_STRING) continue;
1080
1081 // int len = get4LE(eventData + 4 + 1);
1082 log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0';
1083 const char* cp = strstr(eventData + 4 + 1 + 4, "): avc: denied");
1084 if (!cp) continue;
1085
1086 ++count;
1087 }
1088
1089 android_logger_list_close(logger_list);
1090
1091 return count;
1092 }
1093 #endif
1094
TEST(logd,sepolicy_rate_limiter_maximum)1095 TEST(logd, sepolicy_rate_limiter_maximum) {
1096 #ifdef __ANDROID__
1097 static const int rate = AUDIT_RATE_LIMIT_MAX;
1098 static const int duration = 2;
1099 // Two seconds of a liveable sustained rate
1100 EXPECT_EQ(rate * duration, count_avc(sepolicy_rate(rate, rate * duration)));
1101 #else
1102 GTEST_LOG_(INFO) << "This test does nothing.\n";
1103 #endif
1104 }
1105
TEST(logd,sepolicy_rate_limiter_sub_burst)1106 TEST(logd, sepolicy_rate_limiter_sub_burst) {
1107 #ifdef __ANDROID__
1108 // maximum period below half way between sustainable and burst rate.
1109 static const int threshold =
1110 ((AUDIT_RATE_LIMIT_BURST_DURATION *
1111 (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) +
1112 1) /
1113 2;
1114 static const int rate = (threshold / AUDIT_RATE_LIMIT_BURST_DURATION) - 1;
1115 static const int duration = AUDIT_RATE_LIMIT_BURST_DURATION;
1116 EXPECT_EQ(rate * duration, count_avc(sepolicy_rate(rate, rate * duration)));
1117 #else
1118 GTEST_LOG_(INFO) << "This test does nothing.\n";
1119 #endif
1120 }
1121
TEST(logd,sepolicy_rate_limiter_spam)1122 TEST(logd, sepolicy_rate_limiter_spam) {
1123 #ifdef __ANDROID__
1124 // maximum period of double the maximum burst rate
1125 static const int threshold =
1126 ((AUDIT_RATE_LIMIT_BURST_DURATION *
1127 (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) +
1128 1) /
1129 2;
1130 static const int rate = AUDIT_RATE_LIMIT_DEFAULT * 2;
1131 static const int duration = threshold / AUDIT_RATE_LIMIT_DEFAULT;
1132 EXPECT_GE(
1133 ((AUDIT_RATE_LIMIT_DEFAULT * duration) * 115) / 100, // +15% margin
1134 count_avc(sepolicy_rate(rate, rate * duration)));
1135 // give logd another 3 seconds to react to the burst before checking
1136 sepolicy_rate(rate, rate * 3);
1137 // maximum period at double the maximum burst rate (spam filter kicked in)
1138 EXPECT_GE(
1139 threshold * 2,
1140 count_avc(sepolicy_rate(rate, rate * AUDIT_RATE_LIMIT_BURST_DURATION)));
1141 // cool down, and check unspammy rate still works
1142 sleep(2);
1143 EXPECT_LE(AUDIT_RATE_LIMIT_BURST_DURATION - 1, // allow _one_ to be lost
1144 count_avc(sepolicy_rate(1, AUDIT_RATE_LIMIT_BURST_DURATION)));
1145 #else
1146 GTEST_LOG_(INFO) << "This test does nothing.\n";
1147 #endif
1148 }
1149