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