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