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