1 /*
2 * Copyright (C) 2014 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include <fcntl.h>
18 #include <poll.h>
19 #include <signal.h>
20 #include <stdio.h>
21 #include <string.h>
22
23 #include <gtest/gtest.h>
24
25 #include "cutils/sockets.h"
26 #include "log/log.h"
27 #include "log/logger.h"
28
29 #define __unused __attribute__((__unused__))
30
31 /*
32 * returns statistics
33 */
my_android_logger_get_statistics(char * buf,size_t len)34 static void my_android_logger_get_statistics(char *buf, size_t len)
35 {
36 snprintf(buf, len, "getStatistics 0 1 2 3 4");
37 int sock = socket_local_client("logd",
38 ANDROID_SOCKET_NAMESPACE_RESERVED,
39 SOCK_STREAM);
40 if (sock >= 0) {
41 if (write(sock, buf, strlen(buf) + 1) > 0) {
42 ssize_t ret;
43 while ((ret = read(sock, buf, len)) > 0) {
44 if ((size_t)ret == len) {
45 break;
46 }
47 len -= ret;
48 buf += ret;
49
50 struct pollfd p = {
51 .fd = sock,
52 .events = POLLIN,
53 .revents = 0
54 };
55
56 ret = poll(&p, 1, 20);
57 if ((ret <= 0) || !(p.revents & POLLIN)) {
58 break;
59 }
60 }
61 }
62 close(sock);
63 }
64 }
65
alloc_statistics(char ** buffer,size_t * length)66 static void alloc_statistics(char **buffer, size_t *length)
67 {
68 size_t len = 8192;
69 char *buf;
70
71 for(int retry = 32; (retry >= 0); delete [] buf, --retry) {
72 buf = new char [len];
73 my_android_logger_get_statistics(buf, len);
74
75 buf[len-1] = '\0';
76 size_t ret = atol(buf) + 1;
77 if (ret < 4) {
78 delete [] buf;
79 buf = NULL;
80 break;
81 }
82 bool check = ret <= len;
83 len = ret;
84 if (check) {
85 break;
86 }
87 len += len / 8; // allow for some slop
88 }
89 *buffer = buf;
90 *length = len;
91 }
92
find_benchmark_spam(char * cp)93 static char *find_benchmark_spam(char *cp)
94 {
95 // liblog_benchmarks has been run designed to SPAM. The signature of
96 // a noisiest UID statistics is one of the following:
97 //
98 // main: UID/PID Total size/num Now UID/PID[?] Total
99 // 0 7500306/304207 71608/3183 0/4225? 7454388/303656
100 // <wrap> 93432/1012
101 // -or-
102 // 0/gone 7454388/303656 93432/1012
103 //
104 // basically if we see a *large* number of 0/????? entries
105 unsigned long value;
106 do {
107 char *benchmark = strstr(cp, " 0/");
108 char *benchmark_newline = strstr(cp, "\n0/");
109 if (!benchmark) {
110 benchmark = benchmark_newline;
111 }
112 if (benchmark_newline && (benchmark > benchmark_newline)) {
113 benchmark = benchmark_newline;
114 }
115 cp = benchmark;
116 if (!cp) {
117 break;
118 }
119 cp += 3;
120 while (isdigit(*cp) || (*cp == 'g') || (*cp == 'o') || (*cp == 'n')) {
121 ++cp;
122 }
123 value = 0;
124 // ###? or gone
125 if ((*cp == '?') || (*cp == 'e')) {
126 while (*++cp == ' ');
127 while (isdigit(*cp)) {
128 value = value * 10ULL + *cp - '0';
129 ++cp;
130 }
131 if (*cp != '/') {
132 value = 0;
133 continue;
134 }
135 while (isdigit(*++cp));
136 while (*cp == ' ') ++cp;
137 if (!isdigit(*cp)) {
138 value = 0;
139 }
140 }
141 } while ((value < 900000ULL) && *cp);
142 return cp;
143 }
144
TEST(logd,statistics)145 TEST(logd, statistics) {
146 size_t len;
147 char *buf;
148
149 alloc_statistics(&buf, &len);
150
151 #ifdef TARGET_USES_LOGD
152 ASSERT_TRUE(NULL != buf);
153 #else
154 if (!buf) {
155 return;
156 }
157 #endif
158
159 // remove trailing FF
160 char *cp = buf + len - 1;
161 *cp = '\0';
162 bool truncated = *--cp != '\f';
163 if (!truncated) {
164 *cp = '\0';
165 }
166
167 // squash out the byte count
168 cp = buf;
169 if (!truncated) {
170 while (isdigit(*cp) || (*cp == '\n')) {
171 ++cp;
172 }
173 }
174
175 fprintf(stderr, "%s", cp);
176
177 EXPECT_LT((size_t)64, strlen(cp));
178
179 EXPECT_EQ(0, truncated);
180
181 #ifdef TARGET_USES_LOGD
182 char *main_logs = strstr(cp, "\nmain:");
183 EXPECT_TRUE(NULL != main_logs);
184
185 char *radio_logs = strstr(cp, "\nradio:");
186 EXPECT_TRUE(NULL != radio_logs);
187
188 char *system_logs = strstr(cp, "\nsystem:");
189 EXPECT_TRUE(NULL != system_logs);
190
191 char *events_logs = strstr(cp, "\nevents:");
192 EXPECT_TRUE(NULL != events_logs);
193 #endif
194
195 // Parse timing stats
196
197 cp = strstr(cp, "Minimum time between log events per dgram_qlen:");
198
199 if (cp) {
200 while (*cp && (*cp != '\n')) {
201 ++cp;
202 }
203 if (*cp == '\n') {
204 ++cp;
205 }
206
207 char *list_of_spans = cp;
208 EXPECT_NE('\0', *list_of_spans);
209
210 unsigned short number_of_buckets = 0;
211 unsigned short *dgram_qlen = NULL;
212 unsigned short bucket = 0;
213 while (*cp && (*cp != '\n')) {
214 bucket = 0;
215 while (isdigit(*cp)) {
216 bucket = bucket * 10 + *cp - '0';
217 ++cp;
218 }
219 while (*cp == ' ') {
220 ++cp;
221 }
222 if (!bucket) {
223 break;
224 }
225 unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1];
226 EXPECT_TRUE(new_dgram_qlen != NULL);
227 if (dgram_qlen) {
228 memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets);
229 delete [] dgram_qlen;
230 }
231
232 dgram_qlen = new_dgram_qlen;
233 dgram_qlen[number_of_buckets++] = bucket;
234 }
235
236 char *end_of_spans = cp;
237 EXPECT_NE('\0', *end_of_spans);
238
239 EXPECT_LT(5, number_of_buckets);
240
241 unsigned long long *times = new unsigned long long [number_of_buckets];
242 ASSERT_TRUE(times != NULL);
243
244 memset(times, 0, sizeof(*times) * number_of_buckets);
245
246 while (*cp == '\n') {
247 ++cp;
248 }
249
250 unsigned short number_of_values = 0;
251 unsigned long long value;
252 while (*cp && (*cp != '\n')) {
253 EXPECT_GE(number_of_buckets, number_of_values);
254
255 value = 0;
256 while (isdigit(*cp)) {
257 value = value * 10ULL + *cp - '0';
258 ++cp;
259 }
260
261 switch(*cp) {
262 case ' ':
263 case '\n':
264 value *= 1000ULL;
265 /* FALLTHRU */
266 case 'm':
267 value *= 1000ULL;
268 /* FALLTHRU */
269 case 'u':
270 value *= 1000ULL;
271 /* FALLTHRU */
272 case 'n':
273 default:
274 break;
275 }
276 while (*++cp == ' ');
277
278 if (!value) {
279 break;
280 }
281
282 times[number_of_values] = value;
283 ++number_of_values;
284 }
285
286 #ifdef TARGET_USES_LOGD
287 EXPECT_EQ(number_of_values, number_of_buckets);
288 #endif
289
290 FILE *fp;
291 ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r")));
292
293 unsigned max_dgram_qlen = 0;
294 fscanf(fp, "%u", &max_dgram_qlen);
295
296 fclose(fp);
297
298 // Find launch point
299 unsigned short launch = 0;
300 unsigned long long total = 0;
301 do {
302 total += times[launch];
303 } while (((++launch < number_of_buckets)
304 && ((total / launch) >= (times[launch] / 8ULL)))
305 || (launch == 1)); // too soon
306
307 bool failure = number_of_buckets <= launch;
308 if (!failure) {
309 unsigned short l = launch;
310 if (l >= number_of_buckets) {
311 l = number_of_buckets - 1;
312 }
313 failure = max_dgram_qlen < dgram_qlen[l];
314 }
315
316 // We can get failure if at any time liblog_benchmarks has been run
317 // because designed to overload /proc/sys/net/unix/max_dgram_qlen even
318 // at excessive values like 20000. It does so to measure the raw processing
319 // performance of logd.
320 if (failure) {
321 cp = find_benchmark_spam(cp);
322 }
323
324 if (cp) {
325 // Fake a failure, but without the failure code
326 if (number_of_buckets <= launch) {
327 printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n",
328 number_of_buckets, launch);
329 }
330 if (launch >= number_of_buckets) {
331 launch = number_of_buckets - 1;
332 }
333 if (max_dgram_qlen < dgram_qlen[launch]) {
334 printf ("Expected: max_dgram_qlen >= dgram_qlen[%d],"
335 " actual: %u vs %u\n",
336 launch, max_dgram_qlen, dgram_qlen[launch]);
337 }
338 } else
339 #ifndef TARGET_USES_LOGD
340 if (total)
341 #endif
342 {
343 EXPECT_GT(number_of_buckets, launch);
344 if (launch >= number_of_buckets) {
345 launch = number_of_buckets - 1;
346 }
347 EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]);
348 }
349
350 delete [] dgram_qlen;
351 delete [] times;
352 }
353 delete [] buf;
354 }
355
caught_signal(int signum __unused)356 static void caught_signal(int signum __unused) { }
357
dump_log_msg(const char * prefix,log_msg * msg,unsigned int version,int lid)358 static void dump_log_msg(const char *prefix,
359 log_msg *msg, unsigned int version, int lid) {
360 switch(msg->entry.hdr_size) {
361 case 0:
362 version = 1;
363 break;
364
365 case sizeof(msg->entry_v2):
366 if (version == 0) {
367 version = 2;
368 }
369 break;
370 }
371
372 fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
373 if (version != 1) {
374 fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
375 }
376 fprintf(stderr, "pid=%u tid=%u %u.%09u ",
377 msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec);
378 switch(version) {
379 case 1:
380 break;
381 case 2:
382 fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
383 break;
384 case 3:
385 default:
386 lid = msg->entry.lid;
387 break;
388 }
389
390 switch(lid) {
391 case 0:
392 fprintf(stderr, "lid=main ");
393 break;
394 case 1:
395 fprintf(stderr, "lid=radio ");
396 break;
397 case 2:
398 fprintf(stderr, "lid=events ");
399 break;
400 case 3:
401 fprintf(stderr, "lid=system ");
402 break;
403 default:
404 if (lid >= 0) {
405 fprintf(stderr, "lid=%d ", lid);
406 }
407 }
408
409 unsigned int len = msg->entry.len;
410 fprintf(stderr, "msg[%u]={", len);
411 unsigned char *cp = reinterpret_cast<unsigned char *>(msg->msg());
412 while(len) {
413 unsigned char *p = cp;
414 while (*p && (((' ' <= *p) && (*p < 0x7F)) || (*p == '\n'))) {
415 ++p;
416 }
417 if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
418 fprintf(stderr, "\"");
419 while (*cp) {
420 fprintf(stderr, (*cp != '\n') ? "%c" : "\\n", *cp);
421 ++cp;
422 --len;
423 }
424 fprintf(stderr, "\"");
425 } else {
426 fprintf(stderr, "%02x", *cp);
427 }
428 ++cp;
429 if (--len) {
430 fprintf(stderr, ", ");
431 }
432 }
433 fprintf(stderr, "}\n");
434 }
435
TEST(logd,both)436 TEST(logd, both) {
437 log_msg msg;
438
439 // check if we can read any logs from logd
440 bool user_logger_available = false;
441 bool user_logger_content = false;
442
443 int fd = socket_local_client("logdr",
444 ANDROID_SOCKET_NAMESPACE_RESERVED,
445 SOCK_SEQPACKET);
446 if (fd >= 0) {
447 struct sigaction ignore, old_sigaction;
448 memset(&ignore, 0, sizeof(ignore));
449 ignore.sa_handler = caught_signal;
450 sigemptyset(&ignore.sa_mask);
451 sigaction(SIGALRM, &ignore, &old_sigaction);
452 unsigned int old_alarm = alarm(10);
453
454 static const char ask[] = "dumpAndClose lids=0,1,2,3";
455 user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);
456
457 user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;
458
459 if (user_logger_content) {
460 dump_log_msg("user", &msg, 3, -1);
461 }
462
463 alarm(old_alarm);
464 sigaction(SIGALRM, &old_sigaction, NULL);
465
466 close(fd);
467 }
468
469 // check if we can read any logs from kernel logger
470 bool kernel_logger_available = false;
471 bool kernel_logger_content = false;
472
473 static const char *loggers[] = {
474 "/dev/log/main", "/dev/log_main",
475 "/dev/log/radio", "/dev/log_radio",
476 "/dev/log/events", "/dev/log_events",
477 "/dev/log/system", "/dev/log_system",
478 };
479
480 for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) {
481 fd = open(loggers[i], O_RDONLY);
482 if (fd < 0) {
483 continue;
484 }
485 kernel_logger_available = true;
486 fcntl(fd, F_SETFL, O_RDONLY | O_NONBLOCK);
487 int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
488 if (result > 0) {
489 kernel_logger_content = true;
490 dump_log_msg("kernel", &msg, 0, i / 2);
491 }
492 close(fd);
493 }
494
495 static const char yes[] = "\xE2\x9C\x93";
496 static const char no[] = "\xE2\x9c\x98";
497 fprintf(stderr,
498 "LOGGER Available Content\n"
499 "user %-13s%s\n"
500 "kernel %-13s%s\n"
501 " status %-11s%s\n",
502 (user_logger_available) ? yes : no,
503 (user_logger_content) ? yes : no,
504 (kernel_logger_available) ? yes : no,
505 (kernel_logger_content) ? yes : no,
506 (user_logger_available && kernel_logger_available) ? "ERROR" : "ok",
507 (user_logger_content && kernel_logger_content) ? "ERROR" : "ok");
508
509 EXPECT_EQ(0, user_logger_available && kernel_logger_available);
510 EXPECT_EQ(0, !user_logger_available && !kernel_logger_available);
511 EXPECT_EQ(0, user_logger_content && kernel_logger_content);
512 EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
513 }
514
515 // BAD ROBOT
516 // Benchmark threshold are generally considered bad form unless there is
517 // is some human love applied to the continued maintenance and whether the
518 // thresholds are tuned on a per-target basis. Here we check if the values
519 // are more than double what is expected. Doubling will not prevent failure
520 // on busy or low-end systems that could have a tendency to stretch values.
521 //
522 // The primary goal of this test is to simulate a spammy app (benchmark
523 // being the worst) and check to make sure the logger can deal with it
524 // appropriately by checking all the statistics are in an expected range.
525 //
TEST(logd,benchmark)526 TEST(logd, benchmark) {
527 size_t len;
528 char *buf;
529
530 alloc_statistics(&buf, &len);
531 bool benchmark_already_run = buf && find_benchmark_spam(buf);
532 delete [] buf;
533
534 if (benchmark_already_run) {
535 fprintf(stderr, "WARNING: spam already present and too much history\n"
536 " false OK for prune by worst UID check\n");
537 }
538
539 FILE *fp;
540
541 // Introduce some extreme spam for the worst UID filter
542 ASSERT_TRUE(NULL != (fp = popen(
543 "/data/nativetest/liblog-benchmarks/liblog-benchmarks",
544 "r")));
545
546 char buffer[5120];
547
548 static const char *benchmarks[] = {
549 "BM_log_maximum_retry ",
550 "BM_log_maximum ",
551 "BM_clock_overhead ",
552 "BM_log_overhead ",
553 "BM_log_latency ",
554 "BM_log_delay "
555 };
556 static const unsigned int log_maximum_retry = 0;
557 static const unsigned int log_maximum = 1;
558 static const unsigned int clock_overhead = 2;
559 static const unsigned int log_overhead = 3;
560 static const unsigned int log_latency = 4;
561 static const unsigned int log_delay = 5;
562
563 unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];
564
565 memset(ns, 0, sizeof(ns));
566
567 while (fgets(buffer, sizeof(buffer), fp)) {
568 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
569 char *cp = strstr(buffer, benchmarks[i]);
570 if (!cp) {
571 continue;
572 }
573 sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]);
574 fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
575 }
576 }
577 int ret = pclose(fp);
578
579 if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
580 fprintf(stderr,
581 "WARNING: "
582 "/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
583 " can not perform test\n");
584 return;
585 }
586
587 #ifdef TARGET_USES_LOGD
588 EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user
589 #else
590 EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel
591 #endif
592
593 #ifdef TARGET_USES_LOGD
594 EXPECT_GE(30000UL, ns[log_maximum]); // 27305 user
595 #else
596 EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel
597 #endif
598
599 EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
600
601 #ifdef TARGET_USES_LOGD
602 EXPECT_GE(250000UL, ns[log_overhead]); // 121876 user
603 #else
604 EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel
605 #endif
606
607 #ifdef TARGET_USES_LOGD
608 EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space
609 #else
610 EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel
611 #endif
612
613 #ifdef TARGET_USES_LOGD
614 EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
615 #else
616 EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel
617 #endif
618
619 for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
620 EXPECT_NE(0UL, ns[i]);
621 }
622
623 alloc_statistics(&buf, &len);
624
625 #ifdef TARGET_USES_LOGD
626 bool collected_statistics = !!buf;
627 EXPECT_EQ(true, collected_statistics);
628 #else
629 if (!buf) {
630 return;
631 }
632 #endif
633
634 ASSERT_TRUE(NULL != buf);
635
636 char *benchmark_statistics_found = find_benchmark_spam(buf);
637 ASSERT_TRUE(benchmark_statistics_found != NULL);
638
639 // Check how effective the SPAM filter is, parse out Now size.
640 // Total Now
641 // 0/4225? 7454388/303656 31488/755
642 // ^-- benchmark_statistics_found
643
644 unsigned long nowSpamSize = atol(benchmark_statistics_found);
645
646 delete [] buf;
647
648 ASSERT_NE(0UL, nowSpamSize);
649
650 // Determine if we have the spam filter enabled
651 int sock = socket_local_client("logd",
652 ANDROID_SOCKET_NAMESPACE_RESERVED,
653 SOCK_STREAM);
654
655 ASSERT_TRUE(sock >= 0);
656
657 static const char getPruneList[] = "getPruneList";
658 if (write(sock, getPruneList, sizeof(getPruneList)) > 0) {
659 char buffer[80];
660 memset(buffer, 0, sizeof(buffer));
661 read(sock, buffer, sizeof(buffer));
662 char *cp = strchr(buffer, '\n');
663 if (!cp || (cp[1] != '~') || (cp[2] != '!')) {
664 close(sock);
665 fprintf(stderr,
666 "WARNING: "
667 "Logger has SPAM filtration turned off \"%s\"\n", buffer);
668 return;
669 }
670 } else {
671 int save_errno = errno;
672 close(sock);
673 FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno);
674 }
675
676 static const unsigned long expected_absolute_minimum_log_size = 65536UL;
677 unsigned long totalSize = expected_absolute_minimum_log_size;
678 static const char getSize[] = {
679 'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ',
680 LOG_ID_MAIN + '0', '\0'
681 };
682 if (write(sock, getSize, sizeof(getSize)) > 0) {
683 char buffer[80];
684 memset(buffer, 0, sizeof(buffer));
685 read(sock, buffer, sizeof(buffer));
686 totalSize = atol(buffer);
687 if (totalSize < expected_absolute_minimum_log_size) {
688 fprintf(stderr,
689 "WARNING: "
690 "Logger had unexpected referenced size \"%s\"\n", buffer);
691 totalSize = expected_absolute_minimum_log_size;
692 }
693 }
694 close(sock);
695
696 // logd allows excursions to 110% of total size
697 totalSize = (totalSize * 11 ) / 10;
698
699 // 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
700 ASSERT_GT(totalSize, nowSpamSize * 2);
701 }
702